Skip to contentSkip to conversation

3.0-rc6: USB khubd deadlock when hub is powered down

DISCUSSION Stefan Richter 4 participants 9 messages Jul 7, 2011 – Jul 8, 2011 USB

lore
Share & tools
lore
#0 lore raw

Yesterday I updated from 3.0-rc4 to 3.0-rc6. I have got an LCD monitor with integrated USB hub and card reader. Besides the card reader, I had a keyboard and two mice attached to that integrated hub.

When I switched off the monitor yesterday, I go the following deadlock. I noticed it today when I switched the monitor back on and the USB subsystem was dead.

Note, this is not necessarily a 3.0-rc4...3.0-rc6 regression. USB device unplugging has been unstable for me for several kernel releases. (Although the major culprit hasn't been the USB subsystem but the SCSI and maybe block subsystems which nowadays handle storage device removal in Windows 95 fashion.)

So, here is last night's deadlock:

Jul  7 00:48:44 stein kernel: usb 1-3: USB disconnect, device number 2
Jul  7 00:48:44 stein kernel: usb 1-3.1: USB disconnect, device number 3
Jul  7 00:48:44 stein kernel: usb 1-3.1.1: USB disconnect, device number 6
Jul  7 00:48:44 stein kernel: generic-usb 0003:046D:C518.0005: can't reset device, 0000:00:12.2-3.1.3/input0, status -71
Jul  7 00:48:44 stein kernel: generic-usb 0003:046D:C042.0001: can't reset device, 0000:00:12.2-3.2/input0, status -71
Jul  7 00:48:44 stein kernel: generic-usb 0003:1267:0103.0003: can't reset device, 0000:00:12.2-3.3/input0, status -71
Jul  7 00:48:44 stein kernel: usb 1-3: clear tt 2 (0040) error -19
Jul  7 00:48:44 stein kernel: usb 1-3: clear tt 3 (0050) error -19
Jul  7 00:48:44 stein kernel: usb 1-3.1: clear tt 1 (0070) error -19
Jul  7 00:48:44 stein kernel: usb 1-3.1.3: USB disconnect, device number 7
Jul  7 00:48:44 stein kernel: usb 1-3.2: USB disconnect, device number 4
Jul  7 00:48:44 stein kernel: usb 1-3.3: USB disconnect, device number 5
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: =============================================
Jul  7 00:48:44 stein kernel: [ INFO: possible recursive locking detected ]
Jul  7 00:48:44 stein kernel: 3.0.0-rc6 #9
Jul  7 00:48:44 stein kernel: ---------------------------------------------
Jul  7 00:48:44 stein kernel: khubd/303 is trying to acquire lock:
Jul  7 00:48:44 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: but task is already holding lock:
Jul  7 00:48:44 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: other info that might help us debug this:
Jul  7 00:48:44 stein kernel: Possible unsafe locking scenario:
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: CPU0
Jul  7 00:48:44 stein kernel: ----
Jul  7 00:48:44 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 00:48:44 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: *** DEADLOCK ***
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: May be due to missing lock nesting notation
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: 4 locks held by khubd/303:
Jul  7 00:48:44 stein kernel: #0:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff8129a891>] hub_thread+0xdf/0xe5a
Jul  7 00:48:44 stein kernel: #1:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff81299d3c>] usb_disconnect+0x59/0x140
Jul  7 00:48:44 stein kernel: #2:  (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 00:48:44 stein kernel: #3:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff812674fe>] device_release_driver+0x18/0x2d
Jul  7 00:48:44 stein kernel: 
Jul  7 00:48:44 stein kernel: stack backtrace:
Jul  7 00:48:44 stein kernel: Pid: 303, comm: khubd Not tainted 3.0.0-rc6 #9
Jul  7 00:48:44 stein kernel: Call Trace:
Jul  7 00:48:44 stein kernel: [<ffffffff8105cfaf>] __lock_acquire+0x169b/0x1734
Jul  7 00:48:44 stein kernel: [<ffffffff8105a1ff>] ? mark_held_locks+0x52/0x70
Jul  7 00:48:44 stein kernel: [<ffffffff8102e603>] ? sub_preempt_count+0x92/0xa6
Jul  7 00:48:44 stein kernel: [<ffffffff8134fcc1>] ? _raw_spin_unlock_irq+0x36/0x53
Jul  7 00:48:44 stein kernel: [<ffffffff810465eb>] ? wait_on_cpu_work+0x6a/0x99
Jul  7 00:48:44 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 00:48:44 stein kernel: [<ffffffff8105d471>] lock_acquire+0x57/0x6d
Jul  7 00:48:44 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 00:48:44 stein kernel: [<ffffffff8102e6c4>] ? add_preempt_count+0xad/0xb2
Jul  7 00:48:44 stein kernel: [<ffffffff8134e711>] mutex_lock_nested+0x5e/0x2f9
Jul  7 00:48:44 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 00:48:44 stein kernel: [<ffffffff810466e1>] ? wait_on_work+0xc7/0x115
Jul  7 00:48:44 stein kernel: [<ffffffff8104661a>] ? wait_on_cpu_work+0x99/0x99
Jul  7 00:48:44 stein kernel: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 00:48:44 stein kernel: [<ffffffff81046803>] ? __cancel_work_timer+0xd4/0x11d
Jul  7 00:48:44 stein kernel: [<ffffffff812a099b>] usb_unbind_interface+0x93/0xd1
Jul  7 00:48:44 stein kernel: [<ffffffff812673e6>] __device_release_driver+0x67/0xb0
Jul  7 00:48:44 stein kernel: [<ffffffff81267506>] device_release_driver+0x20/0x2d
Jul  7 00:48:44 stein kernel: [<ffffffff81266a24>] bus_remove_device+0xb1/0xc6
Jul  7 00:48:44 stein kernel: [<ffffffff812654fa>] device_del+0x11b/0x187
Jul  7 00:48:44 stein kernel: [<ffffffff8129e81b>] usb_disable_device+0x55/0x14b
Jul  7 00:48:44 stein kernel: [<ffffffff81299d87>] usb_disconnect+0xa4/0x140
Jul  7 00:48:44 stein kernel: [<ffffffff8129acef>] hub_thread+0x53d/0xe5a
Jul  7 00:48:44 stein kernel: [<ffffffff8134d259>] ? schedule+0x878/0x8b0
Jul  7 00:48:44 stein kernel: [<ffffffff8104b06d>] ? wake_up_bit+0x25/0x25
Jul  7 00:48:44 stein kernel: [<ffffffff8134fd24>] ? _raw_spin_unlock_irqrestore+0x46/0x64
Jul  7 00:48:44 stein kernel: [<ffffffff8129a7b2>] ? hub_probe+0x7f3/0x7f3
Jul  7 00:48:44 stein kernel: [<ffffffff8104acca>] kthread+0x7d/0x85
Jul  7 00:48:44 stein kernel: [<ffffffff81351594>] kernel_thread_helper+0x4/0x10
Jul  7 00:48:44 stein kernel: [<ffffffff8102e4f5>] ? finish_task_switch+0x42/0xbe
Jul  7 00:48:44 stein kernel: [<ffffffff813500c4>] ? retint_restore_args+0xe/0xe
Jul  7 00:48:44 stein kernel: [<ffffffff8104ac4d>] ? __init_kthread_worker+0x56/0x56
Jul  7 00:48:44 stein kernel: [<ffffffff81351590>] ? gs_change+0xb/0xb
Jul  7 00:51:26 stein kernel: INFO: task khubd:303 blocked for more than 120 seconds.
Jul  7 00:51:26 stein kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul  7 00:51:26 stein kernel: khubd           D 0000000000000000     0   303      2 0x00000000
Jul  7 00:51:26 stein kernel: ffff88021e3c3af0 0000000000000046 ffffffff8134ccf0 ffffffff8194c2d0
Jul  7 00:51:26 stein kernel: ffff88021e1e6900 ffff88021e3c2010 ffff88021e1e6900 ffff88021e3c3fd8
Jul  7 00:51:26 stein kernel: 00000000000102c0 0000000000004000 ffff88021e3c3fd8 00000000000102c0
Jul  7 00:51:26 stein kernel: Call Trace:
Jul  7 00:51:26 stein kernel: [<ffffffff8134ccf0>] ? schedule+0x30f/0x8b0
Jul  7 00:51:26 stein kernel: [<ffffffff8102e603>] ? sub_preempt_count+0x92/0xa6
Jul  7 00:51:26 stein kernel: [<ffffffff8134fcc1>] ? _raw_spin_unlock_irq+0x36/0x53
Jul  7 00:51:26 stein kernel: [<ffffffff810465eb>] ? wait_on_cpu_work+0x6a/0x99
Jul  7 00:51:26 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 00:51:26 stein kernel: [<ffffffff8134e857>] mutex_lock_nested+0x1a4/0x2f9
Jul  7 00:51:26 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 00:51:26 stein kernel: [<ffffffff8104661a>] ? wait_on_cpu_work+0x99/0x99
Jul  7 00:51:26 stein kernel: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 00:51:26 stein kernel: [<ffffffff81046803>] ? __cancel_work_timer+0xd4/0x11d
Jul  7 00:51:26 stein kernel: [<ffffffff812a099b>] usb_unbind_interface+0x93/0xd1
Jul  7 00:51:26 stein kernel: [<ffffffff812673e6>] __device_release_driver+0x67/0xb0
Jul  7 00:51:26 stein kernel: [<ffffffff81267506>] device_release_driver+0x20/0x2d
Jul  7 00:51:26 stein kernel: [<ffffffff81266a24>] bus_remove_device+0xb1/0xc6
Jul  7 00:51:26 stein kernel: [<ffffffff812654fa>] device_del+0x11b/0x187
Jul  7 00:51:26 stein kernel: [<ffffffff8129e81b>] usb_disable_device+0x55/0x14b
Jul  7 00:51:26 stein kernel: [<ffffffff81299d87>] usb_disconnect+0xa4/0x140
Jul  7 00:51:26 stein kernel: [<ffffffff8129acef>] hub_thread+0x53d/0xe5a
Jul  7 00:51:26 stein kernel: [<ffffffff8134d259>] ? schedule+0x878/0x8b0
Jul  7 00:51:26 stein kernel: [<ffffffff8104b06d>] ? wake_up_bit+0x25/0x25
Jul  7 00:51:26 stein kernel: [<ffffffff8134fd24>] ? _raw_spin_unlock_irqrestore+0x46/0x64
Jul  7 00:51:26 stein kernel: [<ffffffff8129a7b2>] ? hub_probe+0x7f3/0x7f3
Jul  7 00:51:26 stein kernel: [<ffffffff8104acca>] kthread+0x7d/0x85
Jul  7 00:51:26 stein kernel: [<ffffffff81351594>] kernel_thread_helper+0x4/0x10
Jul  7 00:51:26 stein kernel: [<ffffffff8102e4f5>] ? finish_task_switch+0x42/0xbe
Jul  7 00:51:26 stein kernel: [<ffffffff813500c4>] ? retint_restore_args+0xe/0xe
Jul  7 00:51:26 stein kernel: [<ffffffff8104ac4d>] ? __init_kthread_worker+0x56/0x56
Jul  7 00:51:26 stein kernel: [<ffffffff81351590>] ? gs_change+0xb/0xb
Jul  7 00:51:26 stein kernel: INFO: lockdep is turned off.
Signature · 3 lines
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/
#1 lore raw
Quoted 9 lines · On Jul 07 Stefan Richter wrote:

Yesterday I updated from 3.0-rc4 to 3.0-rc6. I have got an LCD monitor with integrated USB hub and card reader. Besides the card reader, I had a keyboard and two mice attached to that integrated hub.

When I switched off the monitor yesterday, I go the following deadlock. I noticed it today when I switched the monitor back on and the USB subsystem was dead.

Note, this is not necessarily a 3.0-rc4...3.0-rc6 regression.

It appears to be a regression from -rc4 to -rc6. At the second occasion that I switched the monitor off while running 3.0-rc6, the same happened again. (IOW judging from the mere two tries I did so far, this issue is 100% reproducible.)

khubd locked up; no subsequent device re-attachments were recognized; only an USB mouse that was attached to a motherboard USB port already before the deadlock continued to let me move the pointer.

Jul  7 15:08:41 stein kernel: usb 1-3.2: USB disconnect, device number 4
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0005: can't reset device, 0000:00:12.2-3.3/input0, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: hub 1-3:1.0: hub_port_status failed (err = -71)
Jul  7 15:08:41 stein kernel: hub 1-3:1.0: connect-debounce failed, port 2 disabled
Jul  7 15:08:41 stein kernel: usb 1-3: USB disconnect, device number 2
Jul  7 15:08:41 stein kernel: usb 1-3.1: USB disconnect, device number 3
Jul  7 15:08:41 stein kernel: usb 1-3.1.1: USB disconnect, device number 6
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0005: can't reset device, 0000:00:12.2-3.3/input0, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -19
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -19
Jul  7 15:08:41 stein kernel: usb 1-3.3: USB disconnect, device number 5
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: =============================================
Jul  7 15:08:42 stein kernel: [ INFO: possible recursive locking detected ]
Jul  7 15:08:42 stein kernel: 3.0.0-rc6 #9
Jul  7 15:08:42 stein kernel: ---------------------------------------------
Jul  7 15:08:42 stein kernel: khubd/303 is trying to acquire lock:
Jul  7 15:08:42 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: but task is already holding lock:
Jul  7 15:08:42 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: other info that might help us debug this:
Jul  7 15:08:42 stein kernel: Possible unsafe locking scenario:
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: CPU0
Jul  7 15:08:42 stein kernel: ----
Jul  7 15:08:42 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 15:08:42 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: *** DEADLOCK ***
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: May be due to missing lock nesting notation
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: 4 locks held by khubd/303:
Jul  7 15:08:42 stein kernel: #0:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff8129a891>] hub_thread+0xdf/0xe5a
Jul  7 15:08:42 stein kernel: #1:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff81299d3c>] usb_disconnect+0x59/0x140
Jul  7 15:08:42 stein kernel: #2:  (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 15:08:42 stein kernel: #3:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff812674fe>] device_release_driver+0x18/0x2d
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: stack backtrace:
Jul  7 15:08:42 stein kernel: Pid: 303, comm: khubd Not tainted 3.0.0-rc6 #9
Jul  7 15:08:42 stein kernel: Call Trace:
Jul  7 15:08:42 stein kernel: [<ffffffff8105cfaf>] __lock_acquire+0x169b/0x1734
Jul  7 15:08:42 stein kernel: [<ffffffff8105a1ff>] ? mark_held_locks+0x52/0x70
Jul  7 15:08:42 stein kernel: [<ffffffff8102e603>] ? sub_preempt_count+0x92/0xa6
Jul  7 15:08:42 stein kernel: [<ffffffff8134fcc1>] ? _raw_spin_unlock_irq+0x36/0x53
Jul  7 15:08:42 stein kernel: [<ffffffff810465eb>] ? wait_on_cpu_work+0x6a/0x99
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff8105d471>] lock_acquire+0x57/0x6d
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff8102e6c4>] ? add_preempt_count+0xad/0xb2
Jul  7 15:08:42 stein kernel: [<ffffffff8134e711>] mutex_lock_nested+0x5e/0x2f9
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff810466e1>] ? wait_on_work+0xc7/0x115
Jul  7 15:08:42 stein kernel: [<ffffffff8104661a>] ? wait_on_cpu_work+0x99/0x99
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff81046803>] ? __cancel_work_timer+0xd4/0x11d
Jul  7 15:08:42 stein kernel: [<ffffffff812a099b>] usb_unbind_interface+0x93/0xd1
Jul  7 15:08:42 stein kernel: [<ffffffff812673e6>] __device_release_driver+0x67/0xb0
Jul  7 15:08:42 stein kernel: [<ffffffff81267506>] device_release_driver+0x20/0x2d
Jul  7 15:08:42 stein kernel: [<ffffffff81266a24>] bus_remove_device+0xb1/0xc6
Jul  7 15:08:42 stein kernel: [<ffffffff812654fa>] device_del+0x11b/0x187
Jul  7 15:08:42 stein kernel: [<ffffffff8129e81b>] usb_disable_device+0x55/0x14b
Jul  7 15:08:42 stein kernel: [<ffffffff81299d87>] usb_disconnect+0xa4/0x140
Jul  7 15:08:42 stein kernel: [<ffffffff8129acef>] hub_thread+0x53d/0xe5a
Jul  7 15:08:42 stein kernel: [<ffffffff8134d259>] ? schedule+0x878/0x8b0
Jul  7 15:08:42 stein kernel: [<ffffffff8134ccf0>] ? schedule+0x30f/0x8b0
Jul  7 15:08:42 stein kernel: [<ffffffff8104b06d>] ? wake_up_bit+0x25/0x25
Jul  7 15:08:42 stein kernel: [<ffffffff8134fd24>] ? _raw_spin_unlock_irqrestore+0x46/0x64
Jul  7 15:08:42 stein kernel: [<ffffffff8129a7b2>] ? hub_probe+0x7f3/0x7f3
Jul  7 15:08:42 stein kernel: [<ffffffff8104acca>] kthread+0x7d/0x85
Jul  7 15:08:42 stein kernel: [<ffffffff81351594>] kernel_thread_helper+0x4/0x10
Jul  7 15:08:42 stein kernel: [<ffffffff8102e4f5>] ? finish_task_switch+0x42/0xbe
Jul  7 15:08:42 stein kernel: [<ffffffff813500c4>] ? retint_restore_args+0xe/0xe
Jul  7 15:08:42 stein kernel: [<ffffffff8104ac4d>] ? __init_kthread_worker+0x56/0x56
Jul  7 15:08:42 stein kernel: [<ffffffff81351590>] ? gs_change+0xb/0xb
Signature · 3 lines
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/
#2 lore raw
Quoted 8 lines · On Jul 07 Stefan Richter wrote:

It appears to be a regression from -rc4 to -rc6. At the second occasion that I switched the monitor off while running 3.0-rc6, the same happened again. (IOW judging from the mere two tries I did so far, this issue is 100% reproducible.)

khubd locked up; no subsequent device re-attachments were recognized; only an USB mouse that was attached to a motherboard USB port already before the deadlock continued to let me move the pointer.

Sarah, "gitk v3.0-rc4.. drivers/usb/core/" makes it look like this is from commit fccf4e86200b8f5edd9a65da26f150e32ba79808. When I find spare time I will test 3.0-rc6 with that one reverted.

Quoted 84 lines
Jul  7 15:08:41 stein kernel: usb 1-3.2: USB disconnect, device number 4
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0005: can't reset device, 0000:00:12.2-3.3/input0, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: hub 1-3:1.0: hub_port_status failed (err = -71)
Jul  7 15:08:41 stein kernel: hub 1-3:1.0: connect-debounce failed, port 2 disabled
Jul  7 15:08:41 stein kernel: usb 1-3: USB disconnect, device number 2
Jul  7 15:08:41 stein kernel: usb 1-3.1: USB disconnect, device number 3
Jul  7 15:08:41 stein kernel: usb 1-3.1.1: USB disconnect, device number 6
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -71
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0005: can't reset device, 0000:00:12.2-3.3/input0, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -19
Jul  7 15:08:41 stein kernel: generic-usb 0003:1267:0103.0006: can't reset device, 0000:00:12.2-3.3/input1, status -71
Jul  7 15:08:41 stein kernel: usb 1-3: clear tt 3 (0050) error -19
Jul  7 15:08:41 stein kernel: usb 1-3.3: USB disconnect, device number 5
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: =============================================
Jul  7 15:08:42 stein kernel: [ INFO: possible recursive locking detected ]
Jul  7 15:08:42 stein kernel: 3.0.0-rc6 #9
Jul  7 15:08:42 stein kernel: ---------------------------------------------
Jul  7 15:08:42 stein kernel: khubd/303 is trying to acquire lock:
Jul  7 15:08:42 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: but task is already holding lock:
Jul  7 15:08:42 stein kernel: (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: other info that might help us debug this:
Jul  7 15:08:42 stein kernel: Possible unsafe locking scenario:
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: CPU0
Jul  7 15:08:42 stein kernel: ----
Jul  7 15:08:42 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 15:08:42 stein kernel: lock(hcd->bandwidth_mutex);
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: *** DEADLOCK ***
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: May be due to missing lock nesting notation
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: 4 locks held by khubd/303:
Jul  7 15:08:42 stein kernel: #0:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff8129a891>] hub_thread+0xdf/0xe5a
Jul  7 15:08:42 stein kernel: #1:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff81299d3c>] usb_disconnect+0x59/0x140
Jul  7 15:08:42 stein kernel: #2:  (hcd->bandwidth_mutex){+.+.+.}, at: [<ffffffff81299d7d>] usb_disconnect+0x9a/0x140
Jul  7 15:08:42 stein kernel: #3:  (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff812674fe>] device_release_driver+0x18/0x2d
Jul  7 15:08:42 stein kernel: 
Jul  7 15:08:42 stein kernel: stack backtrace:
Jul  7 15:08:42 stein kernel: Pid: 303, comm: khubd Not tainted 3.0.0-rc6 #9
Jul  7 15:08:42 stein kernel: Call Trace:
Jul  7 15:08:42 stein kernel: [<ffffffff8105cfaf>] __lock_acquire+0x169b/0x1734
Jul  7 15:08:42 stein kernel: [<ffffffff8105a1ff>] ? mark_held_locks+0x52/0x70
Jul  7 15:08:42 stein kernel: [<ffffffff8102e603>] ? sub_preempt_count+0x92/0xa6
Jul  7 15:08:42 stein kernel: [<ffffffff8134fcc1>] ? _raw_spin_unlock_irq+0x36/0x53
Jul  7 15:08:42 stein kernel: [<ffffffff810465eb>] ? wait_on_cpu_work+0x6a/0x99
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff8105d471>] lock_acquire+0x57/0x6d
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff8102e6c4>] ? add_preempt_count+0xad/0xb2
Jul  7 15:08:42 stein kernel: [<ffffffff8134e711>] mutex_lock_nested+0x5e/0x2f9
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] ? usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff810466e1>] ? wait_on_work+0xc7/0x115
Jul  7 15:08:42 stein kernel: [<ffffffff8104661a>] ? wait_on_cpu_work+0x99/0x99
Jul  7 15:08:42 stein kernel: [<ffffffff8129f588>] usb_set_interface+0x84/0x210
Jul  7 15:08:42 stein kernel: [<ffffffff81046803>] ? __cancel_work_timer+0xd4/0x11d
Jul  7 15:08:42 stein kernel: [<ffffffff812a099b>] usb_unbind_interface+0x93/0xd1
Jul  7 15:08:42 stein kernel: [<ffffffff812673e6>] __device_release_driver+0x67/0xb0
Jul  7 15:08:42 stein kernel: [<ffffffff81267506>] device_release_driver+0x20/0x2d
Jul  7 15:08:42 stein kernel: [<ffffffff81266a24>] bus_remove_device+0xb1/0xc6
Jul  7 15:08:42 stein kernel: [<ffffffff812654fa>] device_del+0x11b/0x187
Jul  7 15:08:42 stein kernel: [<ffffffff8129e81b>] usb_disable_device+0x55/0x14b
Jul  7 15:08:42 stein kernel: [<ffffffff81299d87>] usb_disconnect+0xa4/0x140
Jul  7 15:08:42 stein kernel: [<ffffffff8129acef>] hub_thread+0x53d/0xe5a
Jul  7 15:08:42 stein kernel: [<ffffffff8134d259>] ? schedule+0x878/0x8b0
Jul  7 15:08:42 stein kernel: [<ffffffff8134ccf0>] ? schedule+0x30f/0x8b0
Jul  7 15:08:42 stein kernel: [<ffffffff8104b06d>] ? wake_up_bit+0x25/0x25
Jul  7 15:08:42 stein kernel: [<ffffffff8134fd24>] ? _raw_spin_unlock_irqrestore+0x46/0x64
Jul  7 15:08:42 stein kernel: [<ffffffff8129a7b2>] ? hub_probe+0x7f3/0x7f3
Jul  7 15:08:42 stein kernel: [<ffffffff8104acca>] kthread+0x7d/0x85
Jul  7 15:08:42 stein kernel: [<ffffffff81351594>] kernel_thread_helper+0x4/0x10
Jul  7 15:08:42 stein kernel: [<ffffffff8102e4f5>] ? finish_task_switch+0x42/0xbe
Jul  7 15:08:42 stein kernel: [<ffffffff813500c4>] ? retint_restore_args+0xe/0xe
Jul  7 15:08:42 stein kernel: [<ffffffff8104ac4d>] ? __init_kthread_worker+0x56/0x56
Jul  7 15:08:42 stein kernel: [<ffffffff81351590>] ? gs_change+0xb/0xb
Signature · 3 lines
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/
#3 lore raw
Quoted 6 lines · Stefan Richter
Quoted 5 lines · On Jul 07 Stefan Richter wrote:

It appears to be a regression from -rc4 to -rc6. At the second occasion that I switched the monitor off while running 3.0-rc6, the same happened again. (IOW judging from the mere two tries I did so far, this issue is 100% reproducible.)

Quoted 7 lines
Quoted 3 lines

khubd locked up; no subsequent device re-attachments were recognized; only an USB mouse that was attached to a motherboard USB port already before the deadlock continued to let me move the pointer.

Sarah, "gitk v3.0-rc4.. drivers/usb/core/" makes it look like this is from commit fccf4e86200b8f5edd9a65da26f150e32ba79808. When I find spare time I will test 3.0-rc6 with that one reverted.

Can you test Linus's tree, along with a patch sent yesterday from Alan Stern to the linux-usb mailing list (attached below)? That should resolve this issue, if not, please let us know.

thanks,

greg k-h

Quoted 1 line

From [email protected] Wed Jul 6 14:03:47 2011

Return-Path: <[email protected]>
X-OfflineIMAP: 2303515278-5823848424
Delivered-To: unknown
Received: from imap.suse.de ([unix socket])

	 by imap-int (Cyrus v2.2.12) with LMTPA;
	 Wed, 06 Jul 2011 23:03:47 +0200
X-Sieve: CMU Sieve 2.2
Received: from relay2.suse.de (relay2.suse.de [149.44.160.134])
	(using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits))
	(Client CN "relay.suse.de", Issuer "CAcert Class 3 Root" (verified OK))
	by imap.suse.de (Postfix) with ESMTPS id 685C43C539A9
	for <[email protected]>; Wed,  6 Jul 2011 23:03:47 +0200 (CEST)
Received: by relay2.suse.de (Postfix)
	id 5F09B1855766; Wed,  6 Jul 2011 23:03:47 +0200 (CEST)
Received: from localhost (localhost [127.0.0.1])
	by relay2.suse.de (Postfix) with ESMTP id 53D4018552DE
	for <[email protected]>; Wed,  6 Jul 2011 23:03:47 +0200 (CEST)

Received: from relay2.suse.de ([127.0.0.1])
by localhost (localhost [127.0.0.1]) (amavisd-new, port 10026) with ESMTP id 07676-11 for <[email protected]>; Wed, 6 Jul 2011 23:03:47 +0200 (CEST)
Received: from mx2.suse.de (cantor2.suse.de [195.135.220.15])

	(using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits))
	(No client certificate requested)
	by relay2.suse.de (Postfix) with ESMTPS id 0B33018552CC
	for <[email protected]>; Wed,  6 Jul 2011 23:03:47 +0200 (CEST)
Received: from iolanthe.rowland.org (iolanthe.rowland.org [192.131.102.54])
	by mx2.suse.de (Postfix) with SMTP id A86F58B2F9
	for <[email protected]>; Wed,  6 Jul 2011 23:03:46 +0200 (CEST)

Received: (qmail 6472 invoked by uid 2102); 6 Jul 2011 17:03:45 -0400
Received: from localhost ([email protected])
by localhost with SMTP; 6 Jul 2011 17:03:45 -0400
Date: Wed, 6 Jul 2011 17:03:45 -0400 (EDT)
From: Alan Stern <[email protected]>
X-X-Sender: [email protected]
To: Greg KH <[email protected]>
Cc: Arkadiusz Miskiewicz <[email protected]>,
=?iso-8859-1?Q?=C9ric?= Piel <[email protected]>, Sarah Sharp <[email protected]>,
LKML <[email protected]>,
USB list <[email protected]>,
"Rafael J. Wysocki" <[email protected]>
Subject: [PATCH] USB: additional regression fix for device removal
In-Reply-To: <[email protected]>
Message-ID: <[email protected]>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII
X-Virus-Scanned: by amavisd-new at localhost
X-Spam-Status: No, score=0.001 tagged_above=-20 required=5
tests=[BAYES_50=0.001]
X-Spam-Score: 0.001
X-Spam-Level:
Status: RO
Content-Length: 2323

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(-)
drivers/usb/core/message.c +8 -1
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);
 		}
#4 lore raw
Quoted 3 lines · On Jul 07 Greg KH wrote:

Can you test Linus's tree, along with a patch sent yesterday from Alan Stern to the linux-usb mailing list (attached below)? That should resolve this issue, if not, please let us know.

OK. I am using 3.0-rc6-71-g4dd1b49 plus Alan's "USB: additional regression fix for device removal" now. So far it survived a dozen of power toggles of the hub and the attached devices. Thanks.

Quoted 1 line · Alan Stern

Still, we need to rewrite this stuff. A possible race remains,

On a general level, the last few kernel.org releases have all been rather weak. Dissatisfied,

Signature · 3 lines
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/
#5 lore raw
Quoted 9 lines · Stefan Richter
Quoted 3 lines · On Jul 07 Greg KH wrote:

Can you test Linus's tree, along with a patch sent yesterday from Alan Stern to the linux-usb mailing list (attached below)? That should resolve this issue, if not, please let us know.

OK. I am using 3.0-rc6-71-g4dd1b49 plus Alan's "USB: additional regression fix for device removal" now. So far it survived a dozen of power toggles of the hub and the attached devices. Thanks.

Quoted 5 lines
Quoted 1 line · Alan Stern

Still, we need to rewrite this stuff. A possible race remains,

On a general level, the last few kernel.org releases have all been rather weak. Dissatisfied,

For USB regressions or the kernel overall? Yes, last kernel release had some nasty regressions-disguised-as-bug-fixes in the USB tree as well. My fault there, not sure how to improve other than coming up with a list of every possible plug-unplug/reset/configure/alt setting change combination possible and testing before sending any thing at all. Suggestions welcome, testing appreciated.

Sarah Sharp

#6 lore raw
Quoted 10 lines · On Jul 07 Sarah Sharp wrote:
Quoted 9 lines · Stefan Richter
Quoted 3 lines · On Jul 07 Greg KH wrote:

Can you test Linus's tree, along with a patch sent yesterday from Alan Stern to the linux-usb mailing list (attached below)? That should resolve this issue, if not, please let us know.

OK. I am using 3.0-rc6-71-g4dd1b49 plus Alan's "USB: additional regression fix for device removal" now. So far it survived a dozen of power toggles of the hub and the attached devices. Thanks.

Quoted 7 lines
Quoted 5 lines
Quoted 1 line · Alan Stern

Still, we need to rewrite this stuff. A possible race remains,

On a general level, the last few kernel.org releases have all been rather weak. Dissatisfied,

For USB regressions or the kernel overall?

Kernel overall. USB unplug issues have been there before, but not as reproducible as this one now. (Which is apparently fixed for me now.)

I felt compelled to comment on Alan's sentence though because this does not sound like the 2.6 development approach at all. (Some other subsystem projects, outside USB, ignore that approach anyway and work 2.5 style.)

Signature · 3 lines
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/
#7 lore raw
Quoted 5 lines · Stefan Richter
Quoted 4 lines
Quoted 2 lines

On a general level, the last few kernel.org releases have all been rather weak. Dissatisfied,

For USB regressions or the kernel overall?

Quoted 7 lines

Kernel overall. USB unplug issues have been there before, but not as reproducible as this one now. (Which is apparently fixed for me now.)

I felt compelled to comment on Alan's sentence though because this does not sound like the 2.6 development approach at all. (Some other subsystem projects, outside USB, ignore that approach anyway and work 2.5 style.)

In general, adding support for USB-3.0 has been a tremendous job (of which Sarah has done the lion's share of the work), involving not just adding a new driver but also making significant changes to the subsystem core. Those changes have been sufficiently complicated that things haven't settled down yet.

Particularly since it has now become clear that a key implementation decision (to allocate periodic bandwidth dynamically, as it is used, rather than statically) needs to be reversed. The fan-out effects from this will require changes to several other drivers as well, and this is all still in the design stage. Thus, we are forced to limp along with a hacky, not-entirely-correct implementation until everything can be put right. I don't expect this to happen quickly.

Alan Stern

#8 lore raw
Quoted 6 lines · On Jul 08 Alan Stern wrote:

In general, adding support for USB-3.0 has been a tremendous job (of which Sarah has done the lion's share of the work), involving not just adding a new driver but also making significant changes to the subsystem core. Those changes have been sufficiently complicated that things haven't settled down yet.

Quoted 7 lines

Particularly since it has now become clear that a key implementation decision (to allocate periodic bandwidth dynamically, as it is used, rather than statically) needs to be reversed. The fan-out effects from this will require changes to several other drivers as well, and this is all still in the design stage. Thus, we are forced to limp along with a hacky, not-entirely-correct implementation until everything can be put right. I don't expect this to happen quickly.

OK, fair enough. I acknowledge that such a scope expansion at all layers of the subsystem is a difficult undertaking. Plus, you had working patches that addressed my issue, even before I got around to report it.

Signature · 3 lines
Stefan Richter
-=====-==-== -=== -=---
http://arcgraph.de/sr/