[BUG, NET] deadlock tearing down a bridged interface

[BUG, NET] deadlock tearing down a bridged interface

[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.

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.
-- 
Dave Chinner
david@fromorbit.com

Re: [BUG, NET] deadlock tearing down a bridged interface

[Ben Greear]

Dave Chinner wrote:
> 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

-- 
Ben Greear <greearb@candelatech.com> 
Candela Technologies Inc  http://www.candelatech.com

Re: [BUG, NET] deadlock tearing down a bridged interface

[Dave Chinner]

On Fri, Jul 18, 2008 at 08:44:58AM -0700, Ben Greear wrote:
> Dave Chinner wrote:
>> 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...

> 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.
-- 
Dave Chinner
david@fromorbit.com

Re: [BUG, NET] deadlock tearing down a bridged interface

[Ben Greear]

Dave Chinner wrote:
> On Fri, Jul 18, 2008 at 08:44:58AM -0700, Ben Greear wrote:
>   
>> Dave Chinner wrote:
>>     
>>> 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...
>   
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

-- 
Ben Greear <greearb@candelatech.com> 
Candela Technologies Inc  http://www.candelatech.com

[RFC] netdev: debugging option

[Stephen Hemminger]

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 <shemminger@vyatta.com>

--- a/include/linux/netdevice.h	2008-07-19 15:04:59.000000000 -0700
+++ b/include/linux/netdevice.h	2008-07-19 22:09:21.000000000 -0700
@@ -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
--- a/lib/Kconfig.debug	2008-07-19 15:03:14.000000000 -0700
+++ b/lib/Kconfig.debug	2008-07-19 15:04:50.000000000 -0700
@@ -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
--- a/net/core/dev.c	2008-07-19 15:12:06.000000000 -0700
+++ b/net/core/dev.c	2008-07-19 22:12:06.000000000 -0700
@@ -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();
--- a/net/core/sysctl_net_core.c	2008-07-19 15:12:21.000000000 -0700
+++ b/net/core/sysctl_net_core.c	2008-07-19 15:29:53.000000000 -0700
@@ -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 }
 };
 

Re: [RFC] netdev: debugging option

[David Miller]

From: Stephen Hemminger <shemminger@vyatta.com>
Date: Sat, 19 Jul 2008 23:04:24 -0700

> 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 <shemminger@vyatta.com>

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.

Re: [RFC] netdev: debugging option

[Stephen Hemminger]

On Sun, 20 Jul 2008 00:05:09 -0700 (PDT)
David Miller <davem@davemloft.net> wrote:

> From: Stephen Hemminger <shemminger@vyatta.com>
> Date: Sat, 19 Jul 2008 23:04:24 -0700
> 
> > 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 <shemminger@vyatta.com>
> 
> 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

Fixed by later patch.

> 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

Re: [RFC] netdev: debugging option

[David Miller]

From: Stephen Hemminger <shemminger@vyatta.com>
Date: Mon, 4 Aug 2008 09:37:42 -0700

> On Sun, 20 Jul 2008 00:05:09 -0700 (PDT)
> David Miller <davem@davemloft.net> wrote:
> 
> > From: Stephen Hemminger <shemminger@vyatta.com>
> > 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.

Re: [RFC] netdev: debugging option

[Stephen Hemminger]

On Mon, 04 Aug 2008 14:31:28 -0700 (PDT)
David Miller <davem@davemloft.net> wrote:

> From: Stephen Hemminger <shemminger@vyatta.com>
> Date: Mon, 4 Aug 2008 09:37:42 -0700
> 
> > On Sun, 20 Jul 2008 00:05:09 -0700 (PDT)
> > David Miller <davem@davemloft.net> wrote:
> > 
> > > From: Stephen Hemminger <shemminger@vyatta.com>
> > > 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.
> 

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.

Re: [BUG, NET] deadlock tearing down a bridged interface

[Stephen Hemminger]

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