loopback device reference count leakage

5 messages, 2 authors, 2017-01-27 · open the first message on its own page

loopback device reference count leakage

From: Kaiwen Xu <hidden>
Date: 2017-01-24 05:22:20 

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

From: Cong Wang <hidden>
Date: 2017-01-25 19:50:52 

Hello,

On Mon, Jan 23, 2017 at 9:17 PM, Kaiwen Xu [off-list ref] 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!

Re: loopback device reference count leakage

From: Kaiwen Xu <hidden>
Date: 2017-01-26 22:57:58 

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 [off-list ref] wrote:
quoted
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. ;)
quoted
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().
quoted
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!
quoted hunk
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

    

      From: Cong Wang <hidden>

      Date: 2017-01-27 01:03:13 
    

  

  
On Thu, Jan 26, 2017 at 2:51 PM, Kaiwen Xu [off-list ref] 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

    

      From: Kaiwen Xu <hidden>

      Date: 2017-01-27 03:22:56 
    

  

  
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




    
  

  
    

      

        Keyboard shortcuts
      

      

        
          
hback out one level

          
jnext message in thread

          
kprevious message in thread

          
ldrill in

          
Escclose help / fold thread tree

          
?toggle this help