Re: unregister_netdevice: waiting for DEV to become free (2)

[Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>]

On 2018/08/20 21:55, Julian Anastasov wrote:
> 	Well, only IPVS and tun in the game? But IPVS does not
> take any dev references for sync threads. Can it be a problem
> in tun? For example, a side effects from dst_cache_reset?
> May be dst_release is called too late? Here is what should happen
> on unregistration:
> 
> - NETDEV_UNREGISTER event: rt_flush_dev changes dst->dev with lo
> but dst is not released
> 
> - ndo_uninit/ip_tunnel_uninit: dst_cache_reset is called which
> does nothing!?! May be dst_release call is needed here.
> 
> - no more references are expected here ...
> 
> - netdev_run_todo -> netdev_wait_allrefs: loop here due to refcnt!=0
> 
> - dev->priv_destructor (ip_tunnel_dev_free) calls dst_cache_destroy
> where dst_release is used but it is not reached because we loop in
> netdev_wait_allrefs above
> 
> - dst_cache_destroy: really call dst_release
> 
> 	In fact, after calling rt_flush_dev and replacing the
> dst->dev we should reach dev->priv_destructor (ip_tunnel_dev_free)
> for tun device where dst_release for lo should be called. But may be 
> something prevents it, exit batching?

I traced using debug printk() patch shown below.

----------------------------------------
diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 26f69cf763f4..25f7acacf457 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -3726,6 +3726,11 @@ void netdev_run_todo(void);
  */
 static inline void dev_put(struct net_device *dev)
 {
+	if (!strcmp(dev->name, "lo")) {
+		int count = netdev_refcnt_read(dev);
+		printk("dev_put(%p): %u->%u\n", dev, count, count - 1);
+		dump_stack();
+	}
 	this_cpu_dec(*dev->pcpu_refcnt);
 }
 
@@ -3737,6 +3742,11 @@ static inline void dev_put(struct net_device *dev)
  */
 static inline void dev_hold(struct net_device *dev)
 {
+	if (!strcmp(dev->name, "lo")) {
+		int count = netdev_refcnt_read(dev);
+		printk("dev_hold(%p): %u->%u\n", dev, count, count + 1);
+		dump_stack();
+	}
 	this_cpu_inc(*dev->pcpu_refcnt);
 }
 
diff --git a/net/core/dev.c b/net/core/dev.c
index fdcff29df915..53ff4385c8f7 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -8897,9 +8897,9 @@ static void netdev_wait_allrefs(struct net_device *dev)
 
 		refcnt = netdev_refcnt_read(dev);
 
-		if (time_after(jiffies, warning_time + 10 * HZ)) {
-			pr_emerg("unregister_netdevice: waiting for %s to become free. Usage count = %d\n",
-				 dev->name, refcnt);
+		if (time_after(jiffies, warning_time + HZ)) {
+			pr_emerg("unregister_netdevice: waiting for %s to become free. Usage count = %d%s (%p)\n",
+				 dev->name, refcnt, netdev_reg_state(dev), dev);
 			warning_time = jiffies;
 		}
 	}
diff --git a/net/ipv4/route.c b/net/ipv4/route.c
index a5da63e5faa2..4c5baca105ed 100644
--- a/net/ipv4/route.c
+++ b/net/ipv4/route.c
@@ -1503,6 +1503,7 @@ void rt_flush_dev(struct net_device *dev)
 		list_for_each_entry(rt, &ul->head, rt_uncached) {
 			if (rt->dst.dev != dev)
 				continue;
+			printk("rt_flush_dev(%p)->(%p)\n", dev, net->loopback_dev);
 			rt->dst.dev = net->loopback_dev;
 			dev_hold(rt->dst.dev);
 			dev_put(dev);
@@ -2560,6 +2561,7 @@ struct dst_entry *ipv4_blackhole_route(struct net *net, struct dst_entry *dst_or
 		new->input = dst_discard;
 		new->output = dst_discard_out;
 
+		printk("ipv4_blackhole_route(%p)->(%p)\n", new->dev, net->loopback_dev);
 		new->dev = net->loopback_dev;
 		if (new->dev)
 			dev_hold(new->dev);
----------------------------------------

When a new loopback device in a new network namespace is created using unshare(),
nothing is wrong.

[   60.873014][ T7306] dev_hold(00000000d9f4ea20): 0->1
[   60.873019][ T7306] CPU: 4 PID: 7306 Comm: a.out Not tainted 5.1.0-rc5+ #177
[   60.873021][ T7306] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   60.873022][ T7306] Call Trace:
[   60.873031][ T7306]  dump_stack+0xaa/0xd8
[   60.873037][ T7306]  net_rx_queue_update_kobjects+0x1f5/0x200
[   60.873042][ T7306]  netdev_register_kobject+0xf8/0x1a0
[   60.873047][ T7306]  register_netdevice+0x4cc/0x650
[   60.873052][ T7306]  register_netdev+0x23/0x40
[   60.873056][ T7306]  loopback_net_init+0x50/0xc0
[   60.873059][ T7306]  ? loopback_dev_init+0xa0/0xa0
[   60.873064][ T7306]  ops_init+0x4f/0x140
[   60.873068][ T7306]  setup_net+0xe7/0x250
[   60.873072][ T7306]  copy_net_ns+0xee/0x1e0
[   60.873077][ T7306]  create_new_namespaces+0x141/0x2a0
[   60.873081][ T7306]  unshare_nsproxy_namespaces+0x7e/0xf0
[   60.873086][ T7306]  ksys_unshare+0x268/0x4b0
[   60.873090][ T7306]  __x64_sys_unshare+0x16/0x20
[   60.873095][ T7306]  do_syscall_64+0x7c/0x180
[   60.873099][ T7306]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

But when some device in a network namespace calls rt_flush_dev(),
it gets a usage count on loopback device in that network namespace.

[   71.388104][ T7620] rt_flush_dev(00000000cd35e96a)->(00000000d9f4ea20)
[   71.391757][ T7620] dev_hold(00000000d9f4ea20): 7->8
[   71.394725][ T7620] CPU: 4 PID: 7620 Comm: a.out Not tainted 5.1.0-rc5+ #177
[   71.398094][ T7620] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   71.403711][ T7620] Call Trace:
[   71.405912][ T7620]  dump_stack+0xaa/0xd8
[   71.408252][ T7620]  rt_flush_dev+0x177/0x1b0
[   71.410802][ T7620]  fib_netdev_event+0x150/0x1b0
[   71.413270][ T7620]  notifier_call_chain+0x47/0xd0
[   71.415849][ T7620]  raw_notifier_call_chain+0x2d/0x40
[   71.418491][ T7620]  ? tun_show_group+0x90/0x90
[   71.421108][ T7620]  call_netdevice_notifiers_info+0x32/0x70
[   71.423854][ T7620]  rollback_registered_many+0x421/0x680
[   71.426583][ T7620]  rollback_registered+0x68/0xb0
[   71.429244][ T7620]  unregister_netdevice_queue+0xa5/0x100
[   71.432191][ T7620]  __tun_detach+0x576/0x590
[   71.435533][ T7620]  tun_chr_close+0x41/0x80
[   71.437957][ T7620]  ? __tun_detach+0x590/0x590
[   71.440500][ T7620]  __fput+0xeb/0x2d0
[   71.442816][ T7620]  ____fput+0x15/0x20
[   71.445090][ T7620]  task_work_run+0xa9/0xd0
[   71.447467][ T7620]  do_exit+0x37a/0xf40
[   71.449623][ T7620]  do_group_exit+0x57/0xe0
[   71.451826][ T7620]  get_signal+0x114/0x950
[   71.453989][ T7620]  do_signal+0x2f/0x700
[   71.456126][ T7620]  ? handle_mm_fault+0x1a8/0x360
[   71.458323][ T7620]  ? __x64_sys_futex+0x179/0x210
[   71.460620][ T7620]  exit_to_usermode_loop+0x159/0x180
[   71.462956][ T7620]  do_syscall_64+0x15d/0x180
[   71.465110][ T7620]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

The usage count printed by "unregister_netdevice: waiting for lo to become free."
seems to match number of rt_flush_dev() traces shown above. (Complete log is at
http://I-love.SAKURA.ne.jp/tmp/serial-20190415.txt.xz .)

Although netdev_wait_allrefs() is periodically calling
call_netdevice_notifiers(NETDEV_UNREGISTER, dev) in order to try to drop
the usgae count,

	list_for_each_entry(rt, &ul->head, rt_uncached) {
		if (rt->dst.dev != dev)
			continue;
		rt->dst.dev = net->loopback_dev;
		dev_hold(rt->dst.dev);
		dev_put(dev);
	}

in rt_flush_dev() becomes a no-op because dev == net->loopback_dev and
therefore cannot drop the usage count forever. That is, netdev_wait_allrefs()
on a loopback device cannot make forward progress.

[   95.502947][ T4478] unregister_netdevice: waiting for lo to become free. Usage count = 28 (unregistered) (00000000d9f4ea20)
[   95.509108][ T4478] rt_flush_dev(00000000d9f4ea20)->(00000000d9f4ea20)
[   95.512598][ T4478] dev_hold(00000000d9f4ea20): 28->29
[   95.517241][ T4478] CPU: 5 PID: 4478 Comm: kworker/u128:28 Not tainted 5.1.0-rc5+ #177
[   95.522984][ T4478] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   95.532898][ T4478] Workqueue: netns cleanup_net
[   95.537134][ T4478] Call Trace:
[   95.539751][ T4478]  dump_stack+0xaa/0xd8
[   95.543642][ T4478]  rt_flush_dev+0x177/0x1b0
[   95.546835][ T4478]  fib_netdev_event+0x150/0x1b0
[   95.550609][ T4478]  notifier_call_chain+0x47/0xd0
[   95.557990][ T4478]  raw_notifier_call_chain+0x2d/0x40
[   95.563900][ T4478]  call_netdevice_notifiers_info+0x32/0x70
[   95.568655][ T4478]  netdev_run_todo+0x197/0x410
[   95.572554][ T4478]  rtnl_unlock+0xe/0x10
[   95.576836][ T4478]  default_device_exit_batch+0x1ab/0x1d0
[   95.579650][ T4478]  ? do_wait_intr_irq+0xb0/0xb0
[   95.582236][ T4478]  ? unregister_netdevice_many+0x30/0x30
[   95.584766][ T4478]  ? dev_change_net_namespace+0x4e0/0x4e0
[   95.587397][ T4478]  ops_exit_list.isra.6+0x75/0x90
[   95.590063][ T4478]  cleanup_net+0x20d/0x380
[   95.592373][ T4478]  process_one_work+0x202/0x4f0
[   95.595017][ T4478]  worker_thread+0x3c/0x4b0
[   95.597520][ T4478]  kthread+0x139/0x160
[   95.599822][ T4478]  ? process_one_work+0x4f0/0x4f0
[   95.602351][ T4478]  ? kthread_destroy_worker+0x70/0x70
[   95.604901][ T4478]  ret_from_fork+0x35/0x40
[   95.607249][ T4478] dev_put(00000000d9f4ea20): 29->28
[   95.609935][ T4478] CPU: 5 PID: 4478 Comm: kworker/u128:28 Not tainted 5.1.0-rc5+ #177
[   95.613282][ T4478] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   95.618699][ T4478] Workqueue: netns cleanup_net
[   95.621345][ T4478] Call Trace:
[   95.623381][ T4478]  dump_stack+0xaa/0xd8
[   95.625787][ T4478]  rt_flush_dev+0x19f/0x1b0
[   95.628284][ T4478]  fib_netdev_event+0x150/0x1b0
[   95.630827][ T4478]  notifier_call_chain+0x47/0xd0
[   95.633153][ T4478]  raw_notifier_call_chain+0x2d/0x40
[   95.635702][ T4478]  call_netdevice_notifiers_info+0x32/0x70
[   95.638372][ T4478]  netdev_run_todo+0x197/0x410
[   95.640641][ T4478]  rtnl_unlock+0xe/0x10
[   95.642828][ T4478]  default_device_exit_batch+0x1ab/0x1d0
[   95.645230][ T4478]  ? do_wait_intr_irq+0xb0/0xb0
[   95.647613][ T4478]  ? unregister_netdevice_many+0x30/0x30
[   95.650148][ T4478]  ? dev_change_net_namespace+0x4e0/0x4e0
[   95.652594][ T4478]  ops_exit_list.isra.6+0x75/0x90
[   95.654975][ T4478]  cleanup_net+0x20d/0x380
[   95.657140][ T4478]  process_one_work+0x202/0x4f0
[   95.659829][ T4478]  worker_thread+0x3c/0x4b0
[   95.662098][ T4478]  kthread+0x139/0x160
[   95.664119][ T4478]  ? process_one_work+0x4f0/0x4f0
[   95.666467][ T4478]  ? kthread_destroy_worker+0x70/0x70
[   95.668916][ T4478]  ret_from_fork+0x35/0x40

If we do something like

 	list_for_each_entry(rt, &ul->head, rt_uncached) {
 		if (rt->dst.dev != dev)
 			continue;
-                       rt->dst.dev = net->loopback_dev;
+                       if (dev == net->loopback_dev)
+                               rt->dst.dev = init_net.loopback_dev;
+                       else
+                               rt->dst.dev = net->loopback_dev;
 		dev_hold(rt->dst.dev);
 		dev_put(dev);
 	}

at rt_flush_dev(), I guess that this problem will go away. I don't
know which device should be used instead of init_net.loopback_dev .
But I guess that we need to somehow avoid getting usage count on
a loopback device (by e.g. using a dummy device which is not under
unregistration procedure) when we want to unregister that loopback
device.