diff mbox series

usbnet: fix kernel crash after disconnect

Message ID 20190417091849.7475-1-Jan.Kloetzke@preh.de (mailing list archive)
State Superseded
Headers show
Series usbnet: fix kernel crash after disconnect | expand

Commit Message

Kloetzke Jan April 17, 2019, 9:19 a.m. UTC
When disconnecting cdc_ncm the kernel sporadically crashes shortly
after the disconnect:

  [   57.868812] Unable to handle kernel NULL pointer dereference at virtual address 00000000
  ...
  [   58.006653] PC is at 0x0
  [   58.009202] LR is at call_timer_fn+0xec/0x1b4
  [   58.013567] pc : [<0000000000000000>] lr : [<ffffff80080f5130>] pstate: 00000145
  [   58.020976] sp : ffffff8008003da0
  [   58.024295] x29: ffffff8008003da0 x28: 0000000000000001
  [   58.029618] x27: 000000000000000a x26: 0000000000000100
  [   58.034941] x25: 0000000000000000 x24: ffffff8008003e68
  [   58.040263] x23: 0000000000000000 x22: 0000000000000000
  [   58.045587] x21: 0000000000000000 x20: ffffffc68fac1808
  [   58.050910] x19: 0000000000000100 x18: 0000000000000000
  [   58.056232] x17: 0000007f885aff8c x16: 0000007f883a9f10
  [   58.061556] x15: 0000000000000001 x14: 000000000000006e
  [   58.066878] x13: 0000000000000000 x12: 00000000000000ba
  [   58.072201] x11: ffffffc69ff1db30 x10: 0000000000000020
  [   58.077524] x9 : 8000100008001000 x8 : 0000000000000001
  [   58.082847] x7 : 0000000000000800 x6 : ffffff8008003e70
  [   58.088169] x5 : ffffffc69ff17a28 x4 : 00000000ffff138b
  [   58.093492] x3 : 0000000000000000 x2 : 0000000000000000
  [   58.098814] x1 : 0000000000000000 x0 : 0000000000000000
  ...
  [   58.205800] [<          (null)>]           (null)
  [   58.210521] [<ffffff80080f5298>] expire_timers+0xa0/0x14c
  [   58.215937] [<ffffff80080f542c>] run_timer_softirq+0xe8/0x128
  [   58.221702] [<ffffff8008081120>] __do_softirq+0x298/0x348
  [   58.227118] [<ffffff80080a6304>] irq_exit+0x74/0xbc
  [   58.232009] [<ffffff80080e17dc>] __handle_domain_irq+0x78/0xac
  [   58.237857] [<ffffff8008080cf4>] gic_handle_irq+0x80/0xac
  ...

The crash happens roughly 125..130ms after the disconnect. This
correlates with the 'delay' timer that is started on certain USB tx/rx
errors in the URB completion handler.

The suspected problem is a race of usbnet_stop() with
usbnet_start_xmit(). In usbnet_stop() we call usbnet_terminate_urbs()
to cancel all URBs in flight. This only makes sense if no new URBs are
submitted concurrently, though. But the usbnet_start_xmit() can run at
the same time on another CPU which almost unconditionally submits an
URB. The error callback of the new URB will then schedule the timer
after it was already stopped.

The fix adds a check if the tx queue is stopped after the tx list lock
has been taken. This should reliably prevent the submission of new URBs
while usbnet_terminate_urbs() does its job. The same thing is done on
the rx side even though it might be safe due to other flags that are
checked there.

Signed-off-by: Jan Klötzke <Jan.Kloetzke@preh.de>
---
 drivers/net/usb/usbnet.c | 6 ++++++
 1 file changed, 6 insertions(+)

Comments

Oliver Neukum April 18, 2019, 6:37 a.m. UTC | #1
On Mi, 2019-04-17 at 09:19 +0000, Kloetzke Jan wrote:
> When disconnecting cdc_ncm the kernel sporadically crashes shortly
> after the disconnect:
> 
>   [   57.868812] Unable to handle kernel NULL pointer dereference at virtual address 00000000
>   ...
>   [   58.006653] PC is at 0x0
>   [   58.009202] LR is at call_timer_fn+0xec/0x1b4
>   [   58.013567] pc : [<0000000000000000>] lr : [<ffffff80080f5130>] pstate: 00000145
>   [   58.020976] sp : ffffff8008003da0
>   [   58.024295] x29: ffffff8008003da0 x28: 0000000000000001
>   [   58.029618] x27: 000000000000000a x26: 0000000000000100
>   [   58.034941] x25: 0000000000000000 x24: ffffff8008003e68
>   [   58.040263] x23: 0000000000000000 x22: 0000000000000000
>   [   58.045587] x21: 0000000000000000 x20: ffffffc68fac1808
>   [   58.050910] x19: 0000000000000100 x18: 0000000000000000
>   [   58.056232] x17: 0000007f885aff8c x16: 0000007f883a9f10
>   [   58.061556] x15: 0000000000000001 x14: 000000000000006e
>   [   58.066878] x13: 0000000000000000 x12: 00000000000000ba
>   [   58.072201] x11: ffffffc69ff1db30 x10: 0000000000000020
>   [   58.077524] x9 : 8000100008001000 x8 : 0000000000000001
>   [   58.082847] x7 : 0000000000000800 x6 : ffffff8008003e70
>   [   58.088169] x5 : ffffffc69ff17a28 x4 : 00000000ffff138b
>   [   58.093492] x3 : 0000000000000000 x2 : 0000000000000000
>   [   58.098814] x1 : 0000000000000000 x0 : 0000000000000000
>   ...
>   [   58.205800] [<          (null)>]           (null)
>   [   58.210521] [<ffffff80080f5298>] expire_timers+0xa0/0x14c
>   [   58.215937] [<ffffff80080f542c>] run_timer_softirq+0xe8/0x128
>   [   58.221702] [<ffffff8008081120>] __do_softirq+0x298/0x348
>   [   58.227118] [<ffffff80080a6304>] irq_exit+0x74/0xbc
>   [   58.232009] [<ffffff80080e17dc>] __handle_domain_irq+0x78/0xac
>   [   58.237857] [<ffffff8008080cf4>] gic_handle_irq+0x80/0xac
>   ...
> 
> The crash happens roughly 125..130ms after the disconnect. This
> correlates with the 'delay' timer that is started on certain USB tx/rx
> errors in the URB completion handler.
> 
> The suspected problem is a race of usbnet_stop() with
> usbnet_start_xmit(). In usbnet_stop() we call usbnet_terminate_urbs()
> to cancel all URBs in flight. This only makes sense if no new URBs are
> submitted concurrently, though. But the usbnet_start_xmit() can run at
> the same time on another CPU which almost unconditionally submits an
> URB. The error callback of the new URB will then schedule the timer
> after it was already stopped.

Hi,

interesting. How sure are you of the details of your analysis?
I am asking because usbnet_stop() does a del_timer_sync().
It is indeed written under the assumption that the upper layer
will have ceased transmission when it stops an interface.

So I am wondering whether the correct fix would not be to make
sure the timer is started.

	Regards
		Oliver
Kloetzke Jan April 18, 2019, 8:02 a.m. UTC | #2
Hi,

Am Donnerstag, den 18.04.2019, 08:37 +0200 schrieb Oliver Neukum:
> On Mi, 2019-04-17 at 09:19 +0000, Kloetzke Jan wrote:
> > When disconnecting cdc_ncm the kernel sporadically crashes shortly
> > after the disconnect:
> > 
> >   [   57.868812] Unable to handle kernel NULL pointer dereference
> > at virtual address 00000000
> >   ...
> >   [   58.006653] PC is at 0x0
> >   [   58.009202] LR is at call_timer_fn+0xec/0x1b4
> >   [   58.013567] pc : [<0000000000000000>] lr :
> > [<ffffff80080f5130>] pstate: 00000145
> >   [   58.020976] sp : ffffff8008003da0
> >   [   58.024295] x29: ffffff8008003da0 x28: 0000000000000001
> >   [   58.029618] x27: 000000000000000a x26: 0000000000000100
> >   [   58.034941] x25: 0000000000000000 x24: ffffff8008003e68
> >   [   58.040263] x23: 0000000000000000 x22: 0000000000000000
> >   [   58.045587] x21: 0000000000000000 x20: ffffffc68fac1808
> >   [   58.050910] x19: 0000000000000100 x18: 0000000000000000
> >   [   58.056232] x17: 0000007f885aff8c x16: 0000007f883a9f10
> >   [   58.061556] x15: 0000000000000001 x14: 000000000000006e
> >   [   58.066878] x13: 0000000000000000 x12: 00000000000000ba
> >   [   58.072201] x11: ffffffc69ff1db30 x10: 0000000000000020
> >   [   58.077524] x9 : 8000100008001000 x8 : 0000000000000001
> >   [   58.082847] x7 : 0000000000000800 x6 : ffffff8008003e70
> >   [   58.088169] x5 : ffffffc69ff17a28 x4 : 00000000ffff138b
> >   [   58.093492] x3 : 0000000000000000 x2 : 0000000000000000
> >   [   58.098814] x1 : 0000000000000000 x0 : 0000000000000000
> >   ...
> >   [   58.205800] [<          (null)>]           (null)
> >   [   58.210521] [<ffffff80080f5298>] expire_timers+0xa0/0x14c
> >   [   58.215937] [<ffffff80080f542c>] run_timer_softirq+0xe8/0x128
> >   [   58.221702] [<ffffff8008081120>] __do_softirq+0x298/0x348
> >   [   58.227118] [<ffffff80080a6304>] irq_exit+0x74/0xbc
> >   [   58.232009] [<ffffff80080e17dc>] __handle_domain_irq+0x78/0xac
> >   [   58.237857] [<ffffff8008080cf4>] gic_handle_irq+0x80/0xac
> >   ...
> > 
> > The crash happens roughly 125..130ms after the disconnect. This
> > correlates with the 'delay' timer that is started on certain USB
> > tx/rx
> > errors in the URB completion handler.
> > 
> > The suspected problem is a race of usbnet_stop() with
> > usbnet_start_xmit(). In usbnet_stop() we call
> > usbnet_terminate_urbs()
> > to cancel all URBs in flight. This only makes sense if no new URBs
> > are
> > submitted concurrently, though. But the usbnet_start_xmit() can run
> > at
> > the same time on another CPU which almost unconditionally submits
> > an
> > URB. The error callback of the new URB will then schedule the timer
> > after it was already stopped.
> 
> Hi,
> 
> interesting. How sure are you of the details of your analysis?

We have seen the issue sporadically, maybe once a month, on our IVI
system with dozens of units being tested all day long. We have the fix
in the field since three months and got no further reports so far. So
I'm relatively optimistic that the patch solves the problem.

> I am asking because usbnet_stop() does a del_timer_sync().
> It is indeed written under the assumption that the upper layer
> will have ceased transmission when it stops an interface.

I think this assumption is not correct. As far as I understand the
networking code it is still possible that the ndo_start_xmit callback
is called while ndo_stop is running and even after ndo_stop has
returned. You can only be sure after unregister_netdev() has returned.
Maybe some networking folks can comment on that.

> So I am wondering whether the correct fix would not be to make
> sure the timer is started.

I think the real problem is that new URBs are submitted concurrently.
The timer is just a secondary problem that blows up later. But if my
above assumption wrt. ndo_stop/ndo_start_xmit is not correct then the
patch would be indeed wrong.

Regards,
Jan
David Miller April 18, 2019, 11:35 p.m. UTC | #3
From: Kloetzke Jan <Jan.Kloetzke@preh.de>
Date: Thu, 18 Apr 2019 08:02:59 +0000

> I think this assumption is not correct. As far as I understand the
> networking code it is still possible that the ndo_start_xmit callback
> is called while ndo_stop is running and even after ndo_stop has
> returned. You can only be sure after unregister_netdev() has returned.
> Maybe some networking folks can comment on that.

The kernel loops over the devices being unregistered, and first it clears
the __LINK_STATE_START on all of them, then it invokes ->ndo_stop() on
all of them.

__LINK_STATE_START controls what netif_running() returns.

All calls to ->ndo_start_xmit() are guarded by netif_running() checks.

So when ndo_stop is invoked you should get no more ndo_start_xmit
invocations on that device.  Otherwise how could you shut down DMA
resources and turn off the TX engine properly?
Jan Klötzke April 19, 2019, 7:17 a.m. UTC | #4
Hi David,

On Thu, Apr 18, 2019 at 04:35:44PM -0700, David Miller wrote:
> From: Kloetzke Jan <Jan.Kloetzke@preh.de>
> Date: Thu, 18 Apr 2019 08:02:59 +0000
> 
> > I think this assumption is not correct. As far as I understand the
> > networking code it is still possible that the ndo_start_xmit callback
> > is called while ndo_stop is running and even after ndo_stop has
> > returned. You can only be sure after unregister_netdev() has returned.
> > Maybe some networking folks can comment on that.
> 
> The kernel loops over the devices being unregistered, and first it clears
> the __LINK_STATE_START on all of them, then it invokes ->ndo_stop() on
> all of them.
> 
> __LINK_STATE_START controls what netif_running() returns.
> 
> All calls to ->ndo_start_xmit() are guarded by netif_running() checks.
> 
> So when ndo_stop is invoked you should get no more ndo_start_xmit
> invocations on that device.  Otherwise how could you shut down DMA
> resources and turn off the TX engine properly?

But you could still race with another CPU that is past the
netif_running() check, can you? So the driver has to make sure that it
gracefully handles concurrent ->ndo_start_xmit() and ->ndo_stop() calls.

Or are there any locks/barriers involved that make sure all
->ndo_start_xmit() calls have returned before invoking ->ndo_stop()?

Regards,
Jan
Oliver Neukum April 29, 2019, 6:48 p.m. UTC | #5
On Fr, 2019-04-19 at 09:17 +0200, Jan Klötzke  wrote:
> Hi David,
> 
> On Thu, Apr 18, 2019 at 04:35:44PM -0700, David Miller wrote:
> > From: Kloetzke Jan <Jan.Kloetzke@preh.de>
> > Date: Thu, 18 Apr 2019 08:02:59 +0000
> > 
> > > I think this assumption is not correct. As far as I understand the
> > > networking code it is still possible that the ndo_start_xmit callback
> > > is called while ndo_stop is running and even after ndo_stop has
> > > returned. You can only be sure after unregister_netdev() has returned.
> > > Maybe some networking folks can comment on that.
> > 
> > The kernel loops over the devices being unregistered, and first it clears
> > the __LINK_STATE_START on all of them, then it invokes ->ndo_stop() on
> > all of them.
> > 
> > __LINK_STATE_START controls what netif_running() returns.
> > 
> > All calls to ->ndo_start_xmit() are guarded by netif_running() checks.
> > 
> > So when ndo_stop is invoked you should get no more ndo_start_xmit
> > invocations on that device.  Otherwise how could you shut down DMA
> > resources and turn off the TX engine properly?
> 
> But you could still race with another CPU that is past the
> netif_running() check, can you? So the driver has to make sure that it
> gracefully handles concurrent ->ndo_start_xmit() and ->ndo_stop() calls.

Looking at dev_direct_xmit(struct sk_buff *skb, u16 queue_id)
this indeed seems possible. But the documentation says that it is not.

Dave?

> Or are there any locks/barriers involved that make sure all
> ->ndo_start_xmit() calls have returned before invoking ->ndo_stop()?

Jan,

could you make versio of your patch that gives a WARNing if this race
triggers?

	Regards
		Oliver
Kloetzke Jan April 30, 2019, 2:08 p.m. UTC | #6
Am Montag, den 29.04.2019, 20:48 +0200 schrieb Oliver Neukum:
> On Fr, 2019-04-19 at 09:17 +0200, Jan Klötzke  wrote:
> > Hi David,
> > 
> > On Thu, Apr 18, 2019 at 04:35:44PM -0700, David Miller wrote:
> > > From: Kloetzke Jan <Jan.Kloetzke@preh.de>
> > > Date: Thu, 18 Apr 2019 08:02:59 +0000
> > > 
> > > > I think this assumption is not correct. As far as I understand the
> > > > networking code it is still possible that the ndo_start_xmit callback
> > > > is called while ndo_stop is running and even after ndo_stop has
> > > > returned. You can only be sure after unregister_netdev() has returned.
> > > > Maybe some networking folks can comment on that.
> > > 
> > > The kernel loops over the devices being unregistered, and first it clears
> > > the __LINK_STATE_START on all of them, then it invokes ->ndo_stop() on
> > > all of them.
> > > 
> > > __LINK_STATE_START controls what netif_running() returns.
> > > 
> > > All calls to ->ndo_start_xmit() are guarded by netif_running() checks.
> > > 
> > > So when ndo_stop is invoked you should get no more ndo_start_xmit
> > > invocations on that device.  Otherwise how could you shut down DMA
> > > resources and turn off the TX engine properly?
> > 
> > But you could still race with another CPU that is past the
> > netif_running() check, can you? So the driver has to make sure that it
> > gracefully handles concurrent ->ndo_start_xmit() and ->ndo_stop() calls.
> 
> Looking at dev_direct_xmit(struct sk_buff *skb, u16 queue_id)
> this indeed seems possible. But the documentation says that it is not.
> 
> Dave?
> 
> > Or are there any locks/barriers involved that make sure all
> > ->ndo_start_xmit() calls have returned before invoking ->ndo_stop()?
> 
> Jan,
> 
> could you make versio of your patch that gives a WARNing if this race
> triggers?

Sure. I'll send v2 shortly.

Regards,
Jan
diff mbox series

Patch

diff --git a/drivers/net/usb/usbnet.c b/drivers/net/usb/usbnet.c
index 504282af27e5..921cc0571bd0 100644
--- a/drivers/net/usb/usbnet.c
+++ b/drivers/net/usb/usbnet.c
@@ -506,6 +506,7 @@  static int rx_submit (struct usbnet *dev, struct urb *urb, gfp_t flags)
 
 	if (netif_running (dev->net) &&
 	    netif_device_present (dev->net) &&
+	    test_bit(EVENT_DEV_OPEN, &dev->flags) &&
 	    !test_bit (EVENT_RX_HALT, &dev->flags) &&
 	    !test_bit (EVENT_DEV_ASLEEP, &dev->flags)) {
 		switch (retval = usb_submit_urb (urb, GFP_ATOMIC)) {
@@ -1431,6 +1432,11 @@  netdev_tx_t usbnet_start_xmit (struct sk_buff *skb,
 		spin_unlock_irqrestore(&dev->txq.lock, flags);
 		goto drop;
 	}
+	if (netif_queue_stopped(net)) {
+		usb_autopm_put_interface_async(dev->intf);
+		spin_unlock_irqrestore(&dev->txq.lock, flags);
+		goto drop;
+	}
 
 #ifdef CONFIG_PM
 	/* if this triggers the device is still a sleep */