Long stalls creating a new netns after a netns with a SMB client exits

Hi

several docker users reported long stalls when they used containers
with network filesystem mounts. For example, this was reported here:
https://github.com/moby/moby/issues/5618#issuecomment-314515980.
Another user, Pierre Carru (@piec on GH), then managed to create a
simpler reproduction here: https://github.com/piec/docker-samba-loop
which I analysed initially here:
https://github.com/moby/moby/issues/5618#issuecomment-318432218

I managed to condense a repro down to a simple script below, which
does not rely on docker.
- Configure and start a SMB server on the host
- Create a veth pair and configure one peer in the root namespace
- Create a network namespace and move and configure the other veth peer there
- Execute a (mount.cifs; ls; unmount) inside the network namespace
(and in its own mount namespace, though the mount namespace is not
strictly required)
- Direclty after the 'unmount', delete the network namespace and try
to create a new network namespace

Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:

[   67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1

Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).

While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)

I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.

149 more lines

Hello,

On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:

Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:

[   67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1

Sounds like another netdev refcnt leak.

Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).

Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?

While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)

Yeah, the net_mutex is held by cleanup_net().

I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.

OK, so commit d747a7a51b00984127a88113c does not help this case
either.

It would be great if someone more familiar with the code could take a
look. I'm happy to provide additional info (perf traces etc) or test
patches if needed.

The last time I debugged this kind of netdev refcnt leak problem,
I added a few trace_printk() to dev_hold() and dev_put(),
so you can try it too. I will see if I can use your reproducer
here.

Thanks.

On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:

Hello,

On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:

quoted

Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:

[   67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1

Sounds like another netdev refcnt leak.

I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.

quoted

Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).

Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?

Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.

quoted

While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)

Yeah, the net_mutex is held by cleanup_net().

quoted

I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.

OK, so commit d747a7a51b00984127a88113c does not help this case
either.

d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.

quoted

It would be great if someone more familiar with the code could take a
look. I'm happy to provide additional info (perf traces etc) or test
patches if needed.

The last time I debugged this kind of netdev refcnt leak problem,
I added a few trace_printk() to dev_hold() and dev_put(),
so you can try it too. I will see if I can use your reproducer
here.

The last time I encountered the same symptoms were here
http://www.spinics.net/lists/netdev/msg403433.html but this had an
entirely different cause.

I'll also try if I can get some traces out of dev_hold()/dev_put().

Rolf

Thanks.

On 7/28/17 12:58 PM, Rolf Neugebauer wrote:

quoted

quoted

I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.

OK, so commit d747a7a51b00984127a88113c does not help this case
either.

d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.

It could be a dst is cached on a socket and does not get cleared until
the socket time outs are done.

Test that theory by something like this for IPv4 TCP (similar change for
UDP if the client is UDP based):

diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 3a19ea28339f..37db087b6c97 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c

@@ -1855,7 +1855,7 @@ void inet_sk_rx_dst_set(struct sock *sk, const

struct sk_buff *skb)
 {
        struct dst_entry *dst = skb_dst(skb);

-       if (dst && dst_hold_safe(dst)) {
+       if (0 && dst && dst_hold_safe(dst)) {
                sk->sk_rx_dst = dst;
                inet_sk(sk)->rx_dst_ifindex = skb->skb_iif;
        }

I'll also try if I can get some traces out of dev_hold()/dev_put().

Attached patch puts tracepoints in dev_hold / dev_put; very useful for
debugging cases like this. Use perf record and perf script.

On Fri, Jul 28, 2017 at 8:16 PM, David Ahern [off-list ref] wrote:

This removes the 200s stall (the test is IPv4/TCP based)

quoted

I'll also try if I can get some traces out of dev_hold()/dev_put().

Attached patch puts tracepoints in dev_hold / dev_put; very useful for
debugging cases like this. Use perf record and perf script.

I extended the patch to also print out the ifindex and the nd_net to
make it easier to distinguish the different lo interfaces.

I've attached two perf traces, stall.script.txt is with the issue
present and nostall-sleep.script.txt is the same setup but with a
"sleep 1" after the executing the mount/ls/umount in the name space
and before deleting the network namespace. In the latter case there is
*no* stall for 200s.

In  stall.script.txt the "struct net *" of the interfaces in question
is net=0xffff897c6a86c080 and in nostall-sleep.script.txt it is
net=0xffff897c6a8a4100.

The two traces start diverging wrt to the reference counts on lo after
the reference count reaches 5 when deleting the namespace (timestamp
138.709884 in stall.script.txt and 550.856279 in
nostall-sleep.script.txt). In the trace where the stalls are, the
trace point of last decrement is:
kworker/0:1    20 [000]   361.938911:  net:dev_put: dev=lo[1]
net=0xffff897c6a86c080 refcnt 1
        ffffffffad704f6c perf_trace_dev_put+0xa3 ([kernel.kallsyms])
        ffffffffad6dc90e dev_put+0x111 ([kernel.kallsyms])
        ffffffffad6ec5df dst_destroy+0x4b ([kernel.kallsyms])
        ffffffffad6ec70c dst_gc_task+0xbe ([kernel.kallsyms])
        ffffffffad102bf8 process_one_work+0x276 ([kernel.kallsyms])
        ffffffffad103374 worker_thread+0x1eb ([kernel.kallsyms])
        ffffffffad1082d2 kthread+0xe3 ([kernel.kallsyms])
        ffffffffad8b947a ret_from_fork+0x2a ([kernel.kallsyms])


Let me know if there is additional data needed

Rolf

On Fri, Jul 28, 2017 at 11:58 AM, Rolf Neugebauer
[off-list ref] wrote:

On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:

quoted

Hello,

On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:

quoted

Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:

[   67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1

Sounds like another netdev refcnt leak.

I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.

quoted

quoted

Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).

Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?

Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.

This reminds me of

commit f186ce61bb8235d80068c390dc2aad7ca427a4c2
Author: Krister Johansen [off-list ref]
Date:   Thu Jun 8 13:12:38 2017 -0700

    Fix an intermittent pr_emerg warning about lo becoming free.

but this one is merged in 4.12 too, so must be something else.

On Mon, Jul 31, 2017 at 6:06 PM, Cong Wang [off-list ref] wrote:

On Fri, Jul 28, 2017 at 11:58 AM, Rolf Neugebauer
[off-list ref] wrote:

quoted

On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:

quoted

Hello,

On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:

quoted

Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:

[   67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1

Sounds like another netdev refcnt leak.

I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.

quoted

quoted

Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).

Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?

Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.

This reminds me of

commit f186ce61bb8235d80068c390dc2aad7ca427a4c2
Author: Krister Johansen [off-list ref]

5 more quoted lines

I've done my last test on 4.9.40 not 4.12.x but another user reported
the same issue on 4.12 and 4.4.x and I just verified on 4.12.4 as
well.

I reported something with similar symptoms, i.e. stalls which
eventually stopped here:
http://marc.info/?l=linux-netdev&m=147870616302799&w=2 but judging by
the backtraces from that post it looks entirely different

Rolf

On Mon, Jul 31, 2017 at 9:22 AM, Rolf Neugebauer
[off-list ref] wrote:

On Fri, Jul 28, 2017 at 8:16 PM, David Ahern [off-list ref] wrote:

quoted

On 7/28/17 12:58 PM, Rolf Neugebauer wrote:

quoted

quoted

quoted

I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.

OK, so commit d747a7a51b00984127a88113c does not help this case
either.

d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.

It could be a dst is cached on a socket and does not get cleared until
the socket time outs are done.

Test that theory by something like this for IPv4 TCP (similar change for
UDP if the client is UDP based):

diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 3a19ea28339f..37db087b6c97 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c

@@ -1855,7 +1855,7 @@ void inet_sk_rx_dst_set(struct sock *sk, const

struct sk_buff *skb)
 {
        struct dst_entry *dst = skb_dst(skb);

-       if (dst && dst_hold_safe(dst)) {
+       if (0 && dst && dst_hold_safe(dst)) {
                sk->sk_rx_dst = dst;
                inet_sk(sk)->rx_dst_ifindex = skb->skb_iif;
        }

This removes the 200s stall (the test is IPv4/TCP based)

Interesting. This means we have a kernel socket which holds
the dst refcnt.

Looking at the cifs code, it does create a TCP kernel socket
which doesn't hold refcnt to netns but its sk_rx_dst could
still be set as usual, therefore this socket could hold the dst
which holds lo device after the netns is gone. But its timeout
seems to be 60sec (SMB_ECHO_INTERVAL_DEFAULT),
not 200sec.

Ideally it should use a per netns socket so that it would have
a same life-time with netns. But you need to check this with
cifs developers, I don't understand cifs at all.

On 7/31/17 4:01 PM, Cong Wang wrote:

quoted

quoted

diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 3a19ea28339f..37db087b6c97 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c

@@ -1855,7 +1855,7 @@ void inet_sk_rx_dst_set(struct sock *sk, const

struct sk_buff *skb)
 {
        struct dst_entry *dst = skb_dst(skb);

-       if (dst && dst_hold_safe(dst)) {
+       if (0 && dst && dst_hold_safe(dst)) {
                sk->sk_rx_dst = dst;
                inet_sk(sk)->rx_dst_ifindex = skb->skb_iif;
        }

This removes the 200s stall (the test is IPv4/TCP based)

Interesting. This means we have a kernel socket which holds
the dst refcnt.

Right now there is no tracking that I am aware of for a dst cached on
the socket (outside of walking all sockets). I have been bitten by it
several times in trying to make various changes. It's basically a hidden
reference for the device.