| Message ID | 20190417091849.7475-1-Jan.Kloetzke@preh.de |
|---|---|
| State | Changes Requested |
| Delegated to: | David Miller |
| Headers | show |
| Series | usbnet: fix kernel crash after disconnect | expand |
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
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
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?
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
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
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 --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 */
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(+)