loopback device reference count leakage

loopback device reference count leakage

[Kaiwen Xu]

Hi netdev folks,

I am currently experiencing an issue related with the loopback during
network devices shutdown inside a network namespace, which mainfested as

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

showing up every 10 seconds or so in the kernel log. It eventually
causes a deadlock on new network namespace creation.

When I was trying to debug the issue, I tested from latest kernel 4.10-rc
back to 3.19, which all can be reproduced on. I also tried to disable
IPv6, which doesn't help either.

So I tried to patch the kernel with following change to add addtional
logging message for dev_put() and dev_hold().

    https://lkml.org/lkml/2008/7/20/5

Here are all the dev_put/hold() calls for the loopback device inside a 
namespace from creation to shutdown, when the issue occurs.

Jan 11 16:17:43 <hostname> kernel: [ 2196.943640] lo: dev_hold 1 rx_queue_add_kobject
Jan 11 16:17:43 <hostname> kernel: [ 2196.943652] lo: dev_hold 2 netdev_queue_add_kobject
Jan 11 16:17:43 <hostname> kernel: [ 2196.943654] lo: dev_hold 3 register_netdevice
Jan 11 16:17:43 <hostname> kernel: [ 2196.943658] lo: dev_hold 4 neigh_parms_alloc
Jan 11 16:17:43 <hostname> kernel: [ 2196.943660] lo: dev_hold 5 inetdev_init
Jan 11 16:17:43 <hostname> kernel: [ 2197.001771] lo: dev_hold 6 qdisc_alloc
Jan 11 16:17:43 <hostname> kernel: [ 2197.001815] lo: dev_hold 7 dev_get_by_index
Jan 11 16:17:43 <hostname> kernel: [ 2197.001824] lo: dev_hold 8 dev_get_by_index
Jan 11 16:17:43 <hostname> kernel: [ 2197.001831] lo: dev_hold 9 fib_check_nh
Jan 11 16:17:43 <hostname> kernel: [ 2197.001836] lo: dev_hold 10 fib_check_nh
Jan 11 16:17:43 <hostname> kernel: [ 2197.001843] lo: dev_hold 11 dev_get_by_index
Jan 11 16:17:43 <hostname> kernel: [ 2197.001849] lo: dev_hold 12 dev_get_by_index
Jan 11 16:17:43 <hostname> kernel: [ 2197.001852] lo: dev_hold 13 fib_check_nh
Jan 11 16:17:43 <hostname> kernel: [ 2197.001856] lo: dev_hold 14 fib_check_nh
Jan 11 16:17:43 <hostname> kernel: [ 2197.025451] lo: dev_put 14 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.025473] lo: dev_put 13 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.025475] lo: dev_put 12 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.025477] lo: dev_put 11 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.025480] lo: dev_put 10 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.025482] lo: dev_put 9 free_fib_info_rcu
Jan 11 16:17:43 <hostname> kernel: [ 2197.414900] lo: dev_hold 9 dst_init
Jan 11 16:17:43 <hostname> kernel: [ 2197.418634] lo: dev_hold 10 dst_init
Jan 11 16:17:43 <hostname> kernel: [ 2197.418638] lo: dev_hold 11 dst_init
Jan 11 16:17:43 <hostname> kernel: [ 2197.445496] lo: dev_put 11 dst_destroy
Jan 11 16:17:44 <hostname> kernel: [ 2197.614240] lo: dev_hold 11 dst_init
Jan 11 16:20:41 <hostname> kernel: [ 2374.898896] lo: dev_hold 12 dst_init
Jan 11 16:20:41 <hostname> kernel: [ 2374.898917] lo: dev_hold 13 __neigh_create
Jan 11 16:23:42 <hostname> kernel: [ 2555.900160] lo: dev_hold 14 dst_init
Jan 11 16:24:10 <hostname> kernel: [ 2583.573193] lo: dev_hold 15 dst_init
Jan 11 16:26:09 <hostname> kernel: [ 2702.992174] lo: dev_hold 16 dst_init
Jan 11 16:27:15 <hostname> kernel: [ 2769.188044] lo: dev_hold 17 dst_init
Jan 11 16:31:57 <hostname> kernel: [ 3050.821593] lo: dev_hold 18 dst_init
Jan 11 16:37:41 <hostname> kernel: [ 3394.962714] lo: dev_hold 19 dst_init
Jan 11 16:46:27 <hostname> kernel: [ 3921.376163] lo: dev_hold 20 dst_init
Jan 11 16:46:30 <hostname> kernel: [ 3923.759813] lo: dev_hold 21 dst_init
Jan 11 16:47:01 <hostname> kernel: [ 3954.802588] lo: dev_hold 22 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3954.802596] lo: dev_hold 23 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3954.802599] lo: dev_hold 24 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3954.802602] lo: dev_hold 25 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3954.802605] lo: dev_hold 26 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3954.802609] lo: dev_hold 27 dst_ifdown
Jan 11 16:47:01 <hostname> kernel: [ 3955.482563] lo: dev_put 27 dst_destroy
Jan 11 16:47:01 <hostname> kernel: [ 3955.482566] lo: dev_put 26 dst_destroy
Jan 11 16:47:01 <hostname> kernel: [ 3955.482568] lo: dev_put 25 dst_destroy
Jan 11 16:47:01 <hostname> kernel: [ 3955.482570] lo: dev_put 24 dst_destroy
Jan 11 16:47:01 <hostname> kernel: [ 3955.482572] lo: dev_put 23 dst_destroy
Jan 11 16:47:01 <hostname> kernel: [ 3955.482574] lo: dev_put 22 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.651505] lo: dev_put 21 neigh_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.653397] lo: dev_put 20 qdisc_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.653432] lo: dev_put 19 neigh_parms_release
Jan 11 16:49:20 <hostname> kernel: [ 4093.653463] lo: dev_put 18 rx_queue_release
Jan 11 16:49:20 <hostname> kernel: [ 4093.653474] lo: dev_put 17 netdev_queue_release
Jan 11 16:49:20 <hostname> kernel: [ 4093.653520] lo: dev_put 16 rollback_registered_many
Jan 11 16:49:20 <hostname> kernel: [ 4093.663424] lo: dev_put 15 free_fib_info_rcu
Jan 11 16:49:20 <hostname> kernel: [ 4093.667401] lo: dev_put 14 free_fib_info_rcu
Jan 11 16:49:20 <hostname> kernel: [ 4093.667430] lo: dev_put 13 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667432] lo: dev_put 12 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667434] lo: dev_put 11 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667436] lo: dev_put 10 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667438] lo: dev_put 9 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667441] lo: dev_put 8 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667446] lo: dev_put 7 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667453] lo: dev_put 6 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667459] lo: dev_put 5 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667461] lo: dev_put 4 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667463] lo: dev_put 3 dst_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667478] lo: dev_put 2 in_dev_finish_destroy
Jan 11 16:49:20 <hostname> kernel: [ 4093.667493] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:20 <hostname> kernel: [ 4093.667495] lo: dev_put 2 dst_ifdown
Jan 11 16:49:21 <hostname> kernel: [ 4094.691406] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:21 <hostname> kernel: [ 4094.691409] lo: dev_put 2 dst_ifdown
Jan 11 16:49:22 <hostname> kernel: [ 4095.715386] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:22 <hostname> kernel: [ 4095.715390] lo: dev_put 2 dst_ifdown
Jan 11 16:49:23 <hostname> kernel: [ 4096.739367] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:23 <hostname> kernel: [ 4096.739370] lo: dev_put 2 dst_ifdown
Jan 11 16:49:24 <hostname> kernel: [ 4097.763338] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:24 <hostname> kernel: [ 4097.763342] lo: dev_put 2 dst_ifdown
Jan 11 16:49:25 <hostname> kernel: [ 4098.787312] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:25 <hostname> kernel: [ 4098.787315] lo: dev_put 2 dst_ifdown
Jan 11 16:49:26 <hostname> kernel: [ 4099.811293] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:26 <hostname> kernel: [ 4099.811297] lo: dev_put 2 dst_ifdown
Jan 11 16:49:27 <hostname> kernel: [ 4100.835270] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:27 <hostname> kernel: [ 4100.835273] lo: dev_put 2 dst_ifdown
Jan 11 16:49:28 <hostname> kernel: [ 4101.859249] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:28 <hostname> kernel: [ 4101.859252] lo: dev_put 2 dst_ifdown
Jan 11 16:49:29 <hostname> kernel: [ 4102.883228] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:29 <hostname> kernel: [ 4102.883231] lo: dev_put 2 dst_ifdown
Jan 11 16:49:30 <hostname> kernel: [ 4103.907196] unregister_netdevice: waiting for lo to become free. Usage count = 1
Jan 11 16:49:30 <hostname> kernel: [ 4103.916753] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:30 <hostname> kernel: [ 4103.916755] lo: dev_put 2 dst_ifdown
Jan 11 16:49:31 <hostname> kernel: [ 4104.939171] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:31 <hostname> kernel: [ 4104.939174] lo: dev_put 2 dst_ifdown
Jan 11 16:49:32 <hostname> kernel: [ 4105.963147] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:32 <hostname> kernel: [ 4105.963150] lo: dev_put 2 dst_ifdown
Jan 11 16:49:33 <hostname> kernel: [ 4106.987135] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:33 <hostname> kernel: [ 4106.987138] lo: dev_put 2 dst_ifdown
Jan 11 16:49:34 <hostname> kernel: [ 4108.011109] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:34 <hostname> kernel: [ 4108.011112] lo: dev_put 2 dst_ifdown
Jan 11 16:49:35 <hostname> kernel: [ 4109.035084] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:35 <hostname> kernel: [ 4109.035087] lo: dev_put 2 dst_ifdown
Jan 11 16:49:36 <hostname> kernel: [ 4110.059057] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:36 <hostname> kernel: [ 4110.059060] lo: dev_put 2 dst_ifdown
Jan 11 16:49:37 <hostname> kernel: [ 4111.095053] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:37 <hostname> kernel: [ 4111.095056] lo: dev_put 2 dst_ifdown
Jan 11 16:49:38 <hostname> kernel: [ 4112.119017] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:38 <hostname> kernel: [ 4112.119020] lo: dev_put 2 dst_ifdown
Jan 11 16:49:39 <hostname> kernel: [ 4113.142987] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:39 <hostname> kernel: [ 4113.142990] lo: dev_put 2 dst_ifdown
Jan 11 16:49:40 <hostname> kernel: [ 4114.166957] unregister_netdevice: waiting for lo to become free. Usage count = 1
Jan 11 16:49:40 <hostname> kernel: [ 4114.176525] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:40 <hostname> kernel: [ 4114.176527] lo: dev_put 2 dst_ifdown
Jan 11 16:49:41 <hostname> kernel: [ 4115.198945] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:41 <hostname> kernel: [ 4115.198949] lo: dev_put 2 dst_ifdown
Jan 11 16:49:42 <hostname> kernel: [ 4116.222927] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:42 <hostname> kernel: [ 4116.222931] lo: dev_put 2 dst_ifdown
Jan 11 16:49:43 <hostname> kernel: [ 4117.246894] lo: dev_hold 2 dst_ifdown
Jan 11 16:49:43 <hostname> kernel: [ 4117.246897] lo: dev_put 2 dst_ifdown

As a comparison, here are the calls when the issue didn't occur.

Jan 11 15:59:57 <hostname> kernel: [ 1131.509464] lo: dev_hold 1 rx_queue_add_kobject
Jan 11 15:59:57 <hostname> kernel: [ 1131.509477] lo: dev_hold 2 netdev_queue_add_kobject
Jan 11 15:59:57 <hostname> kernel: [ 1131.509480] lo: dev_hold 3 register_netdevice
Jan 11 15:59:57 <hostname> kernel: [ 1131.509483] lo: dev_hold 4 neigh_parms_alloc
Jan 11 15:59:57 <hostname> kernel: [ 1131.509485] lo: dev_hold 5 inetdev_init
Jan 11 15:59:57 <hostname> kernel: [ 1131.560173] lo: dev_hold 6 qdisc_alloc
Jan 11 15:59:57 <hostname> kernel: [ 1131.560203] lo: dev_hold 7 dev_get_by_index
Jan 11 15:59:57 <hostname> kernel: [ 1131.560210] lo: dev_hold 8 dev_get_by_index
Jan 11 15:59:57 <hostname> kernel: [ 1131.560217] lo: dev_hold 9 fib_check_nh
Jan 11 15:59:57 <hostname> kernel: [ 1131.560221] lo: dev_hold 10 fib_check_nh
Jan 11 15:59:57 <hostname> kernel: [ 1131.560228] lo: dev_hold 11 dev_get_by_index
Jan 11 15:59:57 <hostname> kernel: [ 1131.560234] lo: dev_hold 12 dev_get_by_index
Jan 11 15:59:57 <hostname> kernel: [ 1131.560237] lo: dev_hold 13 fib_check_nh
Jan 11 15:59:57 <hostname> kernel: [ 1131.560240] lo: dev_hold 14 fib_check_nh
Jan 11 15:59:57 <hostname> kernel: [ 1131.580072] lo: dev_put 14 free_fib_info_rcu
Jan 11 15:59:57 <hostname> kernel: [ 1131.580077] lo: dev_put 13 free_fib_info_rcu
Jan 11 15:59:57 <hostname> kernel: [ 1131.580079] lo: dev_put 12 free_fib_info_rcu
Jan 11 15:59:57 <hostname> kernel: [ 1131.580081] lo: dev_put 11 free_fib_info_rcu
Jan 11 15:59:57 <hostname> kernel: [ 1131.580084] lo: dev_put 10 free_fib_info_rcu
Jan 11 15:59:57 <hostname> kernel: [ 1131.580097] lo: dev_put 9 free_fib_info_rcu
Jan 11 16:00:00 <hostname> kernel: [ 1134.594026] lo: dev_hold 9 dst_init
Jan 11 16:00:01 <hostname> kernel: [ 1135.020297] lo: dev_hold 10 dst_init
Jan 11 16:00:01 <hostname> kernel: [ 1135.020304] lo: dev_hold 11 dst_init
Jan 11 16:00:01 <hostname> kernel: [ 1135.039974] lo: dev_put 11 dst_destroy
Jan 11 16:00:02 <hostname> kernel: [ 1136.453739] lo: dev_hold 11 dst_init
Jan 11 16:10:03 <hostname> kernel: [ 1736.603352] lo: dev_hold 12 dst_init
Jan 11 16:10:03 <hostname> kernel: [ 1736.603374] lo: dev_hold 13 __neigh_create
Jan 11 16:11:01 <hostname> kernel: [ 1795.209103] lo: dev_hold 14 dst_init
Jan 11 16:11:26 <hostname> kernel: [ 1820.491721] lo: dev_hold 15 dst_init
Jan 11 16:11:31 <hostname> kernel: [ 1825.519853] lo: dev_hold 16 dst_init
Jan 11 16:12:08 <hostname> kernel: [ 1861.911872] lo: dev_hold 17 dst_init
Jan 11 16:12:10 <hostname> kernel: [ 1864.509095] lo: dev_hold 18 dst_init
Jan 11 16:12:11 <hostname> kernel: [ 1865.094510] lo: dev_hold 19 dst_init
Jan 11 16:12:11 <hostname> kernel: [ 1865.510777] lo: dev_hold 20 dst_init
Jan 11 16:12:12 <hostname> kernel: [ 1865.994909] lo: dev_hold 21 dst_init
Jan 11 16:12:13 <hostname> kernel: [ 1866.861904] lo: dev_hold 22 dst_init
Jan 11 16:12:13 <hostname> kernel: [ 1867.195370] lo: dev_hold 23 dst_init
Jan 11 16:12:14 <hostname> kernel: [ 1868.167117] lo: dev_hold 24 dst_init
Jan 11 16:12:48 <hostname> kernel: [ 1902.280896] lo: dev_hold 25 dst_ifdown
Jan 11 16:12:49 <hostname> kernel: [ 1902.960852] lo: dev_put 25 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.413561] lo: dev_put 24 neigh_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.415441] lo: dev_put 23 qdisc_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.415476] lo: dev_put 22 neigh_parms_release
Jan 11 16:14:59 <hostname> kernel: [ 2033.415508] lo: dev_put 21 rx_queue_release
Jan 11 16:14:59 <hostname> kernel: [ 2033.415518] lo: dev_put 20 netdev_queue_release
Jan 11 16:14:59 <hostname> kernel: [ 2033.415563] lo: dev_put 19 rollback_registered_many
Jan 11 16:14:59 <hostname> kernel: [ 2033.425510] lo: dev_put 18 free_fib_info_rcu
Jan 11 16:14:59 <hostname> kernel: [ 2033.429481] lo: dev_put 17 free_fib_info_rcu
Jan 11 16:14:59 <hostname> kernel: [ 2033.429499] lo: dev_put 16 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429507] lo: dev_put 15 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429509] lo: dev_put 14 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429511] lo: dev_put 13 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429513] lo: dev_put 12 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429515] lo: dev_put 11 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429517] lo: dev_put 10 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429519] lo: dev_put 9 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429523] lo: dev_put 8 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429529] lo: dev_put 7 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429536] lo: dev_put 6 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429541] lo: dev_put 5 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429543] lo: dev_put 4 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429545] lo: dev_put 3 dst_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429551] lo: dev_put 2 in_dev_finish_destroy
Jan 11 16:14:59 <hostname> kernel: [ 2033.429563] lo: dev_hold 2 dst_ifdown
Jan 11 16:14:59 <hostname> kernel: [ 2033.429565] lo: dev_put 2 dst_ifdown
Jan 11 16:15:00 <hostname> kernel: [ 2034.453484] lo: dev_hold 2 dst_ifdown
Jan 11 16:15:00 <hostname> kernel: [ 2034.453487] lo: dev_put 2 dst_ifdown
Jan 11 16:15:01 <hostname> kernel: [ 2035.129452] lo: dev_put 1 dst_destroy

Could you please give me some pointers why this issue could occur? I can
also provide addtional information if needed.

Thanks,
Kaiwen

Re: loopback device reference count leakage

[Cong Wang]

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

Hello,

On Mon, Jan 23, 2017 at 9:17 PM, Kaiwen Xu <kevin@kevxu.net> wrote:
> Hi netdev folks,
>
> I am currently experiencing an issue related with the loopback during
> network devices shutdown inside a network namespace, which mainfested as
>
>     unregister_netdevice: waiting for lo to become free. Usage count = 1
>
> showing up every 10 seconds or so in the kernel log. It eventually
> causes a deadlock on new network namespace creation.

It is at least the 3rd time I saw this bug report. ;)

>
> When I was trying to debug the issue, I tested from latest kernel 4.10-rc
> back to 3.19, which all can be reproduced on. I also tried to disable
> IPv6, which doesn't help either.
>
> So I tried to patch the kernel with following change to add addtional
> logging message for dev_put() and dev_hold().
>
>     https://lkml.org/lkml/2008/7/20/5
>
> Here are all the dev_put/hold() calls for the loopback device inside a
> namespace from creation to shutdown, when the issue occurs.

Excellent debugging!

>From your debugging output, the dst_ifdown() looks suspicious to me,
it seems to be the reason why we miss one dev_put().


> Could you please give me some pointers why this issue could occur? I can
> also provide addtional information if needed.
>

Do you mind to try the attached patch (compile only)? Try it with your
debugging printk's in case it doesn't fix this bug, but it should make some
difference at least.

Thanks!

[-- Attachment #2: dst-loopback.diff --]
[-- Type: text/plain, Size: 540 bytes --]

diff --git a/net/core/dst.c b/net/core/dst.c
index b5cbbe0..99184ba 100644
--- a/net/core/dst.c
+++ b/net/core/dst.c
@@ -441,8 +441,12 @@ static void dst_ifdown(struct dst_entry *dst, struct net_device *dev,
 		dst->input = dst_discard;
 		dst->output = dst_discard_out;
 	} else {
-		dst->dev = dev_net(dst->dev)->loopback_dev;
-		dev_hold(dst->dev);
+		if (dst->dev != dev_net(dst->dev)->loopback_dev) {
+			dst->dev = dev_net(dst->dev)->loopback_dev;
+			dev_hold(dst->dev);
+		} else {
+			dst->dev = NULL;
+		}
 		dev_put(dev);
 	}
 }

Re: loopback device reference count leakage

[Kaiwen Xu]

Hi Cong,

I tested out your patch, it does seem to be preventing the issue from
happening. Here are the dev_put/dev_hold() calls with your patch
applied.

Jan 26 00:29:08 <hostname> kernel: [ 4385.940243] lo: dev_hold 1 rx_queue_add_kobject
Jan 26 00:29:08 <hostname> kernel: [ 4385.940255] lo: dev_hold 2 netdev_queue_add_kobject
Jan 26 00:29:08 <hostname> kernel: [ 4385.940257] lo: dev_hold 3 register_netdevice
Jan 26 00:29:08 <hostname> kernel: [ 4385.940260] lo: dev_hold 4 neigh_parms_alloc
Jan 26 00:29:08 <hostname> kernel: [ 4385.940262] lo: dev_hold 5 inetdev_init
Jan 26 00:29:08 <hostname> kernel: [ 4386.017699] lo: dev_hold 6 qdisc_alloc
Jan 26 00:29:08 <hostname> kernel: [ 4386.017741] lo: dev_hold 7 dev_get_by_index
Jan 26 00:29:08 <hostname> kernel: [ 4386.017749] lo: dev_hold 8 dev_get_by_index
Jan 26 00:29:08 <hostname> kernel: [ 4386.017756] lo: dev_hold 9 fib_check_nh
Jan 26 00:29:08 <hostname> kernel: [ 4386.017760] lo: dev_hold 10 fib_check_nh
Jan 26 00:29:08 <hostname> kernel: [ 4386.017767] lo: dev_hold 11 dev_get_by_index
Jan 26 00:29:08 <hostname> kernel: [ 4386.017772] lo: dev_hold 12 dev_get_by_index
Jan 26 00:29:08 <hostname> kernel: [ 4386.017775] lo: dev_hold 13 fib_check_nh
Jan 26 00:29:08 <hostname> kernel: [ 4386.017778] lo: dev_hold 14 fib_check_nh
Jan 26 00:29:08 <hostname> kernel: [ 4386.033548] lo: dev_put 14 free_fib_info_rcu
Jan 26 00:29:08 <hostname> kernel: [ 4386.033553] lo: dev_put 13 free_fib_info_rcu
Jan 26 00:29:08 <hostname> kernel: [ 4386.033556] lo: dev_put 12 free_fib_info_rcu
Jan 26 00:29:08 <hostname> kernel: [ 4386.033558] lo: dev_put 11 free_fib_info_rcu
Jan 26 00:29:08 <hostname> kernel: [ 4386.033560] lo: dev_put 10 free_fib_info_rcu
Jan 26 00:29:08 <hostname> kernel: [ 4386.033563] lo: dev_put 9 free_fib_info_rcu
Jan 26 00:29:09 <hostname> kernel: [ 4386.438175] lo: dev_hold 9 dst_init
Jan 26 00:29:09 <hostname> kernel: [ 4386.442558] lo: dev_hold 10 dst_init
Jan 26 00:29:09 <hostname> kernel: [ 4386.442564] lo: dev_hold 11 dst_init
Jan 26 00:29:09 <hostname> kernel: [ 4386.477575] lo: dev_put 11 dst_destroy
Jan 26 00:29:09 <hostname> kernel: [ 4386.641150] lo: dev_hold 11 dst_init
Jan 26 00:37:59 <hostname> kernel: [ 4916.949380] lo: dev_hold 12 dst_init
Jan 26 00:37:59 <hostname> kernel: [ 4916.949401] lo: dev_hold 13 __neigh_create
Jan 26 00:56:52 <hostname> kernel: [ 6049.882993] lo: dev_hold 14 dst_init
Jan 26 00:57:54 <hostname> kernel: [ 6111.782520] lo: dev_hold 15 dst_init
Jan 26 01:28:02 <hostname> kernel: [ 7920.396248] lo: dev_hold 16 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396251] lo: dev_hold 17 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396254] lo: dev_hold 18 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396257] lo: dev_hold 19 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396260] lo: dev_hold 20 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396263] lo: dev_hold 21 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396266] lo: dev_hold 22 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396268] lo: dev_hold 23 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396271] lo: dev_hold 24 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396274] lo: dev_hold 25 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396277] lo: dev_hold 26 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396280] lo: dev_hold 27 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396283] lo: dev_hold 28 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396286] lo: dev_hold 29 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396288] lo: dev_hold 30 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396291] lo: dev_hold 31 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396294] lo: dev_hold 32 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396297] lo: dev_hold 33 dst_ifdown
Jan 26 01:28:02 <hostname> kernel: [ 7920.396300] lo: dev_hold 34 dst_ifdown
Jan 26 01:28:03 <hostname> kernel: [ 7920.584272] lo: dev_put 34 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584277] lo: dev_put 33 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584279] lo: dev_put 32 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584281] lo: dev_put 31 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584283] lo: dev_put 30 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584285] lo: dev_put 29 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584287] lo: dev_put 28 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584289] lo: dev_put 27 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584290] lo: dev_put 26 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584301] lo: dev_put 25 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584303] lo: dev_put 24 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584305] lo: dev_put 23 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584307] lo: dev_put 22 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584309] lo: dev_put 21 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584311] lo: dev_put 20 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584324] lo: dev_put 19 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584326] lo: dev_put 18 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584328] lo: dev_put 17 dst_destroy
Jan 26 01:28:03 <hostname> kernel: [ 7920.584330] lo: dev_put 16 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.750192] lo: dev_put 15 neigh_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.751961] lo: dev_put 14 qdisc_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.752014] lo: dev_put 13 neigh_parms_release
Jan 26 01:30:32 <hostname> kernel: [ 8069.752055] lo: dev_put 12 rx_queue_release
Jan 26 01:30:32 <hostname> kernel: [ 8069.752069] lo: dev_put 11 netdev_queue_release
Jan 26 01:30:32 <hostname> kernel: [ 8069.752130] lo: dev_put 10 rollback_registered_many
Jan 26 01:30:32 <hostname> kernel: [ 8069.762072] lo: dev_put 9 free_fib_info_rcu
Jan 26 01:30:32 <hostname> kernel: [ 8069.766123] lo: dev_put 8 free_fib_info_rcu
Jan 26 01:30:32 <hostname> kernel: [ 8069.766127] lo: dev_put 7 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766129] lo: dev_put 6 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766132] lo: dev_put 5 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766134] lo: dev_put 4 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766135] lo: dev_put 3 dst_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766146] lo: dev_put 2 in_dev_finish_destroy
Jan 26 01:30:32 <hostname> kernel: [ 8069.766180] lo: dev_put 1 dst_ifdown

However, what confuses me is that when the issue didn't occur, there
were always multiple dst_ifdown() calls at the end continuously holding
and releasing the loopback device reference count (sometimes it will be
looping for about a minute), until the last dst_destroy() happens. E.g.

Jan 11 16:14:59 <hostname> kernel: [ 2033.429563] lo: dev_hold 2 dst_ifdown
Jan 11 16:14:59 <hostname> kernel: [ 2033.429565] lo: dev_put 2 dst_ifdown
Jan 11 16:15:00 <hostname> kernel: [ 2034.453484] lo: dev_hold 2 dst_ifdown
Jan 11 16:15:00 <hostname> kernel: [ 2034.453487] lo: dev_put 2 dst_ifdown

(this continues...)

Jan 11 16:15:01 <hostname> kernel: [ 2035.129452] lo: dev_put 1 dst_destroy

And when the issue did occur, the last dst_destroy() call never occurs.

I did some further digging, seems like the last dst_destroy() call is
trigger by dst_gc_task(). Here is the call trace (I added a dump_stack()
call to dst_destroy()).

Jan 19 19:44:00 <hostname> kernel: [ 1507.052752] Call Trace:
Jan 19 19:44:00 <hostname> kernel: [ 1507.052757]  [<ffffffff813be1cc>] dump_stack+0x63/0x87
Jan 19 19:44:00 <hostname> kernel: [ 1507.052759]  [<ffffffff816e1ea4>] dst_destroy+0x14/0x110
Jan 19 19:44:00 <hostname> kernel: [ 1507.052761]  [<ffffffff816e215c>] dst_gc_task+0x1bc/0x210
Jan 19 19:44:00 <hostname> kernel: [ 1507.052764]  [<ffffffff810b33d5>] ? put_prev_entity+0x35/0x670
Jan 19 19:44:00 <hostname> kernel: [ 1507.052767]  [<ffffffff81016656>] ? __switch_to+0x1d6/0x570
Jan 19 19:44:00 <hostname> kernel: [ 1507.052770]  [<ffffffff81095960>] process_one_work+0x150/0x3f0
Jan 19 19:44:00 <hostname> kernel: [ 1507.052772]  [<ffffffff810960da>] worker_thread+0x11a/0x470
Jan 19 19:44:00 <hostname> kernel: [ 1507.052776]  [<ffffffff817da0f9>] ? __schedule+0x359/0x980
Jan 19 19:44:00 <hostname> kernel: [ 1507.052778]  [<ffffffff81095fc0>] ? rescuer_thread+0x310/0x310
Jan 19 19:44:00 <hostname> kernel: [ 1507.052780]  [<ffffffff8109b969>] kthread+0xc9/0xe0
Jan 19 19:44:00 <hostname> kernel: [ 1507.052782]  [<ffffffff8109b8a0>] ? kthread_park+0x60/0x60
Jan 19 19:44:00 <hostname> kernel: [ 1507.052786]  [<ffffffff817de34f>] ret_from_fork+0x3f/0x70
Jan 19 19:44:00 <hostname> kernel: [ 1507.052788]  [<ffffffff8109b8a0>] ? kthread_park+0x60/0x60

Thanks,
Kaiwen

On Wed, Jan 25, 2017 at 11:50:25AM -0800, Cong Wang wrote:
> Hello,
> 
> On Mon, Jan 23, 2017 at 9:17 PM, Kaiwen Xu <kevin@kevxu.net> wrote:
> > Hi netdev folks,
> >
> > I am currently experiencing an issue related with the loopback during
> > network devices shutdown inside a network namespace, which mainfested as
> >
> >     unregister_netdevice: waiting for lo to become free. Usage count = 1
> >
> > showing up every 10 seconds or so in the kernel log. It eventually
> > causes a deadlock on new network namespace creation.
> 
> It is at least the 3rd time I saw this bug report. ;)
> 
> >
> > When I was trying to debug the issue, I tested from latest kernel 4.10-rc
> > back to 3.19, which all can be reproduced on. I also tried to disable
> > IPv6, which doesn't help either.
> >
> > So I tried to patch the kernel with following change to add addtional
> > logging message for dev_put() and dev_hold().
> >
> >     https://lkml.org/lkml/2008/7/20/5
> >
> > Here are all the dev_put/hold() calls for the loopback device inside a
> > namespace from creation to shutdown, when the issue occurs.
> 
> Excellent debugging!
> 
> From your debugging output, the dst_ifdown() looks suspicious to me,
> it seems to be the reason why we miss one dev_put().
> 
> 
> > Could you please give me some pointers why this issue could occur? I can
> > also provide addtional information if needed.
> >
> 
> Do you mind to try the attached patch (compile only)? Try it with your
> debugging printk's in case it doesn't fix this bug, but it should make some
> difference at least.
> 
> Thanks!

> diff --git a/net/core/dst.c b/net/core/dst.c
> index b5cbbe0..99184ba 100644
> --- a/net/core/dst.c
> +++ b/net/core/dst.c
> @@ -441,8 +441,12 @@ static void dst_ifdown(struct dst_entry *dst, struct net_device *dev,
>  		dst->input = dst_discard;
>  		dst->output = dst_discard_out;
>  	} else {
> -		dst->dev = dev_net(dst->dev)->loopback_dev;
> -		dev_hold(dst->dev);
> +		if (dst->dev != dev_net(dst->dev)->loopback_dev) {
> +			dst->dev = dev_net(dst->dev)->loopback_dev;
> +			dev_hold(dst->dev);
> +		} else {
> +			dst->dev = NULL;
> +		}
>  		dev_put(dev);
>  	}
>  }

Re: loopback device reference count leakage

[Cong Wang]

On Thu, Jan 26, 2017 at 2:51 PM, Kaiwen Xu <kevin@kevxu.net> wrote:
> Hi Cong,
>
> I tested out your patch, it does seem to be preventing the issue from
> happening. Here are the dev_put/dev_hold() calls with your patch
> applied.

Good. Now we narrow down the bug to those dst's referring loopback_dev.


> However, what confuses me is that when the issue didn't occur, there
> were always multiple dst_ifdown() calls at the end continuously holding
> and releasing the loopback device reference count (sometimes it will be
> looping for about a minute), until the last dst_destroy() happens. E.g.
>
> Jan 11 16:14:59 <hostname> kernel: [ 2033.429563] lo: dev_hold 2 dst_ifdown
> Jan 11 16:14:59 <hostname> kernel: [ 2033.429565] lo: dev_put 2 dst_ifdown
> Jan 11 16:15:00 <hostname> kernel: [ 2034.453484] lo: dev_hold 2 dst_ifdown
> Jan 11 16:15:00 <hostname> kernel: [ 2034.453487] lo: dev_put 2 dst_ifdown
>
> (this continues...)
>
> Jan 11 16:15:01 <hostname> kernel: [ 2035.129452] lo: dev_put 1 dst_destroy
>
> And when the issue did occur, the last dst_destroy() call never occurs.

Yeah, I noticed that too. So we have two cases here:

1) If these dst's (referring to loopback_dev) really need to stay in
GC for a long
time, then we should really just releasing loopback references as what my patch
does.

2) If they don't not, that is, if they are supposed to be GC'ed soon
in this case,
then we should investigate why they are still there.

2) seems more likely than 1), because at the point when loopback device is
being unregistered, the whole network namespace is being gone, all other
devices are already gone, no one should a take reference to this netns,
therefore no one should take a reference to any dst referring to any device
in it too, even though the dst GC is global.

I'd suggest to you add some debugging printk's to the dst refcount functions,
or maybe just inside dst_gc_task(). I think the last dst referring to
the loopback
dev is still being referred at that point, which prevents GC from destroying it.

Meanwhile, if it would be also helpful if you can share how you managed to
reproduce this reliably, I saw this bug in our data center before but never
know how to reproduce it.

Thanks!

Re: loopback device reference count leakage

[Kaiwen Xu]

On Thu, Jan 26, 2017 at 05:01:38PM -0800, Cong Wang wrote:
> I'd suggest to you add some debugging printk's to the dst refcount functions,
> or maybe just inside dst_gc_task(). I think the last dst referring to
> the loopback
> dev is still being referred at that point, which prevents GC from destroying it.

Thanks for the suggestion! I will test it out.

> Meanwhile, if it would be also helpful if you can share how you managed to
> reproduce this reliably, I saw this bug in our data center before but never
> know how to reproduce it.

I used one of our applications to reproduce the issue, to be honest, I
haven't completely isolated which part of the code is triggering the
bug. However, the suspicion is that, since the application basically
acts as a web crawler, the bug is manifested after initiating a large
amount connections to a wide range of IP addresses in a short period of
time. Hope it somewhat helps.

Thanks,
Kaiwen

Re: loopback device reference count leakage

[Cong Wang]

On Mon, Feb 6, 2017 at 6:32 PM, Kaiwen Xu <kevin@kevxu.net> wrote:
> Hi Cong,
>
> I did some more testing, seems like your second assumption is correct.
> There is indeed some things holding the references to a particular dst
> which preventing it to be gc'ed.

Excellent!

>
> I added logging to each dst_hold (or dst_hold_safe, or
> skb_dst_force_safe) and dst_release, which formatted as following:
>
> <dev name> (<protocol>) [<dst addr>]: dst_release / dst_hold ... <refcnt> <caller function>
>
> And inside dst_gc_task(), I added logging when gc delay occurred,
> formatted as:
>
> [dst_gc_task] <dev name> (<protocol>): delayed <refcnt>
>
> I have the log attached.

The following line looks suspicious:

Feb  6 16:27:24 <hostname> kernel: [63589.458067] [dst_gc_task]
lodebug (2): delayed 19

Looks like you ended up having one dst whose refcnt is 19 in GC,
and this lasted for a rather long time for some reason.

It is hard to know if it is a refcnt leak even with your log, since there were
4K+ refcnt'ing happened on that dst...

Meanwhile, can you share your setup of your container? What network device
do you use in your container? How is it connected to outside?

Thanks.

Re: loopback device reference count leakage

[Kaiwen Xu]

I am using macvlan device inside the container. With following Docker
network plugin:

https://github.com/gopher-net/macvlan-docker-plugin

Each macvlan device, which gets assigned into the container network
namespace, is attached to host's vlan device, which is then attached to
host's eth0.

    eth0  <==  eth0.1000  <==  macvlan0 (host macvlan device)
                          \==  macvlan1 (container macvlan device)
                          \==  macvlan2 (container macvlan device)
                          ...

eth0 has a 10.x.x.x/24 IP address. eth0.1000 is able to use any of the
addresses in another 10.x.x.y/24 range (different from the /24 assigned to
eth0), but itself isn't directly assigned an IP address. macvlan0, which
is on the host, is assigned an IP address in the 10.x.x.y/24 range that
belongs to eth0.1000. When container start up, a new macvlan device is
created attaching to eth0.1000 with a different 10.x.x.y/24 address,
which is assigned into the container network namespace. The container's
10.x.x.y/24 address is directly reachable outside of the host.

Thanks,
Kaiwen

On Wed, Feb 08, 2017 at 01:50:57PM -0800, Cong Wang wrote:
> On Mon, Feb 6, 2017 at 6:32 PM, Kaiwen Xu <kevin@kevxu.net> wrote:
> > Hi Cong,
> >
> > I did some more testing, seems like your second assumption is correct.
> > There is indeed some things holding the references to a particular dst
> > which preventing it to be gc'ed.
> 
> Excellent!
> 
> >
> > I added logging to each dst_hold (or dst_hold_safe, or
> > skb_dst_force_safe) and dst_release, which formatted as following:
> >
> > <dev name> (<protocol>) [<dst addr>]: dst_release / dst_hold ... <refcnt> <caller function>
> >
> > And inside dst_gc_task(), I added logging when gc delay occurred,
> > formatted as:
> >
> > [dst_gc_task] <dev name> (<protocol>): delayed <refcnt>
> >
> > I have the log attached.
> 
> The following line looks suspicious:
> 
> Feb  6 16:27:24 <hostname> kernel: [63589.458067] [dst_gc_task]
> lodebug (2): delayed 19
> 
> Looks like you ended up having one dst whose refcnt is 19 in GC,
> and this lasted for a rather long time for some reason.
> 
> It is hard to know if it is a refcnt leak even with your log, since there were
> 4K+ refcnt'ing happened on that dst...
> 
> Meanwhile, can you share your setup of your container? What network device
> do you use in your container? How is it connected to outside?
> 
> Thanks.