Bug 193301

Summary: deadlock on open/closing usb devices using stress-ng
Product: Drivers Reporter: Colin Ian King (colin.king)
Component: USBAssignee: Greg Kroah-Hartman (greg)
Status: NEW ---    
Severity: normal    
Priority: P1    
Hardware: PPC-64   
OS: Linux   
Kernel Version: all versions testing, 4.0 through to 4.10.0-rc5 Subsystem:
Regression: No Bisected commit-id:

Description Colin Ian King 2017-01-26 14:37:15 UTC 
It seems we have a race on rapidly open/closing usb devices (specifically a USB mouse).

To reproduce this, I ran stress-ng on a 128 thread ppc64le Power8 box using the fstat stressor. This will open/fstat/close devices in /dev  - it seems that when we have multiple processes closing the USB mouse we hit a deadlock.  See kernel log below.


Refs:
[1] stress-ng: http://kernel.ubuntu.com/~cking/stress-ng/


[  637.975607] usb 1-3.4: reset low-speed USB device number 4 using xhci_hcd
[  664.568574] usb 1-3.4: reset low-speed USB device number 4 using xhci_hcd
[  722.074678] usb 1-3.4: reset low-speed USB device number 4 using xhci_hcd
[  846.839077] INFO: task kworker/112:1:1148 blocked for more than 120 seconds.
[  846.839342]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  846.839405] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.839477] kworker/112:1   D    0  1148      2 0x00000800
[  846.839486] Workqueue: events __usb_queue_reset_device
[  846.839488] Call Trace:
[  846.839491] [c0000007633f7610] [c0000007633f76d0] 0xc0000007633f76d0 (unreliable)
[  846.839497] [c0000007633f77e0] [c00000000001bf40] __switch_to+0x2c0/0x450
[  846.839501] [c0000007633f7840] [c000000000b86bb4] __schedule+0x334/0xac0
[  846.839504] [c0000007633f7900] [c000000000b87388] schedule+0x48/0xc0
[  846.839508] [c0000007633f7930] [c000000000896534] usb_kill_urb+0xf4/0x130
[  846.839511] [c0000007633f79a0] [c0000000008944c0] usb_hcd_flush_endpoint+0x120/0x230
[  846.839514] [c0000007633f7a50] [c000000000898e00] usb_disable_endpoint+0x80/0x110
[  846.839518] [c0000007633f7a90] [c000000000898f00] usb_disable_interface+0x70/0xa0
[  846.839521] [c0000007633f7ad0] [c000000000889840] usb_reset_and_verify_device+0x520/0x7a0
[  846.839524] [c0000007633f7bb0] [c000000000889cb4] usb_reset_device+0x1f4/0x3d0
[  846.839527] [c0000007633f7c50] [c000000000898a08] __usb_queue_reset_device+0x58/0x90
[  846.839531] [c0000007633f7c90] [c0000000000f6368] process_one_work+0x1c8/0x570
[  846.839534] [c0000007633f7d20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[  846.839538] [c0000007633f7dc0] [c0000000000ff964] kthread+0x154/0x1a0
[  846.839542] [c0000007633f7e30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[  846.839583] INFO: task kworker/112:2:6031 blocked for more than 120 seconds.
[  846.839755]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  846.839813] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.839882] kworker/112:2   D    0  6031      2 0x00000800
[  846.839887] Workqueue: usb_hub_wq hub_event
[  846.839889] Call Trace:
[  846.839891] [c00000076d71f6b0] [c00000076d71f770] 0xc00000076d71f770 (unreliable)
[  846.839895] [c00000076d71f880] [c00000000001bf40] __switch_to+0x2c0/0x450
[  846.839898] [c00000076d71f8e0] [c000000000b86bb4] __schedule+0x334/0xac0
[  846.839901] [c00000076d71f9a0] [c000000000b87388] schedule+0x48/0xc0
[  846.839904] [c00000076d71f9d0] [c000000000b878b0] schedule_preempt_disabled+0x20/0x30
[  846.839907] [c00000076d71f9f0] [c000000000b88ec0] __mutex_lock.isra.0+0x2b0/0xd80
[  846.839910] [c00000076d71fb20] [c00000000088d860] hub_event+0x4e0/0x1740
[  846.839913] [c00000076d71fc90] [c0000000000f6368] process_one_work+0x1c8/0x570
[  846.839916] [c00000076d71fd20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[  846.839919] [c00000076d71fdc0] [c0000000000ff964] kthread+0x154/0x1a0
[  846.839923] [c00000076d71fe30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[  846.839926] INFO: task stress-ng-fstat:6286 blocked for more than 120 seconds.
[  846.839997]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  846.840055] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.840125] stress-ng-fstat D    0  6286   6174 0x00040002
[  846.840128] Call Trace:
[  846.840130] [c0000006efcbf860] [c0000006efcbf920] 0xc0000006efcbf920 (unreliable)
[  846.840134] [c0000006efcbfa30] [c00000000001bf40] __switch_to+0x2c0/0x450
[  846.840137] [c0000006efcbfa90] [c000000000b86bb4] __schedule+0x334/0xac0
[  846.840140] [c0000006efcbfb50] [c000000000b87388] schedule+0x48/0xc0
[  846.840143] [c0000006efcbfb80] [c000000000896534] usb_kill_urb+0xf4/0x130
[  846.840149] [c0000006efcbfbf0] [d00000000a0006f8] usbhid_close+0x108/0x150 [usbhid]
[  846.840156] [c0000006efcbfc30] [d000000009ee59fc] hidinput_close+0x3c/0x60 [hid]
[  846.840159] [c0000006efcbfc60] [c000000000917cbc] input_close_device+0x7c/0xd0
[  846.840163] [c0000006efcbfca0] [c00000000091f178] mousedev_close_device+0x88/0xb0
[  846.840166] [c0000006efcbfcd0] [c00000000091f248] mixdev_close_devices+0xa8/0xf0
[  846.840170] [c0000006efcbfd10] [c0000000009206a0] mousedev_release+0xa0/0xd0
[  846.840174] [c0000006efcbfd50] [c0000000003421a4] __fput+0xe4/0x310
[  846.840177] [c0000006efcbfdb0] [c0000000000fc750] task_work_run+0x130/0x190
[  846.840181] [c0000006efcbfe00] [c00000000001db64] do_notify_resume+0xe4/0xf0
[  846.840184] [c0000006efcbfe30] [c00000000000b744] ret_from_except_lite+0x70/0x74
[  967.671042] INFO: task kworker/112:1:1148 blocked for more than 120 seconds.
[  967.671283]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  967.671341] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  967.671412] kworker/112:1   D    0  1148      2 0x00000800
[  967.671419] Workqueue: events __usb_queue_reset_device
[  967.671421] Call Trace:
[  967.671423] [c0000007633f7610] [c0000007633f76d0] 0xc0000007633f76d0 (unreliable)
[  967.671428] [c0000007633f77e0] [c00000000001bf40] __switch_to+0x2c0/0x450
[  967.671432] [c0000007633f7840] [c000000000b86bb4] __schedule+0x334/0xac0
[  967.671435] [c0000007633f7900] [c000000000b87388] schedule+0x48/0xc0
[  967.671439] [c0000007633f7930] [c000000000896534] usb_kill_urb+0xf4/0x130
[  967.671442] [c0000007633f79a0] [c0000000008944c0] usb_hcd_flush_endpoint+0x120/0x230
[  967.671446] [c0000007633f7a50] [c000000000898e00] usb_disable_endpoint+0x80/0x110
[  967.671449] [c0000007633f7a90] [c000000000898f00] usb_disable_interface+0x70/0xa0
[  967.671452] [c0000007633f7ad0] [c000000000889840] usb_reset_and_verify_device+0x520/0x7a0
[  967.671455] [c0000007633f7bb0] [c000000000889cb4] usb_reset_device+0x1f4/0x3d0
[  967.671458] [c0000007633f7c50] [c000000000898a08] __usb_queue_reset_device+0x58/0x90
[  967.671462] [c0000007633f7c90] [c0000000000f6368] process_one_work+0x1c8/0x570
[  967.671465] [c0000007633f7d20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[  967.671468] [c0000007633f7dc0] [c0000000000ff964] kthread+0x154/0x1a0
[  967.671472] [c0000007633f7e30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[  967.671505] INFO: task kworker/112:2:6031 blocked for more than 120 seconds.
[  967.671673]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  967.671732] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  967.671803] kworker/112:2   D    0  6031      2 0x00000800
[  967.671807] Workqueue: usb_hub_wq hub_event
[  967.671809] Call Trace:
[  967.671811] [c00000076d71f6b0] [c00000076d71f770] 0xc00000076d71f770 (unreliable)
[  967.671815] [c00000076d71f880] [c00000000001bf40] __switch_to+0x2c0/0x450
[  967.671818] [c00000076d71f8e0] [c000000000b86bb4] __schedule+0x334/0xac0
[  967.671821] [c00000076d71f9a0] [c000000000b87388] schedule+0x48/0xc0
[  967.671824] [c00000076d71f9d0] [c000000000b878b0] schedule_preempt_disabled+0x20/0x30
[  967.671827] [c00000076d71f9f0] [c000000000b88ec0] __mutex_lock.isra.0+0x2b0/0xd80
[  967.671830] [c00000076d71fb20] [c00000000088d860] hub_event+0x4e0/0x1740
[  967.671833] [c00000076d71fc90] [c0000000000f6368] process_one_work+0x1c8/0x570
[  967.671836] [c00000076d71fd20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[  967.671839] [c00000076d71fdc0] [c0000000000ff964] kthread+0x154/0x1a0
[  967.671843] [c00000076d71fe30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[  967.671846] INFO: task stress-ng-fstat:6286 blocked for more than 120 seconds.
[  967.671915]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[  967.671975] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  967.672046] stress-ng-fstat D    0  6286   6174 0x00040002
[  967.672048] Call Trace:
[  967.672050] [c0000006efcbf860] [c0000006efcbf920] 0xc0000006efcbf920 (unreliable)
[  967.672054] [c0000006efcbfa30] [c00000000001bf40] __switch_to+0x2c0/0x450
[  967.672057] [c0000006efcbfa90] [c000000000b86bb4] __schedule+0x334/0xac0
[  967.672060] [c0000006efcbfb50] [c000000000b87388] schedule+0x48/0xc0
[  967.672063] [c0000006efcbfb80] [c000000000896534] usb_kill_urb+0xf4/0x130
[  967.672068] [c0000006efcbfbf0] [d00000000a0006f8] usbhid_close+0x108/0x150 [usbhid]
[  967.672073] [c0000006efcbfc30] [d000000009ee59fc] hidinput_close+0x3c/0x60 [hid]
[  967.672077] [c0000006efcbfc60] [c000000000917cbc] input_close_device+0x7c/0xd0
[  967.672080] [c0000006efcbfca0] [c00000000091f178] mousedev_close_device+0x88/0xb0
[  967.672084] [c0000006efcbfcd0] [c00000000091f248] mixdev_close_devices+0xa8/0xf0
[  967.672087] [c0000006efcbfd10] [c0000000009206a0] mousedev_release+0xa0/0xd0
[  967.672091] [c0000006efcbfd50] [c0000000003421a4] __fput+0xe4/0x310
[  967.672094] [c0000006efcbfdb0] [c0000000000fc750] task_work_run+0x130/0x190
[  967.672098] [c0000006efcbfe00] [c00000000001db64] do_notify_resume+0xe4/0xf0
[  967.672102] [c0000006efcbfe30] [c00000000000b744] ret_from_except_lite+0x70/0x74
[ 1088.503052] INFO: task kworker/112:1:1148 blocked for more than 120 seconds.
[ 1088.503322]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[ 1088.503389] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1088.503599] kworker/112:1   D    0  1148      2 0x00000800
[ 1088.503606] Workqueue: events __usb_queue_reset_device
[ 1088.503608] Call Trace:
[ 1088.503611] [c0000007633f7610] [c0000007633f76d0] 0xc0000007633f76d0 (unreliable)
[ 1088.503616] [c0000007633f77e0] [c00000000001bf40] __switch_to+0x2c0/0x450
[ 1088.503619] [c0000007633f7840] [c000000000b86bb4] __schedule+0x334/0xac0
[ 1088.503622] [c0000007633f7900] [c000000000b87388] schedule+0x48/0xc0
[ 1088.503625] [c0000007633f7930] [c000000000896534] usb_kill_urb+0xf4/0x130
[ 1088.503629] [c0000007633f79a0] [c0000000008944c0] usb_hcd_flush_endpoint+0x120/0x230
[ 1088.503632] [c0000007633f7a50] [c000000000898e00] usb_disable_endpoint+0x80/0x110
[ 1088.503635] [c0000007633f7a90] [c000000000898f00] usb_disable_interface+0x70/0xa0
[ 1088.503638] [c0000007633f7ad0] [c000000000889840] usb_reset_and_verify_device+0x520/0x7a0
[ 1088.503641] [c0000007633f7bb0] [c000000000889cb4] usb_reset_device+0x1f4/0x3d0
[ 1088.503644] [c0000007633f7c50] [c000000000898a08] __usb_queue_reset_device+0x58/0x90
[ 1088.503648] [c0000007633f7c90] [c0000000000f6368] process_one_work+0x1c8/0x570
[ 1088.503651] [c0000007633f7d20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[ 1088.503654] [c0000007633f7dc0] [c0000000000ff964] kthread+0x154/0x1a0
[ 1088.503658] [c0000007633f7e30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[ 1088.503687] INFO: task kworker/112:2:6031 blocked for more than 120 seconds.
[ 1088.503761]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[ 1088.503820] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1088.503890] kworker/112:2   D    0  6031      2 0x00000800
[ 1088.503894] Workqueue: usb_hub_wq hub_event
[ 1088.503896] Call Trace:
[ 1088.503898] [c00000076d71f6b0] [c00000076d71f770] 0xc00000076d71f770 (unreliable)
[ 1088.503902] [c00000076d71f880] [c00000000001bf40] __switch_to+0x2c0/0x450
[ 1088.503905] [c00000076d71f8e0] [c000000000b86bb4] __schedule+0x334/0xac0
[ 1088.503908] [c00000076d71f9a0] [c000000000b87388] schedule+0x48/0xc0
[ 1088.503911] [c00000076d71f9d0] [c000000000b878b0] schedule_preempt_disabled+0x20/0x30
[ 1088.503914] [c00000076d71f9f0] [c000000000b88ec0] __mutex_lock.isra.0+0x2b0/0xd80
[ 1088.503917] [c00000076d71fb20] [c00000000088d860] hub_event+0x4e0/0x1740
[ 1088.503920] [c00000076d71fc90] [c0000000000f6368] process_one_work+0x1c8/0x570
[ 1088.503923] [c00000076d71fd20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[ 1088.503926] [c00000076d71fdc0] [c0000000000ff964] kthread+0x154/0x1a0
[ 1088.503930] [c00000076d71fe30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
[ 1088.503933] INFO: task stress-ng-fstat:6286 blocked for more than 120 seconds.
[ 1088.504004]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[ 1088.504062] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1088.504132] stress-ng-fstat D    0  6286   6174 0x00040002
[ 1088.504134] Call Trace:
[ 1088.504136] [c0000006efcbf860] [c0000006efcbf920] 0xc0000006efcbf920 (unreliable)
[ 1088.504140] [c0000006efcbfa30] [c00000000001bf40] __switch_to+0x2c0/0x450
[ 1088.504143] [c0000006efcbfa90] [c000000000b86bb4] __schedule+0x334/0xac0
[ 1088.504146] [c0000006efcbfb50] [c000000000b87388] schedule+0x48/0xc0
[ 1088.504149] [c0000006efcbfb80] [c000000000896534] usb_kill_urb+0xf4/0x130
[ 1088.504154] [c0000006efcbfbf0] [d00000000a0006f8] usbhid_close+0x108/0x150 [usbhid]
[ 1088.504161] [c0000006efcbfc30] [d000000009ee59fc] hidinput_close+0x3c/0x60 [hid]
[ 1088.504164] [c0000006efcbfc60] [c000000000917cbc] input_close_device+0x7c/0xd0
[ 1088.504168] [c0000006efcbfca0] [c00000000091f178] mousedev_close_device+0x88/0xb0
[ 1088.504171] [c0000006efcbfcd0] [c00000000091f248] mixdev_close_devices+0xa8/0xf0
[ 1088.504175] [c0000006efcbfd10] [c0000000009206a0] mousedev_release+0xa0/0xd0
[ 1088.504179] [c0000006efcbfd50] [c0000000003421a4] __fput+0xe4/0x310
[ 1088.504182] [c0000006efcbfdb0] [c0000000000fc750] task_work_run+0x130/0x190
[ 1088.504186] [c0000006efcbfe00] [c00000000001db64] do_notify_resume+0xe4/0xf0
[ 1088.504189] [c0000006efcbfe30] [c00000000000b744] ret_from_except_lite+0x70/0x74
[ 1209.335091] INFO: task kworker/112:1:1148 blocked for more than 120 seconds.
[ 1209.335359]       Tainted: G        W       4.10.0-rc5-next-20170125+ #1
[ 1209.335427] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1209.335637] kworker/112:1   D    0  1148      2 0x00000800
[ 1209.335646] Workqueue: events __usb_queue_reset_device
[ 1209.335649] Call Trace:
[ 1209.335651] [c0000007633f7610] [c0000007633f76d0] 0xc0000007633f76d0 (unreliable)
[ 1209.335658] [c0000007633f77e0] [c00000000001bf40] __switch_to+0x2c0/0x450
[ 1209.335662] [c0000007633f7840] [c000000000b86bb4] __schedule+0x334/0xac0
[ 1209.335665] [c0000007633f7900] [c000000000b87388] schedule+0x48/0xc0
[ 1209.335668] [c0000007633f7930] [c000000000896534] usb_kill_urb+0xf4/0x130
[ 1209.335671] [c0000007633f79a0] [c0000000008944c0] usb_hcd_flush_endpoint+0x120/0x230
[ 1209.335675] [c0000007633f7a50] [c000000000898e00] usb_disable_endpoint+0x80/0x110
[ 1209.335678] [c0000007633f7a90] [c000000000898f00] usb_disable_interface+0x70/0xa0
[ 1209.335682] [c0000007633f7ad0] [c000000000889840] usb_reset_and_verify_device+0x520/0x7a0
[ 1209.335684] [c0000007633f7bb0] [c000000000889cb4] usb_reset_device+0x1f4/0x3d0
[ 1209.335688] [c0000007633f7c50] [c000000000898a08] __usb_queue_reset_device+0x58/0x90
[ 1209.335692] [c0000007633f7c90] [c0000000000f6368] process_one_work+0x1c8/0x570
[ 1209.335695] [c0000007633f7d20] [c0000000000f67b8] worker_thread+0xa8/0x5d0
[ 1209.335698] [c0000007633f7dc0] [c0000000000ff964] kthread+0x154/0x1a0
[ 1209.335702] [c0000007633f7e30] [c00000000000b4e8] ret_from_kernel_thread+0x5c/0x74
Comment 1 Colin Ian King 2017-01-26 14:40:43 UTC 
Devices in question are:

Bus 001 Device 004: ID 046b:ff10 American Megatrends, Inc. Virtual Keyboard and Mouse
Comment 2 Colin Ian King 2017-01-26 14:48:59 UTC 
I'm going to see if quirking this device helps
Comment 3 Greg Kroah-Hartman 2017-01-26 15:00:49 UTC 
On Thu, Jan 26, 2017 at 02:37:15PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=193301
> 
>             Bug ID: 193301
>            Summary: deadlock on open/closing usb devices using stress-ng
>            Product: Drivers
>            Version: 2.5
>     Kernel Version: all versions testing, 4.0 through to 4.10.0-rc5

All USB bugs should be sent to the linux-usb@vger.kernel.org mailing
list, and not entered into bugzilla.  Please bring this issue up there,
if it is still a problem in the latest kernel release.