Problem with patch "make nlmsg_end() and genlmsg_end() void"

Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Marcel Holtmann]

Hi Johannes,

your commit 053c095a82cf773075e83d7233b5cc19a1f73ece is causing problems with systemd-networkd.

I have an up-to-date Arch Linux installation in a KVM and your change causes massive problems. It makes systemd-networkd to run out of memory.

systemd-fsck[84]: /dev/vda1: clean, 53283/131072 files, 409813/524032 blocks
Out of memory: Kill process 142 (systemd-network) score 923 or sacrifice child
Killed process 142 (systemd-network) total-vm:478416kB, anon-rss:463472kB, file-rss:460kB
[FAILED] Failed to start Network Service.
See "systemctl status systemd-networkd.service" for details.
         Stopping Network Service...
[  OK  ] Stopped Network Service.
         Starting Network Service...

Arch Linux 3.19.0-rc4-devel+ (ttyS0)

marcel login: Out of memory: Kill process 154 (systemd-network) score 932 or sacrifice child
Killed process 154 (systemd-network) total-vm:540784kB, anon-rss:468380kB, file-rss:132kB
Out of memory: Kill process 158 (systemd-network) score 932 or sacrifice child
Killed process 158 (systemd-network) total-vm:540388kB, anon-rss:468528kB, file-rss:48kB
Out of memory: Kill process 160 (systemd-network) score 932 or sacrifice child
Killed process 160 (systemd-network) total-vm:540916kB, anon-rss:468528kB, file-rss:4kB
Out of memory: Kill process 162 (systemd-network) score 931 or sacrifice child
Killed process 162 (systemd-network) total-vm:540916kB, anon-rss:468104kB, file-rss:76kB

Regards

Marcel

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Marcel Holtmann]

Hi Johannes,

> your commit 053c095a82cf773075e83d7233b5cc19a1f73ece is causing problems with systemd-networkd.
> 
> I have an up-to-date Arch Linux installation in a KVM and your change causes massive problems. It makes systemd-networkd to run out of memory.
> 
> systemd-fsck[84]: /dev/vda1: clean, 53283/131072 files, 409813/524032 blocks
> Out of memory: Kill process 142 (systemd-network) score 923 or sacrifice child
> Killed process 142 (systemd-network) total-vm:478416kB, anon-rss:463472kB, file-rss:460kB
> [FAILED] Failed to start Network Service.
> See "systemctl status systemd-networkd.service" for details.
>         Stopping Network Service...
> [  OK  ] Stopped Network Service.
>         Starting Network Service...
> 
> Arch Linux 3.19.0-rc4-devel+ (ttyS0)
> 
> marcel login: Out of memory: Kill process 154 (systemd-network) score 932 or sacrifice child
> Killed process 154 (systemd-network) total-vm:540784kB, anon-rss:468380kB, file-rss:132kB
> Out of memory: Kill process 158 (systemd-network) score 932 or sacrifice child
> Killed process 158 (systemd-network) total-vm:540388kB, anon-rss:468528kB, file-rss:48kB
> Out of memory: Kill process 160 (systemd-network) score 932 or sacrifice child
> Killed process 160 (systemd-network) total-vm:540916kB, anon-rss:468528kB, file-rss:4kB
> Out of memory: Kill process 162 (systemd-network) score 931 or sacrifice child
> Killed process 162 (systemd-network) total-vm:540916kB, anon-rss:468104kB, file-rss:76kB

so this was freaking nasty to find since I had to dig into every single RTNL location that might have an affect on this. I think that I tracked this down to these two locations:

diff --git a/net/core/rtnetlink.c b/net/core/rtnetlink.c
index e13b9dbdf154..0e26b9f66cad 100644
--- a/net/core/rtnetlink.c
+++ b/net/core/rtnetlink.c
@@ -1327,7 +1327,7 @@ static int rtnl_dump_ifinfo(struct sk_buff *skb, struct netlink_callback *cb)
                         */
                        WARN_ON((err == -EMSGSIZE) && (skb->len == 0));
 
-                       if (err <= 0)
+                       if (err < 0)
                                goto out;
 
                        nl_dump_check_consistent(cb, nlmsg_hdr(skb));
diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
index 8975d9501d50..d6b4f5d08014 100644
--- a/net/ipv6/addrconf.c
+++ b/net/ipv6/addrconf.c
@@ -4213,7 +4213,7 @@ static int inet6_dump_addr(struct sk_buff *skb, struct netlink_callback *cb,
                                goto cont;
 
                        if (in6_dump_addrs(idev, skb, cb, type,
-                                          s_ip_idx, &ip_idx) <= 0)
+                                          s_ip_idx, &ip_idx) < 0)
                                goto done;
 cont:
                        idx++;

However I am not sure that these are the only ones. We might have additional issues in functionality that systemd-networkd actually does not use at the moment. These two changes make my KVM image boot properly again.

And actually I am not even sure that these two changes are correct. My KVM image is a dead simple image with no IPv6 support. This change might actually just broke IPv6 and I would not notice.

Tom, do you know if we can do anything in systemd-networkd in regards to RTNL and netlink handling to throw a big warning when something comes back from the kernel that would cause massive memory allocation.

Regards

Marcel

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Scott Feldman]

This patch needs to be reverted ASAP.  git bisect landed me here also;
my processes are getting the OOM msgs.  What testing was done?

Seems someone does care that nlmsg_end() returns skb->len.

-scott

On Sun, Jan 18, 2015 at 3:44 PM, Marcel Holtmann <marcel@holtmann.org> wrote:
> Hi Johannes,
>
>> your commit 053c095a82cf773075e83d7233b5cc19a1f73ece is causing problems with systemd-networkd.
>>
>> I have an up-to-date Arch Linux installation in a KVM and your change causes massive problems. It makes systemd-networkd to run out of memory.
>>
>> systemd-fsck[84]: /dev/vda1: clean, 53283/131072 files, 409813/524032 blocks
>> Out of memory: Kill process 142 (systemd-network) score 923 or sacrifice child
>> Killed process 142 (systemd-network) total-vm:478416kB, anon-rss:463472kB, file-rss:460kB
>> [FAILED] Failed to start Network Service.
>> See "systemctl status systemd-networkd.service" for details.
>>         Stopping Network Service...
>> [  OK  ] Stopped Network Service.
>>         Starting Network Service...
>>
>> Arch Linux 3.19.0-rc4-devel+ (ttyS0)
>>
>> marcel login: Out of memory: Kill process 154 (systemd-network) score 932 or sacrifice child
>> Killed process 154 (systemd-network) total-vm:540784kB, anon-rss:468380kB, file-rss:132kB
>> Out of memory: Kill process 158 (systemd-network) score 932 or sacrifice child
>> Killed process 158 (systemd-network) total-vm:540388kB, anon-rss:468528kB, file-rss:48kB
>> Out of memory: Kill process 160 (systemd-network) score 932 or sacrifice child
>> Killed process 160 (systemd-network) total-vm:540916kB, anon-rss:468528kB, file-rss:4kB
>> Out of memory: Kill process 162 (systemd-network) score 931 or sacrifice child
>> Killed process 162 (systemd-network) total-vm:540916kB, anon-rss:468104kB, file-rss:76kB
>
> so this was freaking nasty to find since I had to dig into every single RTNL location that might have an affect on this. I think that I tracked this down to these two locations:
>
> diff --git a/net/core/rtnetlink.c b/net/core/rtnetlink.c
> index e13b9dbdf154..0e26b9f66cad 100644
> --- a/net/core/rtnetlink.c
> +++ b/net/core/rtnetlink.c
> @@ -1327,7 +1327,7 @@ static int rtnl_dump_ifinfo(struct sk_buff *skb, struct netlink_callback *cb)
>                          */
>                         WARN_ON((err == -EMSGSIZE) && (skb->len == 0));
>
> -                       if (err <= 0)
> +                       if (err < 0)
>                                 goto out;
>
>                         nl_dump_check_consistent(cb, nlmsg_hdr(skb));
> diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
> index 8975d9501d50..d6b4f5d08014 100644
> --- a/net/ipv6/addrconf.c
> +++ b/net/ipv6/addrconf.c
> @@ -4213,7 +4213,7 @@ static int inet6_dump_addr(struct sk_buff *skb, struct netlink_callback *cb,
>                                 goto cont;
>
>                         if (in6_dump_addrs(idev, skb, cb, type,
> -                                          s_ip_idx, &ip_idx) <= 0)
> +                                          s_ip_idx, &ip_idx) < 0)
>                                 goto done;
>  cont:
>                         idx++;
>
> However I am not sure that these are the only ones. We might have additional issues in functionality that systemd-networkd actually does not use at the moment. These two changes make my KVM image boot properly again.
>
> And actually I am not even sure that these two changes are correct. My KVM image is a dead simple image with no IPv6 support. This change might actually just broke IPv6 and I would not notice.
>
> Tom, do you know if we can do anything in systemd-networkd in regards to RTNL and netlink handling to throw a big warning when something comes back from the kernel that would cause massive memory allocation.
>
> Regards
>
> Marcel
>
> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Marcel Holtmann]

Hi Scott,

> This patch needs to be reverted ASAP.  git bisect landed me here also;
> my processes are getting the OOM msgs.  What testing was done?
> 
> Seems someone does care that nlmsg_end() returns skb->len.

I still wonder how this affects userspace. I have not figured that out. Something goes wrong pretty badly somewhere.

Have you tried the small diff with the two locations that were problematic for me?

Regards

Marcel

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Miller]

From: Marcel Holtmann <marcel@holtmann.org>
Date: Sun, 18 Jan 2015 18:10:46 -0800

> Hi Scott,
> 
>> This patch needs to be reverted ASAP.  git bisect landed me here also;
>> my processes are getting the OOM msgs.  What testing was done?
>> 
>> Seems someone does care that nlmsg_end() returns skb->len.
> 
> I still wonder how this affects userspace. I have not figured that
> out. Something goes wrong pretty badly somewhere.
> 
> Have you tried the small diff with the two locations that were
> problematic for me?

There were a lot more cases not converted properly, I hope the
patch below gets them all.

Johannes, this was either not tested or tested very poorly, please
don't submit changes like this.  Even neighbour entry and route
dumping were hosed.

====================
[PATCH] netlink: Fix bugs in nlmsg_end() conversions.

Commit 053c095a82cf ("netlink: make nlmsg_end() and genlmsg_end()
void") didn't catch all of the cases where callers were breaking out
on the return value being equal to zero, which they no longer should
when zero means success.

Fix all such cases.

Reported-by: Marcel Holtmann <marcel@holtmann.org>
Reported-by: Scott Feldman <sfeldma@gmail.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
---
 net/core/neighbour.c  | 8 ++++----
 net/core/rtnetlink.c  | 2 +-
 net/decnet/dn_route.c | 5 +----
 net/ipv4/devinet.c    | 6 +++---
 net/ipv4/route.c      | 2 +-
 net/ipv6/addrconf.c   | 2 +-
 6 files changed, 11 insertions(+), 14 deletions(-)

diff --git a/net/core/neighbour.c b/net/core/neighbour.c
index d36d564..70fe9e1 100644
--- a/net/core/neighbour.c
+++ b/net/core/neighbour.c
@@ -2128,7 +2128,7 @@ static int neightbl_dump_info(struct sk_buff *skb, struct netlink_callback *cb)
 
 		if (neightbl_fill_info(skb, tbl, NETLINK_CB(cb->skb).portid,
 				       cb->nlh->nlmsg_seq, RTM_NEWNEIGHTBL,
-				       NLM_F_MULTI) <= 0)
+				       NLM_F_MULTI) < 0)
 			break;
 
 		nidx = 0;
@@ -2144,7 +2144,7 @@ static int neightbl_dump_info(struct sk_buff *skb, struct netlink_callback *cb)
 						     NETLINK_CB(cb->skb).portid,
 						     cb->nlh->nlmsg_seq,
 						     RTM_NEWNEIGHTBL,
-						     NLM_F_MULTI) <= 0)
+						     NLM_F_MULTI) < 0)
 				goto out;
 		next:
 			nidx++;
@@ -2274,7 +2274,7 @@ static int neigh_dump_table(struct neigh_table *tbl, struct sk_buff *skb,
 			if (neigh_fill_info(skb, n, NETLINK_CB(cb->skb).portid,
 					    cb->nlh->nlmsg_seq,
 					    RTM_NEWNEIGH,
-					    NLM_F_MULTI) <= 0) {
+					    NLM_F_MULTI) < 0) {
 				rc = -1;
 				goto out;
 			}
@@ -2311,7 +2311,7 @@ static int pneigh_dump_table(struct neigh_table *tbl, struct sk_buff *skb,
 			if (pneigh_fill_info(skb, n, NETLINK_CB(cb->skb).portid,
 					    cb->nlh->nlmsg_seq,
 					    RTM_NEWNEIGH,
-					    NLM_F_MULTI, tbl) <= 0) {
+					    NLM_F_MULTI, tbl) < 0) {
 				read_unlock_bh(&tbl->lock);
 				rc = -1;
 				goto out;
diff --git a/net/core/rtnetlink.c b/net/core/rtnetlink.c
index e13b9db..0e26b9f 100644
--- a/net/core/rtnetlink.c
+++ b/net/core/rtnetlink.c
@@ -1327,7 +1327,7 @@ static int rtnl_dump_ifinfo(struct sk_buff *skb, struct netlink_callback *cb)
 			 */
 			WARN_ON((err == -EMSGSIZE) && (skb->len == 0));
 
-			if (err <= 0)
+			if (err < 0)
 				goto out;
 
 			nl_dump_check_consistent(cb, nlmsg_hdr(skb));
diff --git a/net/decnet/dn_route.c b/net/decnet/dn_route.c
index 812e5e6..1d7c125 100644
--- a/net/decnet/dn_route.c
+++ b/net/decnet/dn_route.c
@@ -1710,9 +1710,6 @@ static int dn_cache_getroute(struct sk_buff *in_skb, struct nlmsghdr *nlh)
 		rt->rt_flags |= RTCF_NOTIFY;
 
 	err = dn_rt_fill_info(skb, NETLINK_CB(in_skb).portid, nlh->nlmsg_seq, RTM_NEWROUTE, 0, 0);
-
-	if (err == 0)
-		goto out_free;
 	if (err < 0) {
 		err = -EMSGSIZE;
 		goto out_free;
@@ -1763,7 +1760,7 @@ int dn_cache_dump(struct sk_buff *skb, struct netlink_callback *cb)
 			skb_dst_set(skb, dst_clone(&rt->dst));
 			if (dn_rt_fill_info(skb, NETLINK_CB(cb->skb).portid,
 					cb->nlh->nlmsg_seq, RTM_NEWROUTE,
-					1, NLM_F_MULTI) <= 0) {
+					1, NLM_F_MULTI) < 0) {
 				skb_dst_drop(skb);
 				rcu_read_unlock_bh();
 				goto done;
diff --git a/net/ipv4/devinet.c b/net/ipv4/devinet.c
index 5f344eb..59ebe16 100644
--- a/net/ipv4/devinet.c
+++ b/net/ipv4/devinet.c
@@ -1883,7 +1883,7 @@ static int inet_netconf_dump_devconf(struct sk_buff *skb,
 						      cb->nlh->nlmsg_seq,
 						      RTM_NEWNETCONF,
 						      NLM_F_MULTI,
-						      -1) <= 0) {
+						      -1) < 0) {
 				rcu_read_unlock();
 				goto done;
 			}
@@ -1899,7 +1899,7 @@ cont:
 					      NETLINK_CB(cb->skb).portid,
 					      cb->nlh->nlmsg_seq,
 					      RTM_NEWNETCONF, NLM_F_MULTI,
-					      -1) <= 0)
+					      -1) < 0)
 			goto done;
 		else
 			h++;
@@ -1910,7 +1910,7 @@ cont:
 					      NETLINK_CB(cb->skb).portid,
 					      cb->nlh->nlmsg_seq,
 					      RTM_NEWNETCONF, NLM_F_MULTI,
-					      -1) <= 0)
+					      -1) < 0)
 			goto done;
 		else
 			h++;
diff --git a/net/ipv4/route.c b/net/ipv4/route.c
index f6e43ca..2000110 100644
--- a/net/ipv4/route.c
+++ b/net/ipv4/route.c
@@ -2483,7 +2483,7 @@ static int inet_rtm_getroute(struct sk_buff *in_skb, struct nlmsghdr *nlh)
 	err = rt_fill_info(net, dst, src, &fl4, skb,
 			   NETLINK_CB(in_skb).portid, nlh->nlmsg_seq,
 			   RTM_NEWROUTE, 0, 0);
-	if (err <= 0)
+	if (err < 0)
 		goto errout_free;
 
 	err = rtnl_unicast(skb, net, NETLINK_CB(in_skb).portid);
diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
index 8975d95..d6b4f5d 100644
--- a/net/ipv6/addrconf.c
+++ b/net/ipv6/addrconf.c
@@ -4213,7 +4213,7 @@ static int inet6_dump_addr(struct sk_buff *skb, struct netlink_callback *cb,
 				goto cont;
 
 			if (in6_dump_addrs(idev, skb, cb, type,
-					   s_ip_idx, &ip_idx) <= 0)
+					   s_ip_idx, &ip_idx) < 0)
 				goto done;
 cont:
 			idx++;
-- 
2.1.0

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Scott Feldman]

On Sun, Jan 18, 2015 at 8:37 PM, David Miller <davem@davemloft.net> wrote:
>
> ====================
> [PATCH] netlink: Fix bugs in nlmsg_end() conversions.
>
> Commit 053c095a82cf ("netlink: make nlmsg_end() and genlmsg_end()
> void") didn't catch all of the cases where callers were breaking out
> on the return value being equal to zero, which they no longer should
> when zero means success.
>
> Fix all such cases.
>
> Reported-by: Marcel Holtmann <marcel@holtmann.org>
> Reported-by: Scott Feldman <sfeldma@gmail.com>
> Signed-off-by: David S. Miller <davem@davemloft.net>

Fixes my tests, so I'm happy.  Thank you.

Acked-by: Scott Feldman <sfeldma@gmail.com>

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 2114 bytes --]

On Sun, 2015-01-18 at 23:37 -0500, David Miller wrote:
> From: Marcel Holtmann <marcel@holtmann.org>
> Date: Sun, 18 Jan 2015 18:10:46 -0800
> 
> > Hi Scott,
> > 
> >> This patch needs to be reverted ASAP.  git bisect landed me here also;
> >> my processes are getting the OOM msgs.  What testing was done?
> >> 
> >> Seems someone does care that nlmsg_end() returns skb->len.
> > 
> > I still wonder how this affects userspace. I have not figured that
> > out. Something goes wrong pretty badly somewhere.
> > 
> > Have you tried the small diff with the two locations that were
> > problematic for me?
> 
> There were a lot more cases not converted properly, I hope the
> patch below gets them all.
> 
> Johannes, this was either not tested or tested very poorly, please
> don't submit changes like this.  Even neighbour entry and route
> dumping were hosed.
> 
> ====================
> [PATCH] netlink: Fix bugs in nlmsg_end() conversions.
> 
> Commit 053c095a82cf ("netlink: make nlmsg_end() and genlmsg_end()
> void") didn't catch all of the cases where callers were breaking out
> on the return value being equal to zero, which they no longer should
> when zero means success.
> 
> Fix all such cases.

I'm not sure if this is entirely fixed. In Fedora 22 (4.0.0-rc5-git4)
I'm occasionally seeing glibc deadlock in __check_pf() on a netlink
recvmsg(), here:
https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/unix/sysv/linux/check_pf.c;h=162606d7;hb=glibc-2.21#l166

As I understand it, this shouldn't happen. Even if messages are
dropped (which surely shouldn't happen as often as I'm seeing this),
glibc should get ENOBUFS from the recvmsg() call.

https://bugzilla.redhat.com/show_bug.cgi?id=1209433

I haven't bisected and proved that it *was* this commit which
introduced the problem, as it only happens after a day or two of
running Evolution and I haven't managed to trigger it more reliably.

-- 
David Woodhouse                            Open Source Technology Centre
David.Woodhouse@intel.com                              Intel Corporation

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5745 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Johannes Berg]

On Wed, 2015-04-08 at 13:03 +0100, David Woodhouse wrote:

> I'm not sure if this is entirely fixed. In Fedora 22 (4.0.0-rc5-git4)
> I'm occasionally seeing glibc deadlock in __check_pf() on a netlink
> recvmsg(), here:
> https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/unix/sysv/linux/check_pf.c;h=162606d7;hb=glibc-2.21#l166
> 
> As I understand it, this shouldn't happen. Even if messages are
> dropped (which surely shouldn't happen as often as I'm seeing this),
> glibc should get ENOBUFS from the recvmsg() call.
> 
> https://bugzilla.redhat.com/show_bug.cgi?id=1209433
> 
> I haven't bisected and proved that it *was* this commit which
> introduced the problem, as it only happens after a day or two of
> running Evolution and I haven't managed to trigger it more reliably.

I don't see the connection to this change.

The issue with my patch was that some code for NLM_F_DUMP would have
this pattern:

 int fill_function(...)
 {
    ...
    return nlmsg_end(...);
 }

 loop (...) {
   if (fill_function() <= 0)
     break; /* continue in next dump */
 }

and that all had to be converted to be just "< 0" now.

Additionally, the failure mode of this was the process running out of
memory due to receiving the same results over and over again - does that
happen for you? It seems it was stuck in recvmsg(), but that may just be
a side effect of happening to interrupt at that point?

johannes

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 528 bytes --]

On Wed, 2015-04-08 at 15:08 +0200, Johannes Berg wrote:
> Additionally, the failure mode of this was the process running out of
> memory due to receiving the same results over and over again - does that
> happen for you? It seems it was stuck in recvmsg(), but that may just be
> a side effect of happening to interrupt at that point?

No, strace shows it's just sitting in recvmsg().

As I said, I'm not *sure* it's caused by the same commit; bisecting is
distinctly non-trivial. It just seemed likely.

-- 
dwmw2

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5745 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 876 bytes --]

On Wed, 2015-04-08 at 15:12 +0100, David Woodhouse wrote:
> On Wed, 2015-04-08 at 15:08 +0200, Johannes Berg wrote:
> > Additionally, the failure mode of this was the process running out of
> > memory due to receiving the same results over and over again - does that
> > happen for you? It seems it was stuck in recvmsg(), but that may just be
> > a side effect of happening to interrupt at that point?
> 
> No, strace shows it's just sitting in recvmsg().
> 
> As I said, I'm not *sure* it's caused by the same commit; bisecting is
> distinctly non-trivial. It just seemed likely.

FWIW I went back to the Fedora 3.19 kernel for a week and it didn't
show up again. After rebooting to 4.0 earlier today, it's happened
already.

I'll see if I can find a more reliable way of reproducing it, which
will make it slightly saner to try bisecting.


-- 
dwmw2

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5745 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 2480 bytes --]

On Wed, 2015-04-08 at 15:08 +0200, Johannes Berg wrote:
> On Wed, 2015-04-08 at 13:03 +0100, David Woodhouse wrote:
> 
> > I'm not sure if this is entirely fixed. In Fedora 22 (4.0.0-rc5-git4)
> > I'm occasionally seeing glibc deadlock in __check_pf() on a netlink
> > recvmsg(), here:
> > https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/unix/sysv/linux/check_pf.c;h=162606d7;hb=glibc-2.21#l166
> > 
> > As I understand it, this shouldn't happen. Even if messages are
> > dropped (which surely shouldn't happen as often as I'm seeing this),
> > glibc should get ENOBUFS from the recvmsg() call.
> > 
> > https://bugzilla.redhat.com/show_bug.cgi?id=1209433
> > 
> > I haven't bisected and proved that it *was* this commit which
> > introduced the problem, as it only happens after a day or two of
> > running Evolution and I haven't managed to trigger it more reliably.
> 
> I don't see the connection to this change.
> 
> The issue with my patch was that some code for NLM_F_DUMP would have
> this pattern:
> 
>  int fill_function(...)
>  {
>     ...
>     return nlmsg_end(...);
>  }
> 
>  loop (...) {
>    if (fill_function() <= 0)
>      break; /* continue in next dump */
>  }
> 
> and that all had to be converted to be just "< 0" now.
> 
> Additionally, the failure mode of this was the process running out of
> memory due to receiving the same results over and over again - does that
> happen for you? It seems it was stuck in recvmsg(), but that may just be
> a side effect of happening to interrupt at that point?
> 

I don't think the problem was introduced by your change. At 
https://github.com/nahi/httpclient/issues/232 it seems to have been
observed even in November of last year.

I've added some debugging, and it seems that when it deadlocks, glibc
doesn't get *any* response to its RTM_GETADDR request. I know we'd get
ENOBUFS is a *response* was dropped... but what about when the request
itself is dropped? Does userspace get any hint of that? Is this purely
a glibc bug, for assuming its request got delivered and unconditionally
waiting for a response?

I don't know why it suddenly started happening to me in the 4.0 kernel
when I'd never seen it before, but it's still happening. I've put a
poll() in the glibc code (referenced above), and made it fail after a 5
-second timeout. That will at least prevent me from throwing my
computer out the window for the time being...

-- 
dwmw2

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5691 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Eric Dumazet]

On Tue, 2015-06-09 at 14:34 +0100, David Woodhouse wrote:
> On Wed, 2015-04-08 at 15:08 +0200, Johannes Berg wrote:
> > On Wed, 2015-04-08 at 13:03 +0100, David Woodhouse wrote:
> > 
> > > I'm not sure if this is entirely fixed. In Fedora 22 (4.0.0-rc5-git4)
> > > I'm occasionally seeing glibc deadlock in __check_pf() on a netlink
> > > recvmsg(), here:
> > > https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/unix/sysv/linux/check_pf.c;h=162606d7;hb=glibc-2.21#l166
> > > 
> > > As I understand it, this shouldn't happen. Even if messages are
> > > dropped (which surely shouldn't happen as often as I'm seeing this),
> > > glibc should get ENOBUFS from the recvmsg() call.
> > > 
> > > https://bugzilla.redhat.com/show_bug.cgi?id=1209433
> > > 
> > > I haven't bisected and proved that it *was* this commit which
> > > introduced the problem, as it only happens after a day or two of
> > > running Evolution and I haven't managed to trigger it more reliably.
> > 
> > I don't see the connection to this change.
> > 
> > The issue with my patch was that some code for NLM_F_DUMP would have
> > this pattern:
> > 
> >  int fill_function(...)
> >  {
> >     ...
> >     return nlmsg_end(...);
> >  }
> > 
> >  loop (...) {
> >    if (fill_function() <= 0)
> >      break; /* continue in next dump */
> >  }
> > 
> > and that all had to be converted to be just "< 0" now.
> > 
> > Additionally, the failure mode of this was the process running out of
> > memory due to receiving the same results over and over again - does that
> > happen for you? It seems it was stuck in recvmsg(), but that may just be
> > a side effect of happening to interrupt at that point?
> > 
> 
> I don't think the problem was introduced by your change. At 
> https://github.com/nahi/httpclient/issues/232 it seems to have been
> observed even in November of last year.
> 
> I've added some debugging, and it seems that when it deadlocks, glibc
> doesn't get *any* response to its RTM_GETADDR request. I know we'd get
> ENOBUFS is a *response* was dropped... but what about when the request
> itself is dropped? Does userspace get any hint of that? Is this purely
> a glibc bug, for assuming its request got delivered and unconditionally
> waiting for a response?
> 
> I don't know why it suddenly started happening to me in the 4.0 kernel
> when I'd never seen it before, but it's still happening. I've put a
> poll() in the glibc code (referenced above), and made it fail after a 5
> -second timeout. That will at least prevent me from throwing my
> computer out the window for the time being...
> 

Please check that this patch fixes your issue :

http://patchwork.ozlabs.org/patch/473041/

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 659 bytes --]

On Tue, 2015-06-09 at 17:49 -0700, Eric Dumazet wrote:
> > I've added some debugging, and it seems that when it deadlocks, glibc
> > doesn't get *any* response to its RTM_GETADDR request. I know we'd get
> > ENOBUFS is a *response* was dropped... but what about when the request
> > itself is dropped? ... 
> 
> Please check that this patch fixes your issue :
> 
> http://patchwork.ozlabs.org/patch/473041/

Looks likely; thanks. I'm running with that patch now. I haven't been
able to quickly reproduce the problem on demand, but it usually happens
within a day or two. So it'll be a few days at least before I call it a
success.

-- 
dwmw2

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5691 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Miller]

From: David Woodhouse <dwmw2@infradead.org>
Date: Thu, 11 Jun 2015 01:31:28 +0100

> On Tue, 2015-06-09 at 17:49 -0700, Eric Dumazet wrote:
>> > I've added some debugging, and it seems that when it deadlocks, glibc
>> > doesn't get *any* response to its RTM_GETADDR request. I know we'd get
>> > ENOBUFS is a *response* was dropped... but what about when the request
>> > itself is dropped? ... 
>> 
>> Please check that this patch fixes your issue :
>> 
>> http://patchwork.ozlabs.org/patch/473041/
> 
> Looks likely; thanks. I'm running with that patch now. I haven't been
> able to quickly reproduce the problem on demand, but it usually happens
> within a day or two. So it'll be a few days at least before I call it a
> success.

Yeah, and I just sent that to -stable just over a day ago.

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 944 bytes --]

On Thu, 2015-06-11 at 01:31 +0100, David Woodhouse wrote:
> On Tue, 2015-06-09 at 17:49 -0700, Eric Dumazet wrote:
> > > I've added some debugging, and it seems that when it deadlocks, glibc
> > > doesn't get *any* response to its RTM_GETADDR request. I know we'd get
> > > ENOBUFS is a *response* was dropped... but what about when the request
> > > itself is dropped? ... 
> > 
> > Please check that this patch fixes your issue :
> > 
> > http://patchwork.ozlabs.org/patch/473041/
> 
> Looks likely; thanks. I'm running with that patch now. I haven't been
> able to quickly reproduce the problem on demand, but it usually happens
> within a day or two. So it'll be a few days at least before I call it a
> success.

I just saw the same deadlock happen again; glibc's __check_pf() stuck
in recvmsg() waiting for a response that never comes.

This is the Fedora 22 4.0.5 kernel with the above patch applied.


-- 
dwmw2

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5691 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 1569 bytes --]

On Thu, 2015-06-11 at 23:03 +0100, David Woodhouse wrote:
> On Thu, 2015-06-11 at 01:31 +0100, David Woodhouse wrote:
> > On Tue, 2015-06-09 at 17:49 -0700, Eric Dumazet wrote:
> > > > I've added some debugging, and it seems that when it deadlocks, 
> > > > glibc
> > > > doesn't get *any* response to its RTM_GETADDR request. I know 
> > > > we'd get
> > > > ENOBUFS is a *response* was dropped... but what about when the 
> > > > request
> > > > itself is dropped? ... 
> > > 
> > > Please check that this patch fixes your issue :
> > > 
> > > http://patchwork.ozlabs.org/patch/473041/
> > 
> > Looks likely; thanks. I'm running with that patch now. I haven't 
> > been
> > able to quickly reproduce the problem on demand, but it usually 
> > happens
> > within a day or two. So it'll be a few days at least before I call 
> > it a
> > success.
> 
> I just saw the same deadlock happen again; glibc's __check_pf() stuck
> in recvmsg() waiting for a response that never comes.
> 
> This is the Fedora 22 4.0.5 kernel with the above patch applied.

It did at least manage to survive a single night (which it often
doesn't) if I also apply a version of this patch:
https://patchwork.ozlabs.org/patch/473049/

Even on the known problematic kernels, I have been unable to reproduce
this on demand using either my own threaded getaddrinfo() test program,
or the one you posted here.

-- 
David Woodhouse                            Open Source Technology Centre
David.Woodhouse@intel.com                              Intel Corporation

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5691 bytes --]

Re: Problem with patch "make nlmsg_end() and genlmsg_end() void"

[Johannes Berg]

On Sun, 2015-01-18 at 18:10 -0800, Marcel Holtmann wrote:
> Hi Scott,
> 
> > This patch needs to be reverted ASAP.  git bisect landed me here also;
> > my processes are getting the OOM msgs.  What testing was done?
> > 
> > Seems someone does care that nlmsg_end() returns skb->len.
> 
> I still wonder how this affects userspace. I have not figured that
> out. Something goes wrong pretty badly somewhere.

Ugh, sorry everyone, that was clearly very careless of me.

I can explain how it breaks userspace: basically without the change to <
the dump never finishes - it'll send one message and then break on a 0
return (assuming that no message was sent), and on the next dump
iteration send the same message again (since it assumed previously it
wasn't sent). This would often send processes into a live-lock but if
the process tries to store a complete list of objects (whichever they
are) it'll have to allocate memory in this infinite loop.

johannes