kernel-packages team mailing list archive
-
kernel-packages team
-
Mailing list archive
-
Message #167338
[Bug 1557172] [NEW] khubd/usbhid deadlock(?) creates processes in state D
Public bug reported:
(Note that the attached logs are not a machine exhibiting the issue)
I've observed this issue specifically on Dell's PowerEdge R410 with its
DRAC. I manage quite a few other machines with DRACs and haven't seen
this issue so it may be limited to the R410. I've seen cases of this
both with the precise and trusty kernel.
Basically, what happens is that things that read any info about the
DRAC's usbhid device will block in an uninterruptible state. A quick way
to do this is with "cat
/sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2/manufacturer". This means
that commands like lspci will block as well. The thing is that it
doesn't happen every time, but once it happens the first time all future
reads on the device will block in state D too.
This is also associated with the following from the kernel (first from a precise machine):
[197852.595820] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197857.716899] usb 5-2: device descriptor read/64, error -71
[197857.944966] usb 5-2: device descriptor read/64, error -71
[197858.165020] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197858.285090] usb 5-2: device descriptor read/64, error -71
[197858.513108] usb 5-2: device descriptor read/64, error -71
[197858.733154] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197859.145214] usb 5-2: device not accepting address 2, error -71
[197859.261234] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197859.669322] usb 5-2: device not accepting address 2, error -71
[197859.675357] usb 5-2: USB disconnect, device number 2
[198047.530714] INFO: task khubd:203 blocked for more than 120 seconds.
[198047.537147] Not tainted 3.13.0-74-generic #118~precise1-Ubuntu
[198047.543691] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[198047.551792] khubd D ffff880803fe18a0 0 203 2 0x00000000
[198047.551803] ffff8810036b1c18 0000000000000046 ffff88102fc53180 ffff8810036b1fd8
[198047.551809] 0000000000013180 0000000000013180 ffff881003f7c800 ffff880804634800
[198047.551814] ffff8810036b1c38 ffff8810020908e8 ffff8810020908ec 00000000ffffffff
[198047.551819] Call Trace:
[198047.551828] [<ffffffff81764b59>] schedule+0x29/0x70
[198047.551833] [<ffffffff81764e7e>] schedule_preempt_disabled+0xe/0x10
[198047.551837] [<ffffffff81766cb4>] __mutex_lock_slowpath+0x114/0x1b0
[198047.551845] [<ffffffff8156e66e>] ? usb_alloc_urb+0x1e/0x50
[198047.551848] [<ffffffff81766d73>] mutex_lock+0x23/0x37
[198047.551852] [<ffffffff8156597a>] usb_disconnect+0x5a/0x210
[198047.551857] [<ffffffff8156ff6a>] ? usb_control_msg+0xea/0x110
[198047.551860] [<ffffffff8156833f>] hub_port_connect_change+0xcf/0x9c0
[198047.551864] [<ffffffff81562715>] ? hub_port_status+0xd5/0x120
[198047.551868] [<ffffffff81569094>] hub_events+0x464/0x8c0
[198047.551871] [<ffffffff8176472e>] ? __schedule+0x38e/0x700
[198047.551875] [<ffffffff81569525>] hub_thread+0x35/0x150
[198047.551881] [<ffffffff810b0410>] ? __wake_up_sync+0x20/0x20
[198047.551885] [<ffffffff815694f0>] ? hub_events+0x8c0/0x8c0
[198047.551890] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[198047.551893] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.551898] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[198047.551902] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.551908] INFO: task kworker/9:1:246 blocked for more than 120 seconds.
[198047.558892] Not tainted 3.13.0-74-generic #118~precise1-Ubuntu
[198047.565491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[198047.573524] kworker/9:1 D ffff880803fe18a0 0 246 2 0x00000000
[198047.573547] Workqueue: events hid_reset [usbhid]
[198047.573550] ffff8808011f9788 0000000000000046 ffff88080fc93180 ffff8808011f9fd8
[198047.573555] 0000000000013180 0000000000013180 ffff881003f94800 ffff8808011f0000
[198047.573559] ffff8808011f9798 ffff8808011f98d8 7fffffffffffffff 7fffffffffffffff
[198047.573564] Call Trace:
[198047.573579] [<ffffffff81764b59>] schedule+0x29/0x70
[198047.573582] [<ffffffff81763e25>] schedule_timeout+0x1e5/0x250
[198047.573587] [<ffffffff810a4b1d>] ? wake_affine+0x16d/0x2d0
[198047.573591] [<ffffffff81765df7>] wait_for_completion+0xa7/0x160
[198047.573596] [<ffffffff8109fe00>] ? try_to_wake_up+0x210/0x210
[198047.573602] [<ffffffff81089509>] flush_work+0x29/0x40
[198047.573605] [<ffffffff81085170>] ? start_worker+0x40/0x40
[198047.573609] [<ffffffff8108962c>] __cancel_work_timer+0x9c/0x1b0
[198047.573623] [<ffffffff81089770>] cancel_work_sync+0x10/0x20
[198047.573632] [<ffffffffa00a6a19>] hid_cancel_delayed_stuff+0x29/0x30 [usbhid]
[198047.573640] [<ffffffffa00a88cc>] usbhid_close+0xcc/0x110 [usbhid]
[198047.573650] [<ffffffffa0036772>] hidinput_close+0x22/0x30 [hid]
[198047.573659] [<ffffffff815b3bf1>] input_close_device+0x61/0x90
[198047.573663] [<ffffffff815b9b7f>] evdev_cleanup+0xbf/0xd0
[198047.573670] [<ffffffff815b9bc6>] evdev_disconnect+0x36/0x70
[198047.573674] [<ffffffff815b5b75>] __input_unregister_device+0xc5/0x1a0
[198047.573678] [<ffffffff815b5ca5>] input_unregister_device+0x55/0x80
[198047.573687] [<ffffffffa0036105>] hidinput_disconnect+0x95/0xc0 [hid]
[198047.573695] [<ffffffffa0033548>] hid_disconnect+0x68/0x70 [hid]
[198047.573708] [<ffffffffa0033625>] hid_device_remove+0xd5/0xf0 [hid]
[198047.573720] [<ffffffff814b7c7f>] __device_release_driver+0x7f/0xf0
[198047.573724] [<ffffffff814b7d1c>] device_release_driver+0x2c/0x40
[198047.573728] [<ffffffff814b76c4>] bus_remove_device+0x104/0x170
[198047.573736] [<ffffffff814b46e8>] device_del+0x118/0x1a0
[198047.573744] [<ffffffffa0032af0>] hid_destroy_device+0x30/0x70 [hid]
[198047.573754] [<ffffffffa00a6a4b>] usbhid_disconnect+0x2b/0x50 [usbhid]
[198047.573758] [<ffffffff81573380>] usb_unbind_interface+0x60/0x1b0
[198047.573764] [<ffffffff814b7c7f>] __device_release_driver+0x7f/0xf0
[198047.573768] [<ffffffff814b7d1c>] device_release_driver+0x2c/0x40
[198047.573772] [<ffffffff81573560>] usb_driver_release_interface+0x90/0xa0
[198047.573780] [<ffffffffa00a8c51>] ? hid_post_reset+0x51/0x200 [usbhid]
[198047.573785] [<ffffffff815735a7>] usb_forced_unbind_intf+0x37/0x60
[198047.573788] [<ffffffff81573629>] unbind_marked_interfaces.isra.8+0x59/0x80
[198047.573792] [<ffffffff815737dd>] usb_unbind_and_rebind_marked_interfaces+0x1d/0x30
[198047.573796] [<ffffffff81567c1b>] usb_reset_device+0x15b/0x1d0
[198047.573804] [<ffffffffa00a7e2f>] hid_reset+0x16f/0x1e0 [usbhid]
[198047.573808] [<ffffffff81087c5f>] process_one_work+0x17f/0x4c0
[198047.573811] [<ffffffff81088dbb>] worker_thread+0x11b/0x3d0
[198047.573815] [<ffffffff81088ca0>] ? manage_workers.isra.21+0x190/0x190
[198047.573819] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[198047.573823] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.573827] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[198047.573830] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
And these from a trusty machine (which includes info from one of the stuck processes too):
[1367979.659164] SysRq : Show Blocked State
[1367979.663114] task PC stack pid father
[1367979.669300] khubd D ffff88100054f160 0 203 2 0x00000000
[1367979.676574] ffff88100352fc18 0000000000000046 ffff88080fc93180 ffff88100352ffd8
[1367979.684216] 0000000000013180 0000000000013180 ffff8808049f4800 ffff8808043f4800
[1367979.691855] ffff88100352fc38 ffff881002e100e8 ffff881002e100ec 00000000ffffffff
[1367979.699495] Call Trace:
[1367979.702134] [<ffffffff81764b69>] schedule+0x29/0x70
[1367979.707288] [<ffffffff81764e8e>] schedule_preempt_disabled+0xe/0x10
[1367979.713831] [<ffffffff81766cc4>] __mutex_lock_slowpath+0x114/0x1b0
[1367979.720288] [<ffffffff8156e67e>] ? usb_alloc_urb+0x1e/0x50
[1367979.726049] [<ffffffff81766d83>] mutex_lock+0x23/0x37
[1367979.731376] [<ffffffff8156598a>] usb_disconnect+0x5a/0x210
[1367979.737138] [<ffffffff8156ff7a>] ? usb_control_msg+0xea/0x110
[1367979.743160] [<ffffffff8156834f>] hub_port_connect_change+0xcf/0x9c0
[1367979.749703] [<ffffffff81562725>] ? hub_port_status+0xd5/0x120
[1367979.755724] [<ffffffff815690a4>] hub_events+0x464/0x8c0
[1367979.761223] [<ffffffff8176473e>] ? __schedule+0x38e/0x700
[1367979.766897] [<ffffffff81569535>] hub_thread+0x35/0x150
[1367979.772313] [<ffffffff810b0410>] ? __wake_up_sync+0x20/0x20
[1367979.778160] [<ffffffff81569500>] ? hub_events+0x8c0/0x8c0
[1367979.784942] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[1367979.790008] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367979.796378] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[1367979.801965] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367979.808345] kworker/8:1 D ffff88100054f160 0 329 2 0x00000000
[1367979.815632] Workqueue: events hid_reset [usbhid]
[1367979.820445] ffff881002625788 0000000000000046 ffff88102fc93180 ffff881002625fd8
[1367979.828088] 0000000000013180 0000000000013180 ffff8808049f3000 ffff881002639800
[1367979.835726] ffff881002625798 ffff8810026258d8 7fffffffffffffff 7fffffffffffffff
[1367979.843367] Call Trace:
[1367979.845999] [<ffffffff81764b69>] schedule+0x29/0x70
[1367979.851151] [<ffffffff81763e35>] schedule_timeout+0x1e5/0x250
[1367979.857174] [<ffffffff810aa9cf>] ? enqueue_entity+0x2bf/0x760
[1367979.863196] [<ffffffff81765e07>] wait_for_completion+0xa7/0x160
[1367979.869392] [<ffffffff8109fe00>] ? try_to_wake_up+0x210/0x210
[1367979.875414] [<ffffffff81089509>] flush_work+0x29/0x40
[1367979.880741] [<ffffffff81085170>] ? start_worker+0x40/0x40
[1367979.886415] [<ffffffff8108962c>] __cancel_work_timer+0x9c/0x1b0
[1367979.892609] [<ffffffff81089770>] cancel_work_sync+0x10/0x20
[1367979.898461] [<ffffffffa0072a19>] hid_cancel_delayed_stuff+0x29/0x30 [usbhid]
[1367979.905801] [<ffffffffa00748cc>] usbhid_close+0xcc/0x110 [usbhid]
[1367979.912176] [<ffffffffa0042772>] hidinput_close+0x22/0x30 [hid]
[1367979.918374] [<ffffffff815b3c01>] input_close_device+0x61/0x90
[1367979.924397] [<ffffffff815b9b8f>] evdev_cleanup+0xbf/0xd0
[1367979.929983] [<ffffffff815b9bd6>] evdev_disconnect+0x36/0x70
[1367979.935832] [<ffffffff815b5b85>] __input_unregister_device+0xc5/0x1a0
[1367979.942547] [<ffffffff815b5cb5>] input_unregister_device+0x55/0x80
[1367979.949007] [<ffffffffa0042105>] hidinput_disconnect+0x95/0xc0 [hid]
[1367979.955638] [<ffffffffa003f548>] hid_disconnect+0x68/0x70 [hid]
[1367979.961837] [<ffffffffa003f625>] hid_device_remove+0xd5/0xf0 [hid]
[1367979.968298] [<ffffffff814b7c8f>] __device_release_driver+0x7f/0xf0
[1367979.974752] [<ffffffff814b7d2c>] device_release_driver+0x2c/0x40
[1367979.981095] [<ffffffff814b76d4>] bus_remove_device+0x104/0x170
[1367979.987202] [<ffffffff814b46f8>] device_del+0x118/0x1a0
[1367979.992707] [<ffffffffa003eaf0>] hid_destroy_device+0x30/0x70 [hid]
[1367979.999253] [<ffffffffa0072a4b>] usbhid_disconnect+0x2b/0x50 [usbhid]
[1367980.005968] [<ffffffff81573390>] usb_unbind_interface+0x60/0x1b0
[1367980.012252] [<ffffffff814b7c8f>] __device_release_driver+0x7f/0xf0
[1367980.018710] [<ffffffff814b7d2c>] device_release_driver+0x2c/0x40
[1367980.024992] [<ffffffff81573570>] usb_driver_release_interface+0x90/0xa0
[1367980.031885] [<ffffffffa0074c51>] ? hid_post_reset+0x51/0x200 [usbhid]
[1367980.038603] [<ffffffff815735b7>] usb_forced_unbind_intf+0x37/0x60
[1367980.044971] [<ffffffff81573639>] unbind_marked_interfaces.isra.8+0x59/0x80
[1367980.052121] [<ffffffff815737ed>] usb_unbind_and_rebind_marked_interfaces+0x1d/0x30
[1367980.059981] [<ffffffff81567c2b>] usb_reset_device+0x15b/0x1d0
[1367980.066004] [<ffffffffa0073e2f>] hid_reset+0x16f/0x1e0 [usbhid]
[1367980.072199] [<ffffffff81087c5f>] process_one_work+0x17f/0x4c0
[1367980.078221] [<ffffffff81088dbb>] worker_thread+0x11b/0x3d0
[1367980.083982] [<ffffffff81088ca0>] ? manage_workers.isra.21+0x190/0x190
[1367980.090699] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[1367980.095765] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367980.102132] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[1367980.107719] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367980.114098] python2.7 D ffff88100054f160 0 18303 1 0x00000004
[1367980.121369] ffff881001497d08 0000000000000082 ffff88080fc53180 ffff881001497fd8
[1367980.129007] 0000000000013180 0000000000013180 ffff881003f86000 ffff881001688000
[1367980.136648] 0000881000000024 ffff881002e100e8 ffff881002e100ec 00000000ffffffff
[1367980.144286] Call Trace:
[1367980.146921] [<ffffffff81764b69>] schedule+0x29/0x70
[1367980.152073] [<ffffffff81764e8e>] schedule_preempt_disabled+0xe/0x10
[1367980.158615] [<ffffffff81766cc4>] __mutex_lock_slowpath+0x114/0x1b0
[1367980.165069] [<ffffffff81766d83>] mutex_lock+0x23/0x37
[1367980.170397] [<ffffffff81576a8b>] manufacturer_show+0x2b/0x60
[1367980.176331] [<ffffffff814b4890>] dev_attr_show+0x20/0x60
[1367980.181918] [<ffffffff81766d76>] ? mutex_lock+0x16/0x37
[1367980.187418] [<ffffffff811eec6b>] ? seq_buf_alloc+0x1b/0x50
[1367980.193180] [<ffffffff81242875>] sysfs_seq_show+0x145/0x260
[1367980.199027] [<ffffffff811ef3fb>] seq_read+0xfb/0x3c0
[1367980.204267] [<ffffffff811cbc8b>] vfs_read+0xab/0x180
[1367980.209506] [<ffffffff811cbf12>] SyS_read+0x52/0xa0
[1367980.214657] [<ffffffff8177181d>] system_call_fastpath+0x1a/0x1f
lsusb for the device in question:
$ sudo lsusb -v -d 0624:0248
Bus 005 Device 002: ID 0624:0248 Avocent Corp. Virtual Hub
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.10
bDeviceClass 0 (Defined at Interface level)
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x0624 Avocent Corp.
idProduct 0x0248 Virtual Hub
bcdDevice 0.00
iManufacturer 1 Avocent
iProduct 2 USB Composite Device-0
iSerial 3 20080519
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 59
bNumInterfaces 2
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xc0
Self Powered
MaxPower 2mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 1 Keyboard
iInterface 4 Keyboard
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.00
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 65
Report Descriptors:
** UNAVAILABLE **
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 8
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 2 Mouse
iInterface 5 Mouse
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.00
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 63
Report Descriptors:
** UNAVAILABLE **
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 8
Device Status: 0x0000
(Bus Powered)
And now for my purely speculative analysis of what might be going on
after digging through the code...
There are two devices interacting here, the usbhid that is the keyboard
for the DRAC and the hub that it's connected to.
As a part of the usbhid initialization (usbhid_probe) it creates a
tasklet for hid_reset (I have no idea why, but perhaps it needs to reset
the underlying hid/usb devices to start working) which unloads and
reloads all the parts of the hidusb driver (usb, hid, input, evdev). As
a part of the unload for the usbhid it calls hid_cancel_delayed_stuff
(don't let it fool you, it actually works with a usbhid device, not a
hid device) iff it is no longer opened, which normally it should already
be opened, but...
I haven't been able to confirm this, but I think that if the hub closes
it can close the devices associated with it, which gives us a fun race
condition where if we start the probe for the usbhid device and then the
underlying hub gets removed it will have no instances open, which causes
usbhid to call hid_cancel_delayed_stuff, from its own cancel tasklet.
Unsurprisingly when it does this it ends up waiting on itself forever.
I'm currently working around the issue by adding a udev rule to prevent
the device from being used by setting authorized=0 for it. This
obviously prevents the DRAC from actually working, though.
** Affects: linux (Ubuntu)
Importance: Undecided
Status: Incomplete
** Tags: trusty
** Attachment added: "lspci-vnvn.log"
https://bugs.launchpad.net/bugs/1557172/+attachment/4599247/+files/lspci-vnvn.log
--
You received this bug notification because you are a member of Kernel
Packages, which is subscribed to linux in Ubuntu.
https://bugs.launchpad.net/bugs/1557172
Title:
khubd/usbhid deadlock(?) creates processes in state D
Status in linux package in Ubuntu:
Incomplete
Bug description:
(Note that the attached logs are not a machine exhibiting the issue)
I've observed this issue specifically on Dell's PowerEdge R410 with
its DRAC. I manage quite a few other machines with DRACs and haven't
seen this issue so it may be limited to the R410. I've seen cases of
this both with the precise and trusty kernel.
Basically, what happens is that things that read any info about the
DRAC's usbhid device will block in an uninterruptible state. A quick
way to do this is with "cat
/sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2/manufacturer". This
means that commands like lspci will block as well. The thing is that
it doesn't happen every time, but once it happens the first time all
future reads on the device will block in state D too.
This is also associated with the following from the kernel (first from a precise machine):
[197852.595820] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197857.716899] usb 5-2: device descriptor read/64, error -71
[197857.944966] usb 5-2: device descriptor read/64, error -71
[197858.165020] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197858.285090] usb 5-2: device descriptor read/64, error -71
[197858.513108] usb 5-2: device descriptor read/64, error -71
[197858.733154] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197859.145214] usb 5-2: device not accepting address 2, error -71
[197859.261234] usb 5-2: reset full-speed USB device number 2 using uhci_hcd
[197859.669322] usb 5-2: device not accepting address 2, error -71
[197859.675357] usb 5-2: USB disconnect, device number 2
[198047.530714] INFO: task khubd:203 blocked for more than 120 seconds.
[198047.537147] Not tainted 3.13.0-74-generic #118~precise1-Ubuntu
[198047.543691] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[198047.551792] khubd D ffff880803fe18a0 0 203 2 0x00000000
[198047.551803] ffff8810036b1c18 0000000000000046 ffff88102fc53180 ffff8810036b1fd8
[198047.551809] 0000000000013180 0000000000013180 ffff881003f7c800 ffff880804634800
[198047.551814] ffff8810036b1c38 ffff8810020908e8 ffff8810020908ec 00000000ffffffff
[198047.551819] Call Trace:
[198047.551828] [<ffffffff81764b59>] schedule+0x29/0x70
[198047.551833] [<ffffffff81764e7e>] schedule_preempt_disabled+0xe/0x10
[198047.551837] [<ffffffff81766cb4>] __mutex_lock_slowpath+0x114/0x1b0
[198047.551845] [<ffffffff8156e66e>] ? usb_alloc_urb+0x1e/0x50
[198047.551848] [<ffffffff81766d73>] mutex_lock+0x23/0x37
[198047.551852] [<ffffffff8156597a>] usb_disconnect+0x5a/0x210
[198047.551857] [<ffffffff8156ff6a>] ? usb_control_msg+0xea/0x110
[198047.551860] [<ffffffff8156833f>] hub_port_connect_change+0xcf/0x9c0
[198047.551864] [<ffffffff81562715>] ? hub_port_status+0xd5/0x120
[198047.551868] [<ffffffff81569094>] hub_events+0x464/0x8c0
[198047.551871] [<ffffffff8176472e>] ? __schedule+0x38e/0x700
[198047.551875] [<ffffffff81569525>] hub_thread+0x35/0x150
[198047.551881] [<ffffffff810b0410>] ? __wake_up_sync+0x20/0x20
[198047.551885] [<ffffffff815694f0>] ? hub_events+0x8c0/0x8c0
[198047.551890] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[198047.551893] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.551898] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[198047.551902] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.551908] INFO: task kworker/9:1:246 blocked for more than 120 seconds.
[198047.558892] Not tainted 3.13.0-74-generic #118~precise1-Ubuntu
[198047.565491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[198047.573524] kworker/9:1 D ffff880803fe18a0 0 246 2 0x00000000
[198047.573547] Workqueue: events hid_reset [usbhid]
[198047.573550] ffff8808011f9788 0000000000000046 ffff88080fc93180 ffff8808011f9fd8
[198047.573555] 0000000000013180 0000000000013180 ffff881003f94800 ffff8808011f0000
[198047.573559] ffff8808011f9798 ffff8808011f98d8 7fffffffffffffff 7fffffffffffffff
[198047.573564] Call Trace:
[198047.573579] [<ffffffff81764b59>] schedule+0x29/0x70
[198047.573582] [<ffffffff81763e25>] schedule_timeout+0x1e5/0x250
[198047.573587] [<ffffffff810a4b1d>] ? wake_affine+0x16d/0x2d0
[198047.573591] [<ffffffff81765df7>] wait_for_completion+0xa7/0x160
[198047.573596] [<ffffffff8109fe00>] ? try_to_wake_up+0x210/0x210
[198047.573602] [<ffffffff81089509>] flush_work+0x29/0x40
[198047.573605] [<ffffffff81085170>] ? start_worker+0x40/0x40
[198047.573609] [<ffffffff8108962c>] __cancel_work_timer+0x9c/0x1b0
[198047.573623] [<ffffffff81089770>] cancel_work_sync+0x10/0x20
[198047.573632] [<ffffffffa00a6a19>] hid_cancel_delayed_stuff+0x29/0x30 [usbhid]
[198047.573640] [<ffffffffa00a88cc>] usbhid_close+0xcc/0x110 [usbhid]
[198047.573650] [<ffffffffa0036772>] hidinput_close+0x22/0x30 [hid]
[198047.573659] [<ffffffff815b3bf1>] input_close_device+0x61/0x90
[198047.573663] [<ffffffff815b9b7f>] evdev_cleanup+0xbf/0xd0
[198047.573670] [<ffffffff815b9bc6>] evdev_disconnect+0x36/0x70
[198047.573674] [<ffffffff815b5b75>] __input_unregister_device+0xc5/0x1a0
[198047.573678] [<ffffffff815b5ca5>] input_unregister_device+0x55/0x80
[198047.573687] [<ffffffffa0036105>] hidinput_disconnect+0x95/0xc0 [hid]
[198047.573695] [<ffffffffa0033548>] hid_disconnect+0x68/0x70 [hid]
[198047.573708] [<ffffffffa0033625>] hid_device_remove+0xd5/0xf0 [hid]
[198047.573720] [<ffffffff814b7c7f>] __device_release_driver+0x7f/0xf0
[198047.573724] [<ffffffff814b7d1c>] device_release_driver+0x2c/0x40
[198047.573728] [<ffffffff814b76c4>] bus_remove_device+0x104/0x170
[198047.573736] [<ffffffff814b46e8>] device_del+0x118/0x1a0
[198047.573744] [<ffffffffa0032af0>] hid_destroy_device+0x30/0x70 [hid]
[198047.573754] [<ffffffffa00a6a4b>] usbhid_disconnect+0x2b/0x50 [usbhid]
[198047.573758] [<ffffffff81573380>] usb_unbind_interface+0x60/0x1b0
[198047.573764] [<ffffffff814b7c7f>] __device_release_driver+0x7f/0xf0
[198047.573768] [<ffffffff814b7d1c>] device_release_driver+0x2c/0x40
[198047.573772] [<ffffffff81573560>] usb_driver_release_interface+0x90/0xa0
[198047.573780] [<ffffffffa00a8c51>] ? hid_post_reset+0x51/0x200 [usbhid]
[198047.573785] [<ffffffff815735a7>] usb_forced_unbind_intf+0x37/0x60
[198047.573788] [<ffffffff81573629>] unbind_marked_interfaces.isra.8+0x59/0x80
[198047.573792] [<ffffffff815737dd>] usb_unbind_and_rebind_marked_interfaces+0x1d/0x30
[198047.573796] [<ffffffff81567c1b>] usb_reset_device+0x15b/0x1d0
[198047.573804] [<ffffffffa00a7e2f>] hid_reset+0x16f/0x1e0 [usbhid]
[198047.573808] [<ffffffff81087c5f>] process_one_work+0x17f/0x4c0
[198047.573811] [<ffffffff81088dbb>] worker_thread+0x11b/0x3d0
[198047.573815] [<ffffffff81088ca0>] ? manage_workers.isra.21+0x190/0x190
[198047.573819] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[198047.573823] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[198047.573827] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[198047.573830] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
And these from a trusty machine (which includes info from one of the stuck processes too):
[1367979.659164] SysRq : Show Blocked State
[1367979.663114] task PC stack pid father
[1367979.669300] khubd D ffff88100054f160 0 203 2 0x00000000
[1367979.676574] ffff88100352fc18 0000000000000046 ffff88080fc93180 ffff88100352ffd8
[1367979.684216] 0000000000013180 0000000000013180 ffff8808049f4800 ffff8808043f4800
[1367979.691855] ffff88100352fc38 ffff881002e100e8 ffff881002e100ec 00000000ffffffff
[1367979.699495] Call Trace:
[1367979.702134] [<ffffffff81764b69>] schedule+0x29/0x70
[1367979.707288] [<ffffffff81764e8e>] schedule_preempt_disabled+0xe/0x10
[1367979.713831] [<ffffffff81766cc4>] __mutex_lock_slowpath+0x114/0x1b0
[1367979.720288] [<ffffffff8156e67e>] ? usb_alloc_urb+0x1e/0x50
[1367979.726049] [<ffffffff81766d83>] mutex_lock+0x23/0x37
[1367979.731376] [<ffffffff8156598a>] usb_disconnect+0x5a/0x210
[1367979.737138] [<ffffffff8156ff7a>] ? usb_control_msg+0xea/0x110
[1367979.743160] [<ffffffff8156834f>] hub_port_connect_change+0xcf/0x9c0
[1367979.749703] [<ffffffff81562725>] ? hub_port_status+0xd5/0x120
[1367979.755724] [<ffffffff815690a4>] hub_events+0x464/0x8c0
[1367979.761223] [<ffffffff8176473e>] ? __schedule+0x38e/0x700
[1367979.766897] [<ffffffff81569535>] hub_thread+0x35/0x150
[1367979.772313] [<ffffffff810b0410>] ? __wake_up_sync+0x20/0x20
[1367979.778160] [<ffffffff81569500>] ? hub_events+0x8c0/0x8c0
[1367979.784942] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[1367979.790008] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367979.796378] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[1367979.801965] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367979.808345] kworker/8:1 D ffff88100054f160 0 329 2 0x00000000
[1367979.815632] Workqueue: events hid_reset [usbhid]
[1367979.820445] ffff881002625788 0000000000000046 ffff88102fc93180 ffff881002625fd8
[1367979.828088] 0000000000013180 0000000000013180 ffff8808049f3000 ffff881002639800
[1367979.835726] ffff881002625798 ffff8810026258d8 7fffffffffffffff 7fffffffffffffff
[1367979.843367] Call Trace:
[1367979.845999] [<ffffffff81764b69>] schedule+0x29/0x70
[1367979.851151] [<ffffffff81763e35>] schedule_timeout+0x1e5/0x250
[1367979.857174] [<ffffffff810aa9cf>] ? enqueue_entity+0x2bf/0x760
[1367979.863196] [<ffffffff81765e07>] wait_for_completion+0xa7/0x160
[1367979.869392] [<ffffffff8109fe00>] ? try_to_wake_up+0x210/0x210
[1367979.875414] [<ffffffff81089509>] flush_work+0x29/0x40
[1367979.880741] [<ffffffff81085170>] ? start_worker+0x40/0x40
[1367979.886415] [<ffffffff8108962c>] __cancel_work_timer+0x9c/0x1b0
[1367979.892609] [<ffffffff81089770>] cancel_work_sync+0x10/0x20
[1367979.898461] [<ffffffffa0072a19>] hid_cancel_delayed_stuff+0x29/0x30 [usbhid]
[1367979.905801] [<ffffffffa00748cc>] usbhid_close+0xcc/0x110 [usbhid]
[1367979.912176] [<ffffffffa0042772>] hidinput_close+0x22/0x30 [hid]
[1367979.918374] [<ffffffff815b3c01>] input_close_device+0x61/0x90
[1367979.924397] [<ffffffff815b9b8f>] evdev_cleanup+0xbf/0xd0
[1367979.929983] [<ffffffff815b9bd6>] evdev_disconnect+0x36/0x70
[1367979.935832] [<ffffffff815b5b85>] __input_unregister_device+0xc5/0x1a0
[1367979.942547] [<ffffffff815b5cb5>] input_unregister_device+0x55/0x80
[1367979.949007] [<ffffffffa0042105>] hidinput_disconnect+0x95/0xc0 [hid]
[1367979.955638] [<ffffffffa003f548>] hid_disconnect+0x68/0x70 [hid]
[1367979.961837] [<ffffffffa003f625>] hid_device_remove+0xd5/0xf0 [hid]
[1367979.968298] [<ffffffff814b7c8f>] __device_release_driver+0x7f/0xf0
[1367979.974752] [<ffffffff814b7d2c>] device_release_driver+0x2c/0x40
[1367979.981095] [<ffffffff814b76d4>] bus_remove_device+0x104/0x170
[1367979.987202] [<ffffffff814b46f8>] device_del+0x118/0x1a0
[1367979.992707] [<ffffffffa003eaf0>] hid_destroy_device+0x30/0x70 [hid]
[1367979.999253] [<ffffffffa0072a4b>] usbhid_disconnect+0x2b/0x50 [usbhid]
[1367980.005968] [<ffffffff81573390>] usb_unbind_interface+0x60/0x1b0
[1367980.012252] [<ffffffff814b7c8f>] __device_release_driver+0x7f/0xf0
[1367980.018710] [<ffffffff814b7d2c>] device_release_driver+0x2c/0x40
[1367980.024992] [<ffffffff81573570>] usb_driver_release_interface+0x90/0xa0
[1367980.031885] [<ffffffffa0074c51>] ? hid_post_reset+0x51/0x200 [usbhid]
[1367980.038603] [<ffffffff815735b7>] usb_forced_unbind_intf+0x37/0x60
[1367980.044971] [<ffffffff81573639>] unbind_marked_interfaces.isra.8+0x59/0x80
[1367980.052121] [<ffffffff815737ed>] usb_unbind_and_rebind_marked_interfaces+0x1d/0x30
[1367980.059981] [<ffffffff81567c2b>] usb_reset_device+0x15b/0x1d0
[1367980.066004] [<ffffffffa0073e2f>] hid_reset+0x16f/0x1e0 [usbhid]
[1367980.072199] [<ffffffff81087c5f>] process_one_work+0x17f/0x4c0
[1367980.078221] [<ffffffff81088dbb>] worker_thread+0x11b/0x3d0
[1367980.083982] [<ffffffff81088ca0>] ? manage_workers.isra.21+0x190/0x190
[1367980.090699] [<ffffffff8108ff09>] kthread+0xc9/0xe0
[1367980.095765] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367980.102132] [<ffffffff81771768>] ret_from_fork+0x58/0x90
[1367980.107719] [<ffffffff8108fe40>] ? flush_kthread_worker+0xb0/0xb0
[1367980.114098] python2.7 D ffff88100054f160 0 18303 1 0x00000004
[1367980.121369] ffff881001497d08 0000000000000082 ffff88080fc53180 ffff881001497fd8
[1367980.129007] 0000000000013180 0000000000013180 ffff881003f86000 ffff881001688000
[1367980.136648] 0000881000000024 ffff881002e100e8 ffff881002e100ec 00000000ffffffff
[1367980.144286] Call Trace:
[1367980.146921] [<ffffffff81764b69>] schedule+0x29/0x70
[1367980.152073] [<ffffffff81764e8e>] schedule_preempt_disabled+0xe/0x10
[1367980.158615] [<ffffffff81766cc4>] __mutex_lock_slowpath+0x114/0x1b0
[1367980.165069] [<ffffffff81766d83>] mutex_lock+0x23/0x37
[1367980.170397] [<ffffffff81576a8b>] manufacturer_show+0x2b/0x60
[1367980.176331] [<ffffffff814b4890>] dev_attr_show+0x20/0x60
[1367980.181918] [<ffffffff81766d76>] ? mutex_lock+0x16/0x37
[1367980.187418] [<ffffffff811eec6b>] ? seq_buf_alloc+0x1b/0x50
[1367980.193180] [<ffffffff81242875>] sysfs_seq_show+0x145/0x260
[1367980.199027] [<ffffffff811ef3fb>] seq_read+0xfb/0x3c0
[1367980.204267] [<ffffffff811cbc8b>] vfs_read+0xab/0x180
[1367980.209506] [<ffffffff811cbf12>] SyS_read+0x52/0xa0
[1367980.214657] [<ffffffff8177181d>] system_call_fastpath+0x1a/0x1f
lsusb for the device in question:
$ sudo lsusb -v -d 0624:0248
Bus 005 Device 002: ID 0624:0248 Avocent Corp. Virtual Hub
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 1.10
bDeviceClass 0 (Defined at Interface level)
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x0624 Avocent Corp.
idProduct 0x0248 Virtual Hub
bcdDevice 0.00
iManufacturer 1 Avocent
iProduct 2 USB Composite Device-0
iSerial 3 20080519
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 59
bNumInterfaces 2
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xc0
Self Powered
MaxPower 2mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 1 Keyboard
iInterface 4 Keyboard
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.00
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 65
Report Descriptors:
** UNAVAILABLE **
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 8
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 2 Mouse
iInterface 5 Mouse
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.00
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 63
Report Descriptors:
** UNAVAILABLE **
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 8
Device Status: 0x0000
(Bus Powered)
And now for my purely speculative analysis of what might be going on
after digging through the code...
There are two devices interacting here, the usbhid that is the
keyboard for the DRAC and the hub that it's connected to.
As a part of the usbhid initialization (usbhid_probe) it creates a
tasklet for hid_reset (I have no idea why, but perhaps it needs to
reset the underlying hid/usb devices to start working) which unloads
and reloads all the parts of the hidusb driver (usb, hid, input,
evdev). As a part of the unload for the usbhid it calls
hid_cancel_delayed_stuff (don't let it fool you, it actually works
with a usbhid device, not a hid device) iff it is no longer opened,
which normally it should already be opened, but...
I haven't been able to confirm this, but I think that if the hub
closes it can close the devices associated with it, which gives us a
fun race condition where if we start the probe for the usbhid device
and then the underlying hub gets removed it will have no instances
open, which causes usbhid to call hid_cancel_delayed_stuff, from its
own cancel tasklet. Unsurprisingly when it does this it ends up
waiting on itself forever.
I'm currently working around the issue by adding a udev rule to
prevent the device from being used by setting authorized=0 for it.
This obviously prevents the DRAC from actually working, though.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1557172/+subscriptions
Follow ups
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Ubuntu Foundations Team Bug Bot, 2016-05-30
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Hans Bausewein, 2016-05-30
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Hans Bausewein, 2016-05-30
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Hans Bausewein, 2016-05-22
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Hans Bausewein, 2016-05-22
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Romiras, 2016-05-08
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Romiras, 2016-04-27
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Mike Gerow, 2016-04-26
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Romiras-users, 2016-04-20
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Mike Gerow, 2016-03-18
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Joseph Salisbury, 2016-03-15
-
[Bug 1557172] Re: khubd/usbhid deadlock(?) creates processes in state D
From: Mike Gerow, 2016-03-14
-
[Bug 1557172] Missing required logs.
From: Brad Figg, 2016-03-14
