Skip to contentSkip to conversation

deadlock tearing down a bridged interface

BUG, NET In review Dave Chinner 4 participants 10 messages Jul 18, 2008 – Aug 4, 2008

Subsystems (3)
Networking Network drivers Library code
lore
Share & tools
lore

Dave Chinner

author
#0 lore raw

Folks,

I just deadlocked networking on a 2.6.24 kernel. Basically I was trying to restart the bridge interface I use for UML sessions because it wasn't passing packets. This happens occasionally when I leave a UML session too long in gdb, so I bounced the bridge to get it working again.

Unfortunately, a UML session (2.6.25-rc9) was halting at the same time, and instead of giving me a 'device busy' error, the UML session stopped at:

Asking all remaining processes to terminate...done. All processes ended within 1 seconds....done. Saving random seed...done.
Deconfiguring network interfaces...

It appears to be stuck closing the tunnel interface it was using:

uml-linux D ffffffff804297c0 0 7437 7428
ffff8100798efe70 0000000000000086 0000000000000000 ffff81005348b400 ffff81003d820800 ffff81007df9a800 ffff81003d820a50 0000000100000000 00000000ffffffff ffff81003d820800 0000000000000000 0000000000000000

Call Trace:
 [<ffffffff8024a85d>] lock_hrtimer_base+0x1b/0x3c
 [<ffffffff804145f2>] __mutex_lock_slowpath+0x68/0xa3
 [<ffffffff80414458>] mutex_lock+0xa/0xb
 [<ffffffff803adcfe>] netdev_run_todo+0x14/0x21a
 [<ffffffff885901dd>] :tun:tun_chr_close+0x70/0x76
 [<ffffffff802990c7>] __fput+0xa1/0x16c
 [<ffffffff802968f3>] filp_close+0x5d/0x65
 [<ffffffff80297aca>] sys_close+0x8d/0xca
 [<ffffffff8020be2e>] system_call+0x7e/0x83

At the same time that this command was running:

brctl delbr br0

dmesg showed:

unregister_netdevice: waiting for br0 to become free. Usage count = 7
unregister_netdevice: waiting for br0 to become free. Usage count = 7
unregister_netdevice: waiting for br0 to become free. Usage count = 7
unregister_netdevice: waiting for br0 to become free. Usage count = 7
unregister_netdevice: waiting for br0 to become free. Usage count = 7
unregister_netdevice: waiting for br0 to become free. Usage count = 7
....

brctl is stuck here:

brctl D ffffffff804297c0 0 8457 8448
ffff81004d8a3d98 0000000000000082 0000000000000286 ffffffff8023e0ea ffff81000f941800 ffff81007d531000 ffff81000f941a50 000000014d8a3da8 000000012f98b3a2 000000012f98bbea 0000000000000286 ffffffff8023e280

Call Trace:
 [<ffffffff8023e0ea>] lock_timer_base+0x26/0x4c
 [<ffffffff8023e280>] __mod_timer+0xc3/0xd1
 [<ffffffff8041423d>] schedule_timeout+0x8a/0xad
 [<ffffffff8023ddde>] process_timeout+0x0/0x5
 [<ffffffff80414238>] schedule_timeout+0x85/0xad
 [<ffffffff8023e2a2>] msleep+0x14/0x1e
 [<ffffffff803ade06>] netdev_run_todo+0x11c/0x21a
 [<ffffffff88580599>] :bridge:br_del_bridge+0x4c/0x50
 [<ffffffff88581281>] :bridge:br_ioctl_deviceless_stub+0x177/0x1e2
 [<ffffffff80223598>] do_page_fault+0x352/0x6ca
 [<ffffffff803a0ab6>] sock_ioctl+0x12c/0x200
 [<ffffffff802a3849>] do_ioctl+0x21/0x6b
 [<ffffffff802a3ad6>] vfs_ioctl+0x243/0x25c
 [<ffffffff80296861>] fd_install+0x25/0x5a
 [<ffffffff802a3b40>] sys_ioctl+0x51/0x71
 [<ffffffff8020be2e>] system_call+0x7e/0x83

This is as much as I could get before sufficient stuff locked up and I had to reboot.

Cheers,

Dave.

Signature · 2 lines
Dave Chinner
[email protected]
#1 lore raw
Quoted 8 lines · Dave Chinner

Folks,

I just deadlocked networking on a 2.6.24 kernel. Basically I was trying to restart the bridge interface I use for UML sessions because it wasn't passing packets. This happens occasionally when I leave a UML session too long in gdb, so I bounced the bridge to get it working again.

We have been chasing a refcount bug in 2.6.25 that only happens when IPv6 module is loaded. If you are not actually using ipv6, try removing it's module from your /lib/modules/* directory and see if that fixes your problem.

Thanks,
Ben

Signature · 1 line
Ben Greear <[email protected]> Candela Technologies Inc  http://www.candelatech.com
author
#2 lore raw
Quoted 11 lines · Ben Greear
Quoted 8 lines · Dave Chinner

Folks,

I just deadlocked networking on a 2.6.24 kernel. Basically I was trying to restart the bridge interface I use for UML sessions because it wasn't passing packets. This happens occasionally when I leave a UML session too long in gdb, so I bounced the bridge to get it working again.

We have been chasing a refcount bug in 2.6.25 that only happens when IPv6 module is loaded.

Which causes what problem? The deadlock I reported or the bridge occasionally hanging? Is that a problem in 2.6.24?

The deadlock is the one I'm concerned about - it appears that netdev_run_todo() can only wait on a single interface at a time, so if we are tearing down two interfaces concurrently where one has a reference on the other a deadlock is just waiting to happen...

Quoted 3 lines

If you are not actually using ipv6, try removing it's module from your /lib/modules/* directory and see if that fixes your problem.

I'll try it, but a) it's not 2.6.25 and b) I don't tend to triage problems on my main workstation so I'm not likely to try to reproduce this deadlock unless absolutely necessary.

Cheers,

Dave.

Signature · 2 lines
Dave Chinner
[email protected]
#3 lore raw
Quoted 17 lines · Dave Chinner
Quoted 11 lines · Ben Greear
Quoted 9 lines · Dave Chinner

Folks,

I just deadlocked networking on a 2.6.24 kernel. Basically I was trying to restart the bridge interface I use for UML sessions because it wasn't passing packets. This happens occasionally when I leave a UML session too long in gdb, so I bounced the bridge to get it working again.

Quoted 3 lines

We have been chasing a refcount bug in 2.6.25 that only happens when IPv6 module is loaded.

Quoted 8 lines

Which causes what problem? The deadlock I reported or the bridge occasionally hanging? Is that a problem in 2.6.24?

The deadlock is the one I'm concerned about - it appears that netdev_run_todo() can only wait on a single interface at a time, so if we are tearing down two interfaces concurrently where one has a reference on the other a deadlock is just waiting to happen...

Our problem is the refcount hang while trying to remove a netdevice. It appears to be an ipv6 related leakage of some sort, and not directly related to bridges.

Thanks,
Ben

Signature · 1 line
Ben Greear <[email protected]> Candela Technologies Inc  http://www.candelatech.com
#4 lore raw

RFC 1/1 netdev: debugging option

This adds a debugging option for network devices. It could grow to add other uses, but for now just add some messages about device reference counting.

Signed-off-by Stephen Hemminger <[email protected]>
include/linux/netdevice.h +10 -0
@@ -1236,6 +1236,14 @@ extern int		netdev_budget;
 /* Called by rtnetlink.c:rtnl_unlock() */
 extern void netdev_run_todo(void);
 
+#ifdef CONFIG_DEBUG_NETDEV
+extern int netdev_debug;
+extern void __dev_hold(struct net_device *, const char *);
+extern void __dev_put(struct net_device *, const char *);
+
+#define dev_hold(dev)	__dev_hold(dev, __FUNCTION__)
+#define dev_put(dev)	__dev_put(dev, __FUNCTION__)
+#else
 /**
  *	dev_put - release reference to device
  *	@dev: network device

@@ -1257,6 +1265,8 @@ static inline void dev_hold(struct net_d
 {
 	atomic_inc(&dev->refcnt);
 }
+#endif
+
 
 /* Carrier loss detection, dial on demand. The functions netif_carrier_on
  * and _off may be called from IRQ context, but it is caller
lib/Kconfig.debug +7 -0
@@ -428,6 +428,13 @@ config DEBUG_KOBJECT
 	  If you say Y here, some extra kobject debugging messages will be sent
 	  to the syslog. 
 
+config DEBUG_NETDEV
+       bool "network device debugging"
+       depends on DEBUG_KERNEL
+       help
+	  This option enables extra checking on usage and reference counting
+	  of network devices.
+
 config DEBUG_HIGHMEM
 	bool "Highmem debugging"
 	depends on DEBUG_KERNEL && HIGHMEM
net/core/dev.c +24 -0
@@ -4091,6 +4091,30 @@ static void netdev_wait_allrefs(struct n
 	}
 }
 
+#ifdef CONFIG_DEBUG_NETDEV
+/* This is for debugging reference counting of devices */
+int netdev_debug __read_mostly;
+
+void __dev_hold(struct net_device *dev, const char *func)
+{
+	atomic_inc(&dev->refcnt);
+	if (unlikely(netdev_debug))
+		printk(KERN_DEBUG "%s: dev_hold %d %s\n",
+		       dev->name, atomic_read(&dev->refcnt), func);
+}
+EXPORT_SYMBOL(__dev_hold);
+
+void __dev_put(struct net_device *dev, const char *func)
+{
+	BUG_ON(atomic_read(&dev->refcnt) == 0);
+	if (unlikely(netdev_debug))
+		printk(KERN_DEBUG "%s: dev_put %d %s\n",
+		       dev->name, atomic_read(&dev->refcnt), func);
+	atomic_dec(&dev->refcnt);
+}
+EXPORT_SYMBOL(__dev_put);
+#endif
+
 /* The sequence is:
  *
  *	rtnl_lock();
net/core/sysctl_net_core.c +11 -0
@@ -140,6 +140,17 @@ static struct ctl_table net_core_table[]
 		.mode		= 0644,
 		.proc_handler	= &proc_dointvec
 	},
+#ifdef CONFIG_DEBUG_NETDEV
+	{
+		.ctl_name	= CTL_UNNUMBERED,
+		.procname	= "netdev_debug",
+		.data		= &netdev_debug,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dointvec
+	},
+
+#endif
 	{ .ctl_name = 0 }
 };
maintainer
#5 lore raw

Re: [RFC] netdev: debugging option

From: Stephen Hemminger <[email protected]>
Date: Sat, 19 Jul 2008 23:04:24 -0700

Quoted 4 lines

This adds a debugging option for network devices. It could grow to add other uses, but for now just add some messages about device reference counting.

Signed-off-by Stephen Hemminger <[email protected]>

I think this is useful but it could use some minor mods before we put it in.

For example, this thing will spam the logs in at least two common cases:

1) Lots of routing cache replacements

2) For older drivers using netif_rx() (and therefore, every current tunnel), every RX packet will trigger a log message

So we really need to add some kind of run time enable and also a filter of some sort, even if it's just on device.

#6 lore raw

Re: [RFC] netdev: debugging option

Quoted 11 lines · On Sun, 20 Jul 2008 00:05:09 -0700 (PDT) David Miller <[email protected]>…

From: Stephen Hemminger <[email protected]>
Date: Sat, 19 Jul 2008 23:04:24 -0700

Quoted 4 lines

This adds a debugging option for network devices. It could grow to add other uses, but for now just add some messages about device reference counting.

Signed-off-by Stephen Hemminger <[email protected]>

I think this is useful but it could use some minor mods before we put it in.

Quoted 7 lines

For example, this thing will spam the logs in at least two common cases:

1) Lots of routing cache replacements

2) For older drivers using netif_rx() (and therefore, every current tunnel), every RX packet will trigger a log message

Fixed by later patch.

Quoted 2 lines

So we really need to add some kind of run time enable and also a filter of some sort, even if it's just on device.

The sysctl in the patch is default off, so unless it is turned on, the log is quiet

maintainer
#7 lore raw

Re: [RFC] netdev: debugging option

From: Stephen Hemminger <[email protected]>
Date: Mon, 4 Aug 2008 09:37:42 -0700

Quoted 11 lines
Quoted 5 lines · On Sun, 20 Jul 2008 00:05:09 -0700 (PDT) David Miller <[email protected]>…

From: Stephen Hemminger <[email protected]>
Date: Sat, 19 Jul 2008 23:04:24 -0700

So we really need to add some kind of run time enable and also a filter of some sort, even if it's just on device.

The sysctl in the patch is default off, so unless it is turned on, the log is quiet

I get a feeling you think I can just apply your patch now.

You can't respond to my gripes more than a week later and expect the patch to still be in my inbox ready to apply. I delete the patch from my mailbox as soon as I have major issues with it.

If you think your reply means that the patch should be applied you need to resubmit it.

Thanks.

#8 lore raw

Re: [RFC] netdev: debugging option

Quoted 12 lines · On Mon, 04 Aug 2008 14:31:28 -0700 (PDT) David Miller <[email protected]>…

From: Stephen Hemminger <[email protected]>
Date: Mon, 4 Aug 2008 09:37:42 -0700

Quoted 9 lines
Quoted 5 lines · On Sun, 20 Jul 2008 00:05:09 -0700 (PDT) David Miller <[email protected]>…

From: Stephen Hemminger <[email protected]>
Date: Sat, 19 Jul 2008 23:04:24 -0700

So we really need to add some kind of run time enable and also a filter of some sort, even if it's just on device.

Quoted 9 lines
Quoted 2 lines

The sysctl in the patch is default off, so unless it is turned on, the log is quiet

I get a feeling you think I can just apply your patch now.

You can't respond to my gripes more than a week later and expect the patch to still be in my inbox ready to apply. I delete the patch from my mailbox as soon as I have major issues with it.

Okay, I prioritize my mail replies, and this was on the tickler file of (things to get back to when the smoke clears). Just didn't want to let it die.

#9 lore raw
In reply to Ben Greear

It looks something related icmp6_dst_alloc creating a reference (in rt6_info), but these entries are not being cleaned up. Possibly related to icmp6_dst_gc.

This is what happens if a bridge is created, then brought up. and then bridge module is attempted to be removed.

[  148.814733] br0: Dropping NETIF_F_UFO since no NETIF_F_HW_CSUM feature.
[  148.814944] br0: dev_hold 1 register_netdevice
[  148.814972] br0: dev_hold 2 neigh_parms_alloc
[  148.814976] br0: dev_hold 3 inetdev_init
[  148.815875] br0: dev_hold 4 neigh_parms_alloc
[  148.815880] br0: dev_hold 5 ipv6_add_dev
[  165.885715] br0: dev_hold 6 dev_get_by_index
[  165.886940] br0: dev_hold 7 dev_get_by_index
[  165.886947] br0: dev_put 7 free_fib_info
[  165.886952] br0: dev_hold 7 fib_check_nh
[  165.886986] br0: dev_hold 8 fib_check_nh
[  165.886991] br0: dev_put 8 free_fib_info
[  165.887006] br0: dev_hold 8 fib_check_nh
[  165.887011] br0: dev_put 8 free_fib_info
[  165.887026] br0: dev_hold 8 fib_check_nh
[  165.887030] br0: dev_put 8 free_fib_info
[  165.887043] br0: dev_hold 8 dev_get_by_index
[  165.887060] br0: dev_hold 9 dev_get_by_index
[  165.887084] br0: dev_hold 10 dev_get_by_index
[  165.887089] br0: dev_put 10 dst_destroy
[  165.888480] br0: dev_put 9 free_fib_info
[  165.888497] br0: dev_put 8 free_fib_info
[  165.889359] br0: dev_hold 8 dev_get_by_index
[  165.889378] br0: dev_hold 9 fib_check_nh
[  165.889394] br0: dev_hold 10 fib_check_nh
[  165.889399] br0: dev_put 10 free_fib_info
[  165.889412] br0: dev_hold 10 fib_check_nh
[  165.889417] br0: dev_put 10 free_fib_info
[  165.889432] br0: dev_hold 10 fib_check_nh
[  165.889437] br0: dev_put 10 free_fib_info
[  165.894973] br0: dev_hold 10 icmp6_dst_alloc
[  165.894983] br0: dev_hold 11 neigh_create
[  165.895005] br0: dev_hold 12 dev_get_by_index
[  165.895011] br0: dev_hold 13 __mkroute_output
[  165.895017] br0: dev_hold 14 neigh_create
[  165.895022] br0: dev_put 14 ip_route_output_slow
[  166.086518] br0: dev_hold 14 ip_dev_find
[  166.086524] br0: dev_put 14 ip_route_output_slow
[  166.086527] br0: dev_hold 14 dev_get_by_index
[  166.086530] br0: dev_hold 15 __mkroute_output
[  166.086536] br0: dev_hold 16 neigh_create
[  166.086539] br0: dev_put 16 ip_route_output_slow
[  166.086564] br0: dev_hold 16 netif_rx
[  166.086575] br0: dev_put 16 process_backlog
[  166.110517] br0: dev_hold 16 netif_rx
[  166.110528] br0: dev_put 16 process_backlog
[  166.342516] br0: dev_hold 16 netif_rx
[  166.342527] br0: dev_put 16 process_backlog
[  166.414459] br0: dev_hold 16 icmp6_dst_alloc
[  166.414465] br0: dev_hold 17 neigh_create
[  166.598525] br0: dev_hold 18 netif_rx
[  166.598537] br0: dev_put 18 process_backlog
[  166.798613] br0: dev_hold 18 netif_rx
[  166.798624] br0: dev_put 18 process_backlog
[  167.250500] br0: dev_hold 18 netif_rx
[  167.250511] br0: dev_put 18 process_backlog
[  167.414464] br0: dev_hold 18 icmp6_dst_alloc
[  167.414470] br0: dev_hold 19 neigh_create
[  167.610510] br0: dev_hold 20 netif_rx
[  167.610521] br0: dev_put 20 process_backlog
[  167.610656] br0: dev_hold 20 netif_rx
[  167.610664] br0: dev_put 20 process_backlog
[  167.866495] br0: dev_hold 20 netif_rx
[  167.866506] br0: dev_put 20 process_backlog
[  167.938575] br0: dev_hold 20 netif_rx
[  167.938586] br0: dev_put 20 process_backlog
[  168.118511] br0: dev_hold 20 netif_rx
[  168.118522] br0: dev_put 20 process_backlog
[  168.118662] br0: dev_hold 20 netif_rx
[  168.118670] br0: dev_put 20 process_backlog
[  168.322535] br0: dev_hold 20 netif_rx
[  168.322546] br0: dev_put 20 process_backlog
[  169.390505] br0: dev_hold 20 netif_rx
[  169.390516] br0: dev_put 20 process_backlog
[  169.462506] br0: dev_hold 20 netif_rx
[  169.462517] br0: dev_put 20 process_backlog
[  170.078564] br0: dev_hold 20 netif_rx
[  170.078576] br0: dev_put 20 process_backlog
[  171.414377] br0: dev_hold 20 icmp6_dst_alloc
[  171.602486] br0: dev_hold 21 netif_rx
[  171.602499] br0: dev_put 21 process_backlog
[  172.122369] br0: dev_hold 21 icmp6_dst_alloc
[  175.414312] br0: dev_hold 22 icmp6_dst_alloc
[  176.414294] br0: no IPv6 routers present
[  179.754147] br0: dev_hold 23 ip_dev_find
[  179.754153] br0: dev_put 23 ip_route_output_slow
[  179.754157] br0: dev_hold 23 ip_route_output_slow
[  179.754162] br0: dev_hold 24 __mkroute_output
[  179.754168] br0: dev_hold 25 neigh_create
[  179.754174] br0: dev_put 25 ip_route_output_slow
[  179.754202] br0: dev_hold 25 netif_rx
[  179.754214] br0: dev_put 25 process_backlog
[  179.754239] br0: dev_hold 25 netif_rx
[  179.754248] br0: dev_put 25 process_backlog
[  179.754268] br0: dev_hold 25 netif_rx
[  179.754277] br0: dev_put 25 process_backlog
[  179.754297] br0: dev_hold 25 netif_rx
[  179.754306] br0: dev_put 25 process_backlog
[  179.754323] br0: dev_hold 25 netif_rx
[  179.754331] br0: dev_put 25 process_backlog
[  179.754707] br0: dev_hold 25 netif_rx
[  179.754716] br0: dev_put 25 process_backlog
[  181.754187] br0: dev_hold 25 netif_rx
[  181.754195] br0: dev_put 25 process_backlog
[  181.754209] br0: dev_hold 25 netif_rx
[  181.754216] br0: dev_put 25 process_backlog
[  181.754230] br0: dev_hold 25 netif_rx
[  181.754238] br0: dev_put 25 process_backlog
[  181.754252] br0: dev_hold 25 netif_rx
[  181.754260] br0: dev_put 25 process_backlog
[  181.754273] br0: dev_hold 25 netif_rx
[  181.754280] br0: dev_put 25 process_backlog
[  181.754458] br0: dev_hold 25 netif_rx
[  181.754467] br0: dev_put 25 process_backlog
[  181.754481] br0: dev_hold 25 netif_rx
[  181.754489] br0: dev_put 25 process_backlog
[  181.754503] br0: dev_hold 25 netif_rx
[  181.754510] br0: dev_put 25 process_backlog
[  181.754524] br0: dev_hold 25 netif_rx
[  181.754532] br0: dev_put 25 process_backlog
[  181.754546] br0: dev_hold 25 netif_rx
[  181.754554] br0: dev_put 25 process_backlog
[  183.754140] br0: dev_hold 25 netif_rx
[  183.754149] br0: dev_put 25 process_backlog
[  183.754163] br0: dev_hold 25 netif_rx
[  183.754172] br0: dev_put 25 process_backlog
[  183.754185] br0: dev_hold 25 netif_rx
[  183.754193] br0: dev_put 25 process_backlog
[  183.754206] br0: dev_hold 25 netif_rx
[  183.754214] br0: dev_put 25 process_backlog
[  183.754227] br0: dev_hold 25 netif_rx
[  183.754235] br0: dev_put 25 process_backlog
[  188.854636] br0: dev_put 24 free_fib_info
[  188.855481] br0: dev_put 23 dst_destroy
[  188.855547] br0: dev_put 22 dst_destroy
[  188.855610] br0: dev_put 21 dst_destroy
[  188.855675] br0: dev_put 20 neigh_destroy
[  188.855739] br0: dev_put 19 dst_destroy
[  188.855803] br0: dev_put 18 neigh_destroy
[  188.855866] br0: dev_put 17 dst_destroy
[  188.855931] br0: dev_put 16 neigh_destroy
[  188.855994] br0: dev_put 15 dst_destroy
[  188.856075] br0: dev_put 14 dst_destroy
[  188.856145] br0: dev_put 13 dst_destroy
[  188.865683] br0: dev_put 12 neigh_destroy
[  188.865750] br0: dev_put 11 dst_destroy
[  188.865813] br0: dev_put 10 neigh_destroy
[  188.865876] br0: dev_put 9 dst_destroy
[  188.866002] br0: dev_put 8 neigh_destroy
[  188.866065] br0: dev_put 7 dst_destroy
[  243.751561] br0: dev_hold 7 ip_dev_find
[  243.751564] br0: dev_put 7 ip_route_output_slow