Regression 3.0-rc6+ : khubd blocked (usbnet_cdc_unbind)

Hello,
It seems I'm very unlucky this week and I've come across to what looks like a second regression in the kernel. I'm running a version few commits after 3.0-rc6, which includes commit e534c5b831c8 "fix regression occurring during device removal".

When I plug/unplug/plug a mobile phone, after waiting a few minutes I get a "task khubd:621 blocked for more than 120 seconds." Note that it's directly connected to my laptop, not via an external hub (although the bug also happens with an external hub).

Below is the whole dmesg log (with usb debug messages on)

Let me know if you need me to investigate more, or maybe there is already a fix for that bug?

Cheers,
Éric

hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0002
ehci_hcd 0000:00:1d.7: GetStatus port:1 status 001803 0 ACK POWER sig=j CSC CONNECT
hub 2-0:1.0: port 1, status 0501, change 0001, 480 Mb/s
hub 2-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x501
ehci_hcd 0000:00:1d.7: port 1 high speed
ehci_hcd 0000:00:1d.7: GetStatus port:1 status 001005 0 ACK POWER sig=se0 PE CONNECT
usb 2-1: new high speed USB device number 8 using ehci_hcd
ehci_hcd 0000:00:1d.7: port 1 high speed
ehci_hcd 0000:00:1d.7: GetStatus port:1 status 001005 0 ACK POWER sig=se0 PE CONNECT
usb 2-1: skipped 3 descriptors after interface
usb 2-1: skipped 4 descriptors after interface
usb 2-1: skipped 4 descriptors after interface
usb 2-1: skipped 3 descriptors after interface
usb 2-1: skipped 2 descriptors after interface
usb 2-1: skipped 3 descriptors after interface
usb 2-1: default language 0x0409
usb 2-1: udev 8, busnum 2, minor = 135
usb 2-1: New USB device found, idVendor=0fce, idProduct=d0f3
usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 2-1: Product: Sony Ericsson W595
usb 2-1: Manufacturer: Sony Ericsson
usb 2-1: SerialNumber: 3529650311339760
usb 2-1: usb_probe_device
usb 2-1: configuration #3 chosen from 1 choice
usb 2-1: adding 2-1:3.0 (config #3, interface 0)
usb 2-1: adding 2-1:3.1 (config #3, interface 1)
usb 2-1: adding 2-1:3.2 (config #3, interface 2)
usb 2-1: adding 2-1:3.3 (config #3, interface 3)
usb 2-1: adding 2-1:3.4 (config #3, interface 4)
usb 2-1: adding 2-1:3.5 (config #3, interface 5)
usb 2-1: adding 2-1:3.6 (config #3, interface 6)
usb 2-1: adding 2-1:3.7 (config #3, interface 7)
usb 2-1: adding 2-1:3.8 (config #3, interface 8)
usb 2-1: adding 2-1:3.9 (config #3, interface 9)
usb 2-1: adding 2-1:3.10 (config #3, interface 10)
drivers/usb/core/inode.c: creating file '008'
usb usb1: usb auto-resume
ehci_hcd 0000:00:1a.7: resume root hub
hub 1-0:1.0: hub_resume
hub 1-0:1.0: state 7 ports 4 chg 0000 evt 0000
usb usb3: usb auto-resume
usb usb3: wakeup_rh
hub 3-0:1.0: hub_resume
hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
usb usb4: usb auto-resume
usb usb4: wakeup_rh
hub 4-0:1.0: hub_resume
hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
usb usb5: usb auto-resume
usb usb5: wakeup_rh
hub 5-0:1.0: hub_resume
hub 5-0:1.0: port 2: status 0107 change 0000
hub 5-0:1.0: state 7 ports 2 chg 0000 evt 0000
usb 5-2: usb auto-resume
hub 5-0:1.0: state 7 ports 2 chg 0000 evt 0004
uhci_hcd 0000:00:1d.0: port 2 portsc 00a5,01
usb 5-2: finish resume
usb usb6: usb auto-resume
usb usb6: wakeup_rh
hub 6-0:1.0: hub_resume
hub 6-0:1.0: state 7 ports 2 chg 0000 evt 0000
usb usb7: usb auto-resume
usb usb7: wakeup_rh
hub 7-0:1.0: hub_resume
hub 7-0:1.0: state 7 ports 2 chg 0000 evt 0000
cdc_acm 2-1:3.1: usb_probe_interface
cdc_acm 2-1:3.1: usb_probe_interface
cdc_acm 2-1:3.1: usb_probe_interface - got id
cdc_acm 2-1:3.1: ttyACM0: USB ACM device
cdc_acm 2-1:3.3: usb_probe_interface
cdc_acm 2-1:3.3: usb_probe_interface - got id
cdc_acm 2-1:3.3: ttyACM1: USB ACM device
usbcore: registered new interface driver cdc_acm
cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
cdc_ether 2-1:3.8: usb_probe_interface
cdc_ether 2-1:3.8: usb_probe_interface - got id
cdc_ether 2-1:3.8: usb0: register 'cdc_ether' at usb-0000:00:1d.7-1, CDC Ethernet Device, 02:80:37:0f:03:00
usbcore: registered new interface driver cdc_ether
cdc_wdm 2-1:3.7: usb_probe_interface
cdc_wdm 2-1:3.7: usb_probe_interface - got id
cdc_wdm 2-1:3.7: looking for a minor, starting at 0
cdc_wdm 2-1:3.7: cdc-wdm-176: USB WDM device
usbcore: registered new interface driver cdc_wdm
usb 2-1: link qh16-0001/ffff88011a072b80 start 5 [1/0 us]
usb 2-1: link qh16-0001/ffff88011a361680 start 6 [1/0 us]
usb 2-1: link qh8-0001/ffff88011a072680 start 7 [1/0 us]
usb usb3: suspend_rh (auto-stop)
usb usb4: suspend_rh (auto-stop)
usb usb6: suspend_rh (auto-stop)
usb usb7: suspend_rh (auto-stop)
usb 2-1: unlink qh16-0001/ffff88011a072b80 start 5 [1/0 us]
usb 2-1: unlink qh16-0001/ffff88011a361680 start 6 [1/0 us]
ehci_hcd 0000:00:1d.7: reused qh ffff88011a072b80 schedule
usb 2-1: link qh16-0001/ffff88011a072b80 start 5 [1/0 us]
usb 2-1: unlink qh16-0001/ffff88011a072b80 start 5 [1/0 us]
hub 1-0:1.0: hub_suspend
usb usb1: bus auto-suspend
ehci_hcd 0000:00:1a.7: suspend root hub
hub 3-0:1.0: hub_suspend
usb usb3: bus auto-suspend
usb usb3: suspend_rh
hub 4-0:1.0: hub_suspend
usb usb4: bus auto-suspend
usb usb4: suspend_rh
usb 5-2: usb auto-suspend
hub 6-0:1.0: hub_suspend
usb usb6: bus auto-suspend
usb usb6: suspend_rh
hub 7-0:1.0: hub_suspend
usb usb7: bus auto-suspend
usb usb7: suspend_rh
hub 5-0:1.0: hub_suspend
usb usb5: bus auto-suspend
usb usb5: suspend_rh
usb0: no IPv6 routers present
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 1
hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0002
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 2
ehci_hcd 0000:00:1d.7: GetStatus port:1 status 001002 0 ACK POWER sig=se0 CSC
hub 2-0:1.0: port 1, status 0100, change 0001, 12 Mb/s
usb 2-1: USB disconnect, device number 8
usb 2-1: unregistering device
usb 2-1: unregistering interface 2-1:3.0
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 3
usb 2-1: unregistering interface 2-1:3.1
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 4
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 5
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 6
usb 2-1: unregistering interface 2-1:3.2
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 7
usb 2-1: unregistering interface 2-1:3.3
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 8
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 9
usb 2-1: unregistering interface 2-1:3.4
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 10
usb 2-1: unregistering interface 2-1:3.5
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 11
usb 2-1: unregistering interface 2-1:3.6
usb 2-1: unregistering interface 2-1:3.7
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 12
drivers/usb/core/file.c: removing 0 minor
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 13
usb 2-1: unregistering interface 2-1:3.8
usb 2-1: unlink qh8-0001/ffff88011a072680 start 7 [1/0 us]
ehci_hcd 0000:00:1d.7: detected XactErr len 0/1514 retry 14
ehci_hcd 0000:00:1d.7: shutdown urb ffff880124ba3540 ep7in-intr
cdc_ether 2-1:3.8: usb0: unregister 'cdc_ether' usb-0000:00:1d.7-1, CDC Ethernet Device

INFO: task khubd:621 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
khubd D ffff88013a309fd8 0 621 2 0x00000000
ffff88013a309a30 0000000000000046 ffff88013ba9acc0 ffff88013b8bacc0 ffff88013b8bacc0 ffff88013a309fd8 ffff88013a309fd8 ffff88013a309fd8 ffff88013b8a4320 ffff88013b8bacc0 ffffffff81542714 ffff88013a05a440

Call Trace:
 [<ffffffff8138b0ce>] ? apic_timer_interrupt+0xe/0x20
 [<ffffffff8109ccd0>] ? rcu_batches_completed+0x10/0x10
 [<ffffffff81388674>] __mutex_lock_slowpath+0xf4/0x190
 [<ffffffff813880ad>] mutex_lock+0x1d/0x40
 [<ffffffffa00e324e>] usb_set_interface+0x6e/0x2a0 [usbcore]
 [<ffffffffa00e50cf>] usb_unbind_interface+0x10f/0x180 [usbcore]
 [<ffffffff81269227>] __device_release_driver+0x77/0xd0
 [<ffffffff812692a7>] device_release_driver+0x27/0x40
 [<ffffffffa00e51c8>] usb_driver_release_interface+0x88/0x90 [usbcore]
 [<ffffffff8105b89b>] ? __cancel_work_timer+0x7b/0x130
 [<ffffffffa04c60b7>] usbnet_cdc_unbind+0x97/0xb0 [cdc_ether]
 [<ffffffffa04b281e>] usbnet_disconnect+0x7e/0x100 [usbnet]
 [<ffffffffa00e500d>] usb_unbind_interface+0x4d/0x180 [usbcore]
 [<ffffffff81269227>] __device_release_driver+0x77/0xd0
 [<ffffffff812692a7>] device_release_driver+0x27/0x40
 [<ffffffff81268d93>] bus_remove_device+0x73/0xb0
 [<ffffffff81266855>] device_del+0x125/0x1a0
 [<ffffffffa00e2ce6>] usb_disable_device+0x76/0x200 [usbcore]
 [<ffffffffa00da3a8>] usb_disconnect+0xb8/0x170 [usbcore]
 [<ffffffffa00dcacc>] hub_thread+0xbfc/0x1640 [usbcore]
 [<ffffffff8138713a>] ? schedule+0x44a/0x9e0
 [<ffffffff8105ff70>] ? abort_exclusive_wait+0xb0/0xb0
 [<ffffffffa00dbed0>] ? usb_remote_wakeup+0x60/0x60 [usbcore]
 [<ffffffff8105f7a7>] kthread+0x87/0x90
 [<ffffffff8138b464>] kernel_thread_helper+0x4/0x10
 [<ffffffff8105f720>] ? kthread_worker_fn+0x190/0x190
 [<ffffffff8138b460>] ? gs_change+0x13/0x13

Ah -- this stack dump points out the reason for the hang. It looks like that "fix regression..." commit didn't go far enough; I neglected the fact that interfaces can be unbound out of order when a driver claims multiple interfaces.

Adding this patch on top of that commit should fix this. Let me know what you both get.

Alan Stern

 drivers/usb/core/message.c |    9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

Index: usb-3.0/drivers/usb/core/message.c
===================================================================
@@ -1147,6 +1147,14 @@ void usb_disable_device(struct usb_devic
 	 * any drivers bound to them (a key side effect)
 	 */
 	if (dev->actconfig) {
+		/*
+		 * FIXME: In order to avoid self-deadlock involving the
+		 * bandwidth_mutex, we have to mark all the interfaces
+		 * before unregistering any of them.
+		 */
+		for (i = 0; i < dev->actconfig->desc.bNumInterfaces; i++)
+			dev->actconfig->interface[i]->unregistering = 1;
+
 		for (i = 0; i < dev->actconfig->desc.bNumInterfaces; i++) {
 			struct usb_interface	*interface;
 

@@ -1156,7 +1164,6 @@ void usb_disable_device(struct usb_devic
 				continue;
 			dev_dbg(&dev->dev, "unregistering interface %s\n",
 				dev_name(&interface->dev));
-			interface->unregistering = 1;
 			remove_intf_ep_devs(interface);
 			device_del(&interface->dev);
 		}

This one makes usb working after resume from ram (current Linus git + this patch).

Arkadiusz Miśkiewicz        PLD/Linux Team
arekm / maven.pl            http://ftp.pld-linux.org/

Thanks so much for testing.

Alan, care to resend this to me so I can get it to Linus?

greg k-h

Commit e534c5b831c8b8e9f5edee5c8a37753c808b80dc (USB: fix regression occurring during device removal) didn't go far enough. It failed to take into account that when a driver claims multiple interfaces, it may release them all at the same time. As a result, some interfaces can get released before they are unregistered, and we deadlock trying to acquire the bandwidth_mutex that we already own.

This patch (asl478) handles this case by setting the "unregistering" flag on all the interfaces before removing any of them.

---

This should take care of Eric's problem as well as Arkadiusz, since they seemed to be hitting the same thing (cdc_ether claiming multiple interfaces and hanging while releasing them).

Still, we need to rewrite this stuff. A possible race remains, because a driver may try to change an altsetting at the same time as the device is removed. Either the driver's disconnect routine would hang waiting for the altsetting change (which is waiting to acquire the bandwidth_mutex) or else the altsetting change would go through after the driver was unbound from the device. Neither alternative is good.

Alan Stern

 drivers/usb/core/message.c |    9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

Index: usb-3.0/drivers/usb/core/message.c
===================================================================
@@ -1147,6 +1147,14 @@ void usb_disable_device(struct usb_devic
 	 * any drivers bound to them (a key side effect)
 	 */
 	if (dev->actconfig) {
+		/*
+		 * FIXME: In order to avoid self-deadlock involving the
+		 * bandwidth_mutex, we have to mark all the interfaces
+		 * before unregistering any of them.
+		 */
+		for (i = 0; i < dev->actconfig->desc.bNumInterfaces; i++)
+			dev->actconfig->interface[i]->unregistering = 1;
+
 		for (i = 0; i < dev->actconfig->desc.bNumInterfaces; i++) {
 			struct usb_interface	*interface;
 

@@ -1156,7 +1164,6 @@ void usb_disable_device(struct usb_devic
 				continue;
 			dev_dbg(&dev->dev, "unregistering interface %s\n",
 				dev_name(&interface->dev));
-			interface->unregistering = 1;
 			remove_intf_ep_devs(interface);
 			device_del(&interface->dev);
 		}

Op 06-07-11 23:03, Alan Stern schreef:

Great, it works here :-)

Thanks,
Éric