[RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Vegard Nossum]

>From b96d44099cc28d084bc1e86aba45465505362298 Mon Sep 17 00:00:00 2001
From: Vegard Nossum <vegard.nossum@gmail.com>
Date: Wed, 13 Aug 2008 11:52:21 +0200
Subject: [PATCH] netconsole: avoid deadlock on printk from driver code

I encountered a hard-to-debug deadlock when I pulled out the plug of my
RealTek 8139 which was also running netconsole: The driver wants to print
a "link down" message. However, this triggers netconsole, which wants to
print the message using the same device. Here is a backtrace:

 [<c05916b6>] _spin_lock_irqsave+0x76/0x90
 [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
 [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
 [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
 [<c037c70c>] write_msg+0x8c/0xc0
 [<c0135883>] __call_console_drivers+0x53/0x60
 [<c01358db>] _call_console_drivers+0x4b/0x90
 [<c0135a25>] release_console_sem+0xc5/0x1f0
 [<c0135f0b>] vprintk+0x1ab/0x3e0
 [<c013615b>] printk+0x1b/0x20
 [<c0349736>] mii_check_media+0x196/0x1e0
 [<c03597f4>] rtl_check_media+0x24/0x30
 [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
 [<c01716d8>] handle_IRQ_event+0x28/0x70
 [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
 [<c0107128>] do_IRQ+0x48/0xa0

The least invasive fix is to detect that we're trying to re-enter the
driver code. We provide a netdev_busy() function which can be used to
determine whether a deadlock can occur if we try to transmit another
packet.

Note that this may lead to lost messages if the driver is active on
another CPU while we try to use the same device for netconsole. It would
probably be best to set a "lost messages" flag in this case and add it
to the stream when the device becomes ready again.

The only extra overhead in non-netconsole code paths is the fact that we
need another callback in struct net_device. However, all drivers must be
checked for the possibility of a deadlock and implement the ->busy()
callback as necessary.

(Patch is untested.)

Cc: Alexey Dobriyan <adobriyan@gmail.com>
Cc: Jeff Garzik <jgarzik@pobox.com>
Signed-off-by: Vegard Nossum <vegard.nossum@gmail.com>
---
 drivers/net/8139too.c     |    7 +++++++
 drivers/net/netconsole.c  |    5 ++++-
 include/linux/netdevice.h |   19 +++++++++++++++++++
 3 files changed, 30 insertions(+), 1 deletions(-)

diff --git a/drivers/net/8139too.c b/drivers/net/8139too.c
index 8a5b0d2..c1af142 100644
--- a/drivers/net/8139too.c
+++ b/drivers/net/8139too.c
@@ -636,6 +636,7 @@ static void rtl8139_tx_timeout (struct net_device *dev);
 static void rtl8139_init_ring (struct net_device *dev);
 static int rtl8139_start_xmit (struct sk_buff *skb,
 			       struct net_device *dev);
+static bool rtl8139_busy (struct net_device *dev);
 #ifdef CONFIG_NET_POLL_CONTROLLER
 static void rtl8139_poll_controller(struct net_device *dev);
 #endif
@@ -979,6 +980,7 @@ static int __devinit rtl8139_init_one (struct pci_dev *pdev,
 	/* The Rtl8139-specific entries in the device structure. */
 	dev->open = rtl8139_open;
 	dev->hard_start_xmit = rtl8139_start_xmit;
+	dev->busy = rtl8139_busy;
 	netif_napi_add(dev, &tp->napi, rtl8139_poll, 64);
 	dev->stop = rtl8139_close;
 	dev->get_stats = rtl8139_get_stats;
@@ -1741,6 +1743,11 @@ static int rtl8139_start_xmit (struct sk_buff *skb, struct net_device *dev)
 	return 0;
 }
 
+static bool rtl8139_busy (struct net_device *dev)
+{
+	struct rtl8139_private *tp = netdev_priv(dev);
+	return spin_is_locked(&tp->lock);
+}
 
 static void rtl8139_tx_interrupt (struct net_device *dev,
 				  struct rtl8139_private *tp,
diff --git a/drivers/net/netconsole.c b/drivers/net/netconsole.c
index 9681618..b06d7ef 100644
--- a/drivers/net/netconsole.c
+++ b/drivers/net/netconsole.c
@@ -707,8 +707,11 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 
 	spin_lock_irqsave(&target_list_lock, flags);
 	list_for_each_entry(nt, &target_list, list) {
+		struct net_device *dev;
+
 		netconsole_target_get(nt);
-		if (nt->enabled && netif_running(nt->np.dev)) {
+		dev = nt->np.dev;
+		if (nt->enabled && netif_running(dev) && !netdev_busy(dev)) {
 			/*
 			 * We nest this inside the for-each-target loop above
 			 * so that we're able to get as much logging out to
diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 488c56e..8865a17 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -642,6 +642,10 @@ struct net_device
 	void			*priv;	/* pointer to private data	*/
 	int			(*hard_start_xmit) (struct sk_buff *skb,
 						    struct net_device *dev);
+
+	/* Don't use directly; see netdev_busy() below. */
+	bool			(*busy) (struct net_device *dev);
+
 	/* These may be needed for future network-power-down code. */
 	unsigned long		trans_start;	/* Time (in jiffies) of last Tx	*/
 
@@ -809,6 +813,21 @@ static inline void *netdev_priv(const struct net_device *dev)
 			      & ~NETDEV_ALIGN_CONST);
 }
 
+/**
+ *	netdev_busy -r eturns false if ->hard_start_xmit() may deadlock
+ *	@dev: network device
+ *
+ * More specifically, the driver callback must return true if any of the
+ * locks that are needed for ->hard_start_xmit() are locked. This may look
+ * like a race (because somebody else can take the locks in-between), but
+ * that's fine; we only want to avoid the situation where we can deadlock
+ * against ourselves.
+ */
+static inline bool netdev_busy(struct net_device *dev)
+{
+	return dev->busy && dev->busy(dev);
+}
+
 /* Set the sysfs physical device reference for the network logical device
  * if set prior to registration will cause a symlink during initialization.
  */
-- 
1.5.5.1

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Alexey Dobriyan]

On Wed, Aug 13, 2008 at 11:53:24AM +0200, Vegard Nossum wrote:
> I encountered a hard-to-debug deadlock when I pulled out the plug of my
> RealTek 8139 which was also running netconsole: The driver wants to print
> a "link down" message. However, this triggers netconsole, which wants to
> print the message using the same device. Here is a backtrace:
> 
>  [<c05916b6>] _spin_lock_irqsave+0x76/0x90
>  [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
>  [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
>  [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
>  [<c037c70c>] write_msg+0x8c/0xc0
>  [<c0135883>] __call_console_drivers+0x53/0x60
>  [<c01358db>] _call_console_drivers+0x4b/0x90
>  [<c0135a25>] release_console_sem+0xc5/0x1f0
>  [<c0135f0b>] vprintk+0x1ab/0x3e0
>  [<c013615b>] printk+0x1b/0x20
>  [<c0349736>] mii_check_media+0x196/0x1e0
>  [<c03597f4>] rtl_check_media+0x24/0x30
>  [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
>  [<c01716d8>] handle_IRQ_event+0x28/0x70
>  [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
>  [<c0107128>] do_IRQ+0x48/0xa0
> 
> The least invasive fix is to detect that we're trying to re-enter the
> driver code. We provide a netdev_busy() function which can be used to
> determine whether a deadlock can occur if we try to transmit another
> packet.
> 
> Note that this may lead to lost messages if the driver is active on
> another CPU while we try to use the same device for netconsole.

This sucks.

> It would probably be best to set a "lost messages" flag in this case and
> add it to the stream when the device becomes ready again.
> 
> The only extra overhead in non-netconsole code paths is the fact that we
> need another callback in struct net_device. However, all drivers must be
> checked for the possibility of a deadlock and implement the ->busy()
> callback as necessary.

> --- a/drivers/net/8139too.c
> +++ b/drivers/net/8139too.c
> @@ -979,6 +980,7 @@ static int __devinit rtl8139_init_one (struct pci_dev *pdev,
>  	/* The Rtl8139-specific entries in the device structure. */
>  	dev->open = rtl8139_open;
>  	dev->hard_start_xmit = rtl8139_start_xmit;
> +	dev->busy = rtl8139_busy;
>  	netif_napi_add(dev, &tp->napi, rtl8139_poll, 64);
>  	dev->stop = rtl8139_close;
>  	dev->get_stats = rtl8139_get_stats;
> @@ -1741,6 +1743,11 @@ static int rtl8139_start_xmit (struct sk_buff *skb, struct net_device *dev)
>  	return 0;
>  }
>  
> +static bool rtl8139_busy (struct net_device *dev)
> +{
> +	struct rtl8139_private *tp = netdev_priv(dev);
> +	return spin_is_locked(&tp->lock);
> +}

How do I know if my driver is suspectible to this sort of deadlock?

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Vegard Nossum]

(Hm, did my original e-mail not make it to the lists?)

>> The least invasive fix is to detect that we're trying to re-enter the
>> driver code. We provide a netdev_busy() function which can be used to
>> determine whether a deadlock can occur if we try to transmit another
>> packet.
>>
>> Note that this may lead to lost messages if the driver is active on
>> another CPU while we try to use the same device for netconsole.
>
> This sucks.

Indeed. What can be done about it?

>> It would probably be best to set a "lost messages" flag in this case and
>> add it to the stream when the device becomes ready again.

With such a flag, we can at least avoid silent loss of messages. But
what is the likelihood of this happening in the first place? I have no
idea.

I still think that this is better than a possible deadlock, which
gives NO CLUE as to what happened (because it jams the other
consoles). Hopefully the interface will not be used for other traffic.

But I agree. This possibly penalizes all the other cases where people
*don't* pull out their netconsole-device cables.

We could simply not print out the "link up/down" message if the device
is running netconsole. But it feels like papering over the design
error. Because there are other functions in there which may cause
additional messages to be printed, not just the very visible printk().

Can we detect if the lock was taken on the same CPU or not?

Maybe it is possible to postpone the packet instead of discarding it?

>> +static bool rtl8139_busy (struct net_device *dev)
>> +{
>> +     struct rtl8139_private *tp = netdev_priv(dev);
>> +     return spin_is_locked(&tp->lock);
>> +}
>
> How do I know if my driver is suspectible to this sort of deadlock?

if the ->hard_start_xmit() takes any locks which can be taken from any
code that calls (also indirectly!) printk(), in this case the
interrupt handler that is invoked when I replace the cable. My guess
is that _all_ drivers need to take some sort of lock in
hard_start_xmit().

It's a bit fragile, I agree. But the completely silent deadlock is nasty too!


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: Alexey Dobriyan <adobriyan@gmail.com>
Date: Wed, 13 Aug 2008 13:59:43 +0400

> On Wed, Aug 13, 2008 at 11:53:24AM +0200, Vegard Nossum wrote:
> > I encountered a hard-to-debug deadlock when I pulled out the plug of my
> > RealTek 8139 which was also running netconsole: The driver wants to print
> > a "link down" message. However, this triggers netconsole, which wants to
> > print the message using the same device. Here is a backtrace:
> > 
> >  [<c05916b6>] _spin_lock_irqsave+0x76/0x90
> >  [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
> >  [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
> >  [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
> >  [<c037c70c>] write_msg+0x8c/0xc0
> >  [<c0135883>] __call_console_drivers+0x53/0x60
> >  [<c01358db>] _call_console_drivers+0x4b/0x90
> >  [<c0135a25>] release_console_sem+0xc5/0x1f0
> >  [<c0135f0b>] vprintk+0x1ab/0x3e0
> >  [<c013615b>] printk+0x1b/0x20
> >  [<c0349736>] mii_check_media+0x196/0x1e0
> >  [<c03597f4>] rtl_check_media+0x24/0x30
> >  [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
> >  [<c01716d8>] handle_IRQ_event+0x28/0x70
> >  [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
> >  [<c0107128>] do_IRQ+0x48/0xa0
> > 
> > The least invasive fix is to detect that we're trying to re-enter the
> > driver code. We provide a netdev_busy() function which can be used to
> > determine whether a deadlock can occur if we try to transmit another
> > packet.
> > 
> > Note that this may lead to lost messages if the driver is active on
> > another CPU while we try to use the same device for netconsole.
> 
> This sucks.

It's also the wrong fix.

As a quicker and more palatable solution, print your link status
message in some kind of deferred context where you can have the
lock not held or similar.

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: Vegard Nossum <vegardno@ifi.uio.no>
Date: Wed, 13 Aug 2008 11:53:24 +0200

> [PATCH] netconsole: avoid deadlock on printk from driver code
> 
> I encountered a hard-to-debug deadlock when I pulled out the plug of my
> RealTek 8139 which was also running netconsole: The driver wants to print
> a "link down" message. However, this triggers netconsole, which wants to
> print the message using the same device. Here is a backtrace:

See my other reply, this is absolutely the wrong way to go about
this.

You only have two sane options:

1) Defer the link status printk message into a deferred context,
   such as a workqueue, so that you can do it outside of the
   lock.

2) Do your locking differently so that the link status handling
   locking does not bisect the locking used for packet transmit
   in ->hard_start_xmit().

#2 is the reason why most other drivers don't have this silly
bug, they don't hold TX path locks when handling link status
and printing out such messages.

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Vegard Nossum]

On Wed, Aug 13, 2008 at 12:29 PM, David Miller <davem@davemloft.net> wrote:
> From: Alexey Dobriyan <adobriyan@gmail.com>
> Date: Wed, 13 Aug 2008 13:59:43 +0400
>> > The least invasive fix is to detect that we're trying to re-enter the
>> > driver code. We provide a netdev_busy() function which can be used to
>> > determine whether a deadlock can occur if we try to transmit another
>> > packet.
>> >
>> > Note that this may lead to lost messages if the driver is active on
>> > another CPU while we try to use the same device for netconsole.
>>
>> This sucks.
>
> It's also the wrong fix.
>
> As a quicker and more palatable solution, print your link status
> message in some kind of deferred context where you can have the
> lock not held or similar.

This is true, but it is very fragile. It fixes only one case (exactly
the case that I saw), while there may be many more of the same nature.

For your proposed fix to work in all cases, _all_ printks coming from
rtl8139_tx_interrupt() must be printed in a different context. That
includes, but is not necessarily limited to, these obvious cases:

        DPRINTK ("%s: Abnormal interrupt, status %8.8x.\n",
                 dev->name, status);

    printk(KERN_DEBUG "%s: Transmit error, Tx status %8.8x.\n",

                printk (KERN_ERR "%s: PCI Bus error %4.4x.\n",
                        dev->name, pci_cmd_status);

                printk (KERN_ERR "%s: Out-of-sync dirty pointer, %ld
vs. %ld.\n",

There must also be no BUG()s, WARN()s, other debugging facilities
(spinlock debugging, lockdep, irqtrace, etc.) triggering which may
call printk() inside the protected section. Can we really ensure this?
For all drivers supporting netconsole?


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: "Vegard Nossum" <vegard.nossum@gmail.com>
Date: Wed, 13 Aug 2008 12:44:46 +0200

> There must also be no BUG()s, WARN()s, other debugging facilities
> (spinlock debugging, lockdep, irqtrace, etc.) triggering which may
> call printk() inside the protected section. Can we really ensure this?
> For all drivers supporting netconsole?

For all drivers supporting netconsole?  Well yes, there will be some
bugs somewhere in some driver wrt. netconsole.  But that's life
and why we will constantly have something to fix in the kernel isn't
it?

But one thing is for sure, your deliriously dirty ->busy thing is
emphatically not the answer.

BTW, it seems the main reason this driver is susceptible to this
problem is that it doesn't handle link status events in it's
NAPI poll handler.  If it did that, you would have never seen
this deadlock.

The netpoll layer prevents recursion into the NAPI ->poll() handler.

Most drivers manage link state either in their NAPI ->poll() handler
or a periodic timer that samples the link state.  Both schemes
avoid this very issue.

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Pekka Enberg]

Hi David,

On Wed, Aug 13, 2008 at 1:37 PM, David Miller <davem@davemloft.net> wrote:
> From: Vegard Nossum <vegardno@ifi.uio.no>
> Date: Wed, 13 Aug 2008 11:53:24 +0200
>
>> [PATCH] netconsole: avoid deadlock on printk from driver code
>>
>> I encountered a hard-to-debug deadlock when I pulled out the plug of my
>> RealTek 8139 which was also running netconsole: The driver wants to print
>> a "link down" message. However, this triggers netconsole, which wants to
>> print the message using the same device. Here is a backtrace:
>
> See my other reply, this is absolutely the wrong way to go about
> this.
>
> You only have two sane options:
>
> 1) Defer the link status printk message into a deferred context,
>   such as a workqueue, so that you can do it outside of the
>   lock.

It's not just the link status. We have assert() and debugging printks
there under tp->lock as well which can also trigger the deadlock
condition.

On Wed, Aug 13, 2008 at 1:37 PM, David Miller <davem@davemloft.net> wrote:
> 2) Do your locking differently so that the link status handling
>   locking does not bisect the locking used for packet transmit
>   in ->hard_start_xmit().
>
> #2 is the reason why most other drivers don't have this silly
> bug, they don't hold TX path locks when handling link status
> and printing out such messages.

Yeah, that works for the link status case, but not for things like the
printks in rtl8139_tx_interrupt()... Hmm.

                             Pekka

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Pekka J Enberg]

On Thu, 14 Aug 2008, Pekka Enberg wrote:
> > See my other reply, this is absolutely the wrong way to go about
> > this.
> >
> > You only have two sane options:
> >
> > 1) Defer the link status printk message into a deferred context,
> >   such as a workqueue, so that you can do it outside of the
> >   lock.
> 
> It's not just the link status. We have assert() and debugging printks
> there under tp->lock as well which can also trigger the deadlock
> condition.
> 
> On Wed, Aug 13, 2008 at 1:37 PM, David Miller <davem@davemloft.net> wrote:
> > 2) Do your locking differently so that the link status handling
> >   locking does not bisect the locking used for packet transmit
> >   in ->hard_start_xmit().
> >
> > #2 is the reason why most other drivers don't have this silly
> > bug, they don't hold TX path locks when handling link status
> > and printing out such messages.
> 
> Yeah, that works for the link status case, but not for things like the
> printks in rtl8139_tx_interrupt()... Hmm.

...so I guess something like the following (totally untested) patch could 
work.

		Pekka

Subject: [PATCH] 8139too: avoid deadlock with netconsole
From: Pekka Enberg <penberg@cs.helsinki.fi>

As explained by Vegard Nossum, the 8139too driver can deadlock with netconsole:

  I encountered a hard-to-debug deadlock when I pulled out the plug of my
  RealTek 8139 which was also running netconsole: The driver wants to print a
  "link down" message. However, this triggers netconsole, which wants to print
  the message using the same device. Here is a backtrace:

     [<c05916b6>] _spin_lock_irqsave+0x76/0x90
     [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
     [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
     [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
     [<c037c70c>] write_msg+0x8c/0xc0
     [<c0135883>] __call_console_drivers+0x53/0x60
     [<c01358db>] _call_console_drivers+0x4b/0x90
     [<c0135a25>] release_console_sem+0xc5/0x1f0
     [<c0135f0b>] vprintk+0x1ab/0x3e0
     [<c013615b>] printk+0x1b/0x20
     [<c0349736>] mii_check_media+0x196/0x1e0
     [<c03597f4>] rtl_check_media+0x24/0x30
     [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
     [<c01716d8>] handle_IRQ_event+0x28/0x70
     [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
     [<c0107128>] do_IRQ+0x48/0xa0

To avoid the deadlock, use a separate ->tx_lock for the TX paths and make sure
we never call printk() while holding that lock.

Cc: Alexey Dobriyan <adobriyan@gmail.com>
Cc: David Miller <davem@davemloft.net>
Cc: Jeff Garzik <jgarzik@pobox.com>
Reported-by: Vegard Nossum <vegard.nossum@gmail.com>
Signed-off-by: Pekka Enberg <penberg@cs.helsinki.fi>
---
 drivers/net/8139too.c |   34 +++++++++++++++++++++++++---------
 1 file changed, 25 insertions(+), 9 deletions(-)

Index: linux-2.6/drivers/net/8139too.c
===================================================================
--- linux-2.6.orig/drivers/net/8139too.c	2008-08-14 16:29:32.000000000 +0300
+++ linux-2.6/drivers/net/8139too.c	2008-08-14 16:41:10.000000000 +0300
@@ -598,6 +598,7 @@
 
 	spinlock_t		lock;
 	spinlock_t		rx_lock;
+	spinlock_t		tx_lock;
 
 	chip_t			chipset;
 	u32			rx_config;
@@ -1009,6 +1010,7 @@
 		(debug < 0 ? RTL8139_DEF_MSG_ENABLE : ((1 << debug) - 1));
 	spin_lock_init (&tp->lock);
 	spin_lock_init (&tp->rx_lock);
+	spin_lock_init (&tp->tx_lock);
 	INIT_DELAYED_WORK(&tp->thread, rtl8139_thread);
 	tp->mii.dev = dev;
 	tp->mii.mdio_read = mdio_read;
@@ -1675,9 +1677,9 @@
 	RTL_W16 (IntrMask, 0x0000);
 
 	/* Stop a shared interrupt from scavenging while we are. */
-	spin_lock_irq(&tp->lock);
+	spin_lock_irq(&tp->tx_lock);
 	rtl8139_tx_clear (tp);
-	spin_unlock_irq(&tp->lock);
+	spin_unlock_irq(&tp->tx_lock);
 
 	/* ...and finally, reset everything */
 	if (netif_running(dev)) {
@@ -1721,7 +1723,7 @@
 		return 0;
 	}
 
-	spin_lock_irqsave(&tp->lock, flags);
+	spin_lock_irqsave(&tp->tx_lock, flags);
 	RTL_W32_F (TxStatus0 + (entry * sizeof (u32)),
 		   tp->tx_flag | max(len, (unsigned int)ETH_ZLEN));
 
@@ -1732,7 +1734,7 @@
 
 	if ((tp->cur_tx - NUM_TX_DESC) == tp->dirty_tx)
 		netif_stop_queue (dev);
-	spin_unlock_irqrestore(&tp->lock, flags);
+	spin_unlock_irqrestore(&tp->tx_lock, flags);
 
 	if (netif_msg_tx_queued(tp))
 		printk (KERN_DEBUG "%s: Queued Tx packet size %u to slot %d.\n",
@@ -1746,11 +1748,15 @@
 				  struct rtl8139_private *tp,
 				  void __iomem *ioaddr)
 {
-	unsigned long dirty_tx, tx_left;
+	unsigned long dirty_tx, old_dirty_tx, tx_left;
+	int error;
 
 	assert (dev != NULL);
 	assert (ioaddr != NULL);
 
+	spin_lock(&tp->tx_lock);
+retry:
+	error = 0;
 	dirty_tx = tp->dirty_tx;
 	tx_left = tp->cur_tx - dirty_tx;
 	while (tx_left > 0) {
@@ -1766,8 +1772,7 @@
 		if (txstatus & (TxOutOfWindow | TxAborted)) {
 			/* There was an major error, log it. */
 			if (netif_msg_tx_err(tp))
-				printk(KERN_DEBUG "%s: Transmit error, Tx status %8.8x.\n",
-					dev->name, txstatus);
+				error = 1;
 			dev->stats.tx_errors++;
 			if (txstatus & TxAborted) {
 				dev->stats.tx_aborted_errors++;
@@ -1793,12 +1798,19 @@
 
 		dirty_tx++;
 		tx_left--;
+		if (error) {
+			spin_unlock(&tp->tx_lock);
+			printk(KERN_DEBUG "%s: Transmit error, Tx status %8.8x.\n",
+				dev->name, txstatus);
+			spin_lock(&tp->tx_lock);
+			goto retry;
+		}
 	}
 
 #ifndef RTL8139_NDEBUG
 	if (tp->cur_tx - dirty_tx > NUM_TX_DESC) {
-		printk (KERN_ERR "%s: Out-of-sync dirty pointer, %ld vs. %ld.\n",
-		        dev->name, dirty_tx, tp->cur_tx);
+		error = 1;
+		old_dirty_tx = dirty_tx;
 		dirty_tx += NUM_TX_DESC;
 	}
 #endif /* RTL8139_NDEBUG */
@@ -1809,6 +1821,10 @@
 		mb();
 		netif_wake_queue (dev);
 	}
+	spin_unlock(&tp->tx_lock);
+	if (error)
+		printk (KERN_ERR "%s: Out-of-sync dirty pointer, %ld vs. %ld.\n",
+		        dev->name, old_dirty_tx, tp->cur_tx);
 }
 
 

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: "Pekka Enberg" <penberg@cs.helsinki.fi>
Date: Thu, 14 Aug 2008 16:28:37 +0300

> On Wed, Aug 13, 2008 at 1:37 PM, David Miller <davem@davemloft.net> wrote:
> > 2) Do your locking differently so that the link status handling
> >   locking does not bisect the locking used for packet transmit
> >   in ->hard_start_xmit().
> >
> > #2 is the reason why most other drivers don't have this silly
> > bug, they don't hold TX path locks when handling link status
> > and printing out such messages.
> 
> Yeah, that works for the link status case, but not for things like the
> printks in rtl8139_tx_interrupt()... Hmm.

Note that netconsole specifically does trylock on the netdev
xmit lock specifically to handle this case.

If you could command the TX path solely under this generic lock
already provided by the generic networking, you could avoid this
deadlock as well.

This is yet another reason many other drivers don't get hit by
this problem.  The solution is built into netpoll but it only
works if you use the provided generic locking mechanisms to
mutex the driver's TX path.

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: Pekka J Enberg <penberg@cs.helsinki.fi>
Date: Thu, 14 Aug 2008 16:44:32 +0300 (EEST)

> @@ -598,6 +598,7 @@
>  
>  	spinlock_t		lock;
>  	spinlock_t		rx_lock;
> +	spinlock_t		tx_lock;
>  
>  	chip_t			chipset;
>  	u32			rx_config;

Why create a special purpose lock when the generic networking
already is taking a lock for you to proect the TX path?

Furthermore, as I just described in another reply, netpoll
already knows that it might need to trylock() attempt on this
lock in order to avoid the very deadlocks this thread is
about.

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Pekka J Enberg]

On Thu, 14 Aug 2008, David Miller wrote:
> From: Pekka J Enberg <penberg@cs.helsinki.fi>
> Date: Thu, 14 Aug 2008 16:44:32 +0300 (EEST)
> 
> > @@ -598,6 +598,7 @@
> >  
> >  	spinlock_t		lock;
> >  	spinlock_t		rx_lock;
> > +	spinlock_t		tx_lock;
> >  
> >  	chip_t			chipset;
> >  	u32			rx_config;
> 
> Why create a special purpose lock when the generic networking
> already is taking a lock for you to proect the TX path?

Heh, no reason, just my ignorance of the networking layer... Does this 
look more like it?

		Pekka

Subject: [PATCH] 8139too: avoid deadlock with netconsole
From: Pekka Enberg <penberg@cs.helsinki.fi>

As explained by Vegard Nossum, the 8139too driver can deadlock with netconsole:

  I encountered a hard-to-debug deadlock when I pulled out the plug of my
  RealTek 8139 which was also running netconsole: The driver wants to print a
  "link down" message. However, this triggers netconsole, which wants to print
  the message using the same device. Here is a backtrace:

     [<c05916b6>] _spin_lock_irqsave+0x76/0x90
     [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
     [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
     [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
     [<c037c70c>] write_msg+0x8c/0xc0
     [<c0135883>] __call_console_drivers+0x53/0x60
     [<c01358db>] _call_console_drivers+0x4b/0x90
     [<c0135a25>] release_console_sem+0xc5/0x1f0
     [<c0135f0b>] vprintk+0x1ab/0x3e0
     [<c013615b>] printk+0x1b/0x20
     [<c0349736>] mii_check_media+0x196/0x1e0
     [<c03597f4>] rtl_check_media+0x24/0x30
     [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
     [<c01716d8>] handle_IRQ_event+0x28/0x70
     [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
     [<c0107128>] do_IRQ+0x48/0xa0

To avoid the deadlock, use netif_tx_lock() for the TX paths and make sure we
never call printk() while holding that lock as suggested by David Miller.

Cc: Alexey Dobriyan <adobriyan@gmail.com>
Cc: David Miller <davem@davemloft.net>
Cc: Jeff Garzik <jgarzik@pobox.com>
Reported-by: Vegard Nossum <vegard.nossum@gmail.com>
Signed-off-by: Pekka Enberg <penberg@cs.helsinki.fi>
---
 drivers/net/8139too.c |   35 +++++++++++++++++++++++++++--------
 1 file changed, 27 insertions(+), 8 deletions(-)

Index: linux-2.6/drivers/net/8139too.c
===================================================================
--- linux-2.6.orig/drivers/net/8139too.c
+++ linux-2.6/drivers/net/8139too.c
@@ -1675,9 +1675,11 @@ static void rtl8139_tx_timeout_task (str
 	RTL_W16 (IntrMask, 0x0000);
 
 	/* Stop a shared interrupt from scavenging while we are. */
-	spin_lock_irq(&tp->lock);
+	local_irq_disable();
+	netif_tx_lock(dev);
 	rtl8139_tx_clear (tp);
-	spin_unlock_irq(&tp->lock);
+	netif_tx_unlock(dev);
+	local_irq_enable();
 
 	/* ...and finally, reset everything */
 	if (netif_running(dev)) {
@@ -1721,7 +1723,8 @@ static int rtl8139_start_xmit (struct sk
 		return 0;
 	}
 
-	spin_lock_irqsave(&tp->lock, flags);
+	local_irq_save(flags);
+	netif_tx_lock(dev);
 	RTL_W32_F (TxStatus0 + (entry * sizeof (u32)),
 		   tp->tx_flag | max(len, (unsigned int)ETH_ZLEN));
 
@@ -1732,7 +1735,8 @@ static int rtl8139_start_xmit (struct sk
 
 	if ((tp->cur_tx - NUM_TX_DESC) == tp->dirty_tx)
 		netif_stop_queue (dev);
-	spin_unlock_irqrestore(&tp->lock, flags);
+	netif_tx_unlock(dev);
+	local_irq_restore(flags);
 
 	if (netif_msg_tx_queued(tp))
 		printk (KERN_DEBUG "%s: Queued Tx packet size %u to slot %d.\n",
@@ -1747,10 +1751,15 @@ static void rtl8139_tx_interrupt (struct
 				  void __iomem *ioaddr)
 {
 	unsigned long dirty_tx, tx_left;
+	unsigned long old_dirty_tx = 0;
+	int error;
 
 	assert (dev != NULL);
 	assert (ioaddr != NULL);
 
+	netif_tx_lock(dev);
+retry:
+	error = 0;
 	dirty_tx = tp->dirty_tx;
 	tx_left = tp->cur_tx - dirty_tx;
 	while (tx_left > 0) {
@@ -1766,8 +1775,7 @@ static void rtl8139_tx_interrupt (struct
 		if (txstatus & (TxOutOfWindow | TxAborted)) {
 			/* There was an major error, log it. */
 			if (netif_msg_tx_err(tp))
-				printk(KERN_DEBUG "%s: Transmit error, Tx status %8.8x.\n",
-					dev->name, txstatus);
+				error = 1;
 			dev->stats.tx_errors++;
 			if (txstatus & TxAborted) {
 				dev->stats.tx_aborted_errors++;
@@ -1793,12 +1801,19 @@ static void rtl8139_tx_interrupt (struct
 
 		dirty_tx++;
 		tx_left--;
+		if (error) {
+			netif_tx_unlock(dev);
+			printk(KERN_DEBUG "%s: Transmit error, Tx status %8.8x.\n",
+				dev->name, txstatus);
+			netif_tx_lock(dev);
+			goto retry;
+		}
 	}
 
 #ifndef RTL8139_NDEBUG
 	if (tp->cur_tx - dirty_tx > NUM_TX_DESC) {
-		printk (KERN_ERR "%s: Out-of-sync dirty pointer, %ld vs. %ld.\n",
-		        dev->name, dirty_tx, tp->cur_tx);
+		error = 1;
+		old_dirty_tx = dirty_tx;
 		dirty_tx += NUM_TX_DESC;
 	}
 #endif /* RTL8139_NDEBUG */
@@ -1809,6 +1824,10 @@ static void rtl8139_tx_interrupt (struct
 		mb();
 		netif_wake_queue (dev);
 	}
+	netif_tx_unlock(dev);
+	if (error)
+		printk (KERN_ERR "%s: Out-of-sync dirty pointer, %ld vs. %ld.\n",
+		        dev->name, old_dirty_tx, tp->cur_tx);
 }
 
 

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[Vegard Nossum]

On Wed, Aug 20, 2008 at 7:54 PM, Pekka J Enberg <penberg@cs.helsinki.fi> wrote:
> Subject: [PATCH] 8139too: avoid deadlock with netconsole
> From: Pekka Enberg <penberg@cs.helsinki.fi>
>
> As explained by Vegard Nossum, the 8139too driver can deadlock with netconsole:
>
>  I encountered a hard-to-debug deadlock when I pulled out the plug of my
>  RealTek 8139 which was also running netconsole: The driver wants to print a
>  "link down" message. However, this triggers netconsole, which wants to print
>  the message using the same device. Here is a backtrace:
>
>     [<c05916b6>] _spin_lock_irqsave+0x76/0x90
>     [<c035b255>] rtl8139_start_xmit+0x65/0x130 <-- spin_lock(&tp->lock)
>     [<c04c5e28>] netpoll_send_skb+0x158/0x1a0
>     [<c04c62fb>] netpoll_send_udp+0x1db/0x1f0
>     [<c037c70c>] write_msg+0x8c/0xc0
>     [<c0135883>] __call_console_drivers+0x53/0x60
>     [<c01358db>] _call_console_drivers+0x4b/0x90
>     [<c0135a25>] release_console_sem+0xc5/0x1f0
>     [<c0135f0b>] vprintk+0x1ab/0x3e0
>     [<c013615b>] printk+0x1b/0x20
>     [<c0349736>] mii_check_media+0x196/0x1e0
>     [<c03597f4>] rtl_check_media+0x24/0x30
>     [<c035a0ea>] rtl8139_interrupt+0x42a/0x4a0 <-- spin_lock(&tp->lock)
>     [<c01716d8>] handle_IRQ_event+0x28/0x70
>     [<c0172d9b>] handle_fasteoi_irq+0x6b/0xe0
>     [<c0107128>] do_IRQ+0x48/0xa0
>
> To avoid the deadlock, use netif_tx_lock() for the TX paths and make sure we
> never call printk() while holding that lock as suggested by David Miller.
>
> Cc: Alexey Dobriyan <adobriyan@gmail.com>
> Cc: David Miller <davem@davemloft.net>
> Cc: Jeff Garzik <jgarzik@pobox.com>
> Reported-by: Vegard Nossum <vegard.nossum@gmail.com>
> Signed-off-by: Pekka Enberg <penberg@cs.helsinki.fi>
> ---

I'm sorry, but it doesn't help :-)

console [netcon0] enabled
=============================================
[ INFO: possible recursive locking detected ]
2.6.27-rc3-00468-g86f91c5 #19
---------------------------------------------
swapper/1 is trying to acquire lock:
 (_xmit_ETHER#2){....}, at: [<c0449210>] rtl8139_start_xmit+0xc0/0x230
but task is already holding lock:
 (_xmit_ETHER#2){....}, at: [<c05b515b>] netpoll_send_skb+0x13b/0x1a0
other info that might help us debug this:
3 locks held by swapper/1:
 #0:  (target_list_lock){....}, at: [<c046ab5d>] write_msg+0x2d/0xc0
 #1:  (_xmit_ETHER#2){....}, at: [<c05b515b>] netpoll_send_skb+0x13b/0x1a0
 #2:  (&dev->tx_global_lock){....}, at: [<c04491e1>] rtl8139_start_xmit+0x91/0x2
30
stack backtrace:
Pid: 1, comm: swapper Not tainted 2.6.27-rc3-00468-g86f91c5 #19
 [<c015fccb>] validate_chain+0xbbb/0xe90
 [<c010e45b>] ? save_stack_trace+0x2b/0x50
 [<c01601f9>] __lock_acquire+0x259/0xa00
 [<c0160a29>] lock_acquire+0x89/0xc0
 [<c0449210>] ? rtl8139_start_xmit+0xc0/0x230
 [<c0681720>] _spin_lock+0x40/0x70
 [<c0449210>] ? rtl8139_start_xmit+0xc0/0x230
 [<c0449210>] rtl8139_start_xmit+0xc0/0x230
 [<c05b515b>] ? netpoll_send_skb+0x13b/0x1a0
 [<c05b5178>] netpoll_send_skb+0x158/0x1a0
 [<c05b564b>] netpoll_send_udp+0x1db/0x1f0
 [<c046abbc>] write_msg+0x8c/0xc0
 [<c013ad13>] __call_console_drivers+0x53/0x60
 [<c013ad6b>] _call_console_drivers+0x4b/0x90
 [<c013aeb5>] release_console_sem+0xc5/0x1f0
 [<c013b698>] register_console+0x138/0x2c0
 [<c08bb860>] init_netconsole+0x1a0/0x1c0
 [<c01520b9>] ? ktime_get+0x19/0x40
 [<c0101120>] do_one_initcall+0x30/0x170
 [<c08bb6c0>] ? init_netconsole+0x0/0x1c0
 [<c017b583>] ? register_irq_proc+0xb3/0xd0
 [<c08916aa>] kernel_init+0x11a/0x180
 [<c0891590>] ? kernel_init+0x0/0x180
 [<c0105cf3>] kernel_thread_helper+0x7/0x14
 =======================

After that, I also got lots of kgdbts errors, don't know exactly how
it relates to your patch...

<3>kgdbts: BP mismatch c03763a0 expected c0139b80
<4>------------[ cut here ]------------
<4>WARNING: at /uio/arkimedes/s29/vegardno/git-working/linux-2.6/drivers/misc/kg
dbts.c:302 check_and_rewind_pc+0xb2/0xe0()
Pid: 1, comm: swapper Not tainted 2.6.27-rc3-00468-g86f91c5 #19
 [<c013a9cf>] warn_on_slowpath+0x4f/0x80
 [<c01670a2>] ? sprint_symbol+0x92/0xc0
 [<c013b25d>] ? vprintk+0x6d/0x350
 [<c013b25d>] ? vprintk+0x6d/0x350
 [<c01248e3>] ? __change_page_attr_set_clr+0x693/0xc30
 [<c0376917>] ? __copy_to_user_ll+0x57/0x60
 [<c0184e1a>] ? probe_kernel_write+0x4a/0x90
 [<c0139b80>] ? do_fork+0x0/0x2b0
 [<c013b55b>] ? printk+0x1b/0x20
 [<c0139b80>] ? do_fork+0x0/0x2b0
 [<c03fee62>] check_and_rewind_pc+0xb2/0xe0
 [<c03763a0>] ? delay_tsc+0x20/0xb8
 [<c0139b80>] ? do_fork+0x0/0x2b0
 [<c03fdc52>] validate_simple_test+0x22/0xa0
 [<c03fe407>] run_simple_test+0x107/0x260
 [<c0184eaa>] ? probe_kernel_read+0x4a/0x90
 [<c03fdd34>] kgdbts_put_char+0x14/0x20
 [<c0177476>] put_packet+0x86/0xe0
 [<c0178376>] kgdb_handle_exception+0x446/0xe40
 [<c013b25d>] ? vprintk+0x6d/0x350
 [<c011dd61>] kgdb_notify+0xa1/0x1d0
 [<c0153037>] notifier_call_chain+0x37/0x70
 [<c0153435>] __atomic_notifier_call_chain+0x35/0x50
 [<c015346a>] atomic_notifier_call_chain+0x1a/0x20
 [<c015349d>] notify_die+0x2d/0x30
 [<c0106d5a>] die_nmi+0x3a/0x100
 [<c011add5>] nmi_watchdog_tick+0x1d5/0x1e0
 [<c0107227>] do_nmi+0x97/0x2d0
 [<c06823f3>] nmi_stack_correct+0x26/0x2b
 [<c03763a0>] ? delay_tsc+0x20/0xb8
 [<c03762c9>] __delay+0x9/0x10
 [<c03857ec>] _raw_spin_lock+0xbc/0x150
 [<c015b73e>] ? get_lock_stats+0x1e/0x50
 [<c015b77d>] ? put_lock_stats+0xd/0x30
 [<c068173c>] _spin_lock+0x5c/0x70
 [<c0449210>] ? rtl8139_start_xmit+0xc0/0x230
 [<c0449210>] rtl8139_start_xmit+0xc0/0x230
 [<c05b515b>] ? netpoll_send_skb+0x13b/0x1a0
 [<c05b5178>] netpoll_send_skb+0x158/0x1a0
 [<c05b564b>] netpoll_send_udp+0x1db/0x1f0
 [<c046abbc>] write_msg+0x8c/0xc0
 [<c013ad13>] __call_console_drivers+0x53/0x60
 [<c013ad6b>] _call_console_drivers+0x4b/0x90
 [<c013aeb5>] release_console_sem+0xc5/0x1f0
 [<c013b698>] register_console+0x138/0x2c0
 [<c08bb860>] init_netconsole+0x1a0/0x1c0
 [<c01520b9>] ? ktime_get+0x19/0x40
 [<c0101120>] do_one_initcall+0x30/0x170
 [<c08bb6c0>] ? init_netconsole+0x0/0x1c0
 [<c017b583>] ? register_irq_proc+0xb3/0xd0
 [<c08916aa>] kernel_init+0x11a/0x180
 [<c0891590>] ? kernel_init+0x0/0x180
 [<c0105cf3>] kernel_thread_helper+0x7/0x14
 =======================
<4>---[ end trace 3a158aadebbe6259 ]---

(This repeats every few seconds.)

When pulling the cable, I get this:

<0>BUG: spinlock lockup on CPU#1, swapper/1, f58599ac
Pid: 1, comm: swapper Tainted: G        W 2.6.27-rc3-00468-g86f91c5 #19
 [<c0385840>] _raw_spin_lock+0x110/0x150
 [<c068173c>] _spin_lock+0x5c/0x70
 [<c0449210>] ? rtl8139_start_xmit+0xc0/0x230
 [<c0449210>] rtl8139_start_xmit+0xc0/0x230
 [<c05b515b>] ? netpoll_send_skb+0x13b/0x1a0
 [<c05b5178>] netpoll_send_skb+0x158/0x1a0
 [<c05b564b>] netpoll_send_udp+0x1db/0x1f0
 [<c046abbc>] write_msg+0x8c/0xc0
 [<c013ad13>] __call_console_drivers+0x53/0x60
 [<c013ad6b>] _call_console_drivers+0x4b/0x90
 [<c013aeb5>] release_console_sem+0xc5/0x1f0
 [<c013b698>] register_console+0x138/0x2c0
 [<c08bb860>] init_netconsole+0x1a0/0x1c0
 [<c01520b9>] ? ktime_get+0x19/0x40
 [<c0101120>] do_one_initcall+0x30/0x170
 [<c08bb6c0>] ? init_netconsole+0x0/0x1c0
 [<c017b583>] ? register_irq_proc+0xb3/0xd0
 [<c08916aa>] kernel_init+0x11a/0x180
 [<c0891590>] ? kernel_init+0x0/0x180
 [<c0105cf3>] kernel_thread_helper+0x7/0x14
 =======================

...and machine is unusable. Thanks for trying! :-D


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: [RFC][PATCH] netconsole: avoid deadlock on printk from driver code

[David Miller]

From: Pekka J Enberg <penberg@cs.helsinki.fi>
Date: Wed, 20 Aug 2008 20:54:01 +0300 (EEST)

> @@ -1721,7 +1723,8 @@ static int rtl8139_start_xmit (struct sk
>  		return 0;
>  	}
>  
> -	spin_lock_irqsave(&tp->lock, flags);
> +	local_irq_save(flags);
> +	netif_tx_lock(dev);
>  	RTL_W32_F (TxStatus0 + (entry * sizeof (u32)),
>  		   tp->tx_flag | max(len, (unsigned int)ETH_ZLEN));

The generic networking takes the TX lock for you, you don't
need to take it explicitly here.

You also cannot depend upon IRQ disabled locking, the generic
TX lock is only softirq safe, not hard IRQ safe.

This means you have to move TX descriptor reclaim into a
soft IRQ context, such as NAPI ->poll().