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

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

[Stefan Richter]

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.

-- 
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/

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

[Stefan Richter]

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

-- 
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/

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

[Stefan Richter]

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.

> 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
> 

-- 
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/

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

[Greg KH]

[-- Attachment #1: Type: text/plain, Size: 975 bytes --]

On Thu, Jul 07, 2011 at 03:38:49PM +0200, Stefan Richter wrote:
> 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.

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

[-- Attachment #2: s --]
[-- Type: text/plain, Size: 4919 bytes --]

>From stern+4e0774f0@rowland.harvard.edu Wed Jul  6 14:03:47 2011
Return-Path: <stern+4e0774f0@rowland.harvard.edu>
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 <gregkh@imap.suse.de>; 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 <gregkh@suse.de>; 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 <gregkh@suse.de>; 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 <gregkh@suse.de>; 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 <gregkh@suse.de>; 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 (sendmail-bs@127.0.0.1)
  by localhost with SMTP; 6 Jul 2011 17:03:45 -0400
Date: Wed, 6 Jul 2011 17:03:45 -0400 (EDT)
From: Alan Stern <stern@rowland.harvard.edu>
X-X-Sender: stern@iolanthe.rowland.org
To: Greg KH <gregkh@suse.de>
Cc: Arkadiusz Miskiewicz <a.miskiewicz@gmail.com>,
	=?iso-8859-1?Q?=C9ric?= Piel <E.A.B.Piel@tudelft.nl>,
	Sarah Sharp <sarah.a.sharp@linux.intel.com>,
	LKML <linux-kernel@vger.kernel.org>,
	USB list <linux-usb@vger.kernel.org>,
	"Rafael J. Wysocki" <rjw@sisk.pl>
Subject: [PATCH] USB: additional regression fix for device removal
In-Reply-To: <20110706204647.GC1460@suse.de>
Message-ID: <Pine.LNX.4.44L0.1107061658180.1995-100000@iolanthe.rowland.org>
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.

Signed-off-by: Alan Stern <stern@rowland.harvard.edu>
CC: <stable@kernel.org>

---

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
===================================================================
--- usb-3.0.orig/drivers/usb/core/message.c
+++ 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);
 		}

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

[Stefan Richter]

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.

Alan Stern wrote:
> 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,
-- 
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/

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

[Sarah Sharp]

On Thu, Jul 07, 2011 at 09:24:49PM +0200, Stefan Richter wrote:
> 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.
> 
> Alan Stern wrote:
> > 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

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

[Stefan Richter]

On Jul 07 Sarah Sharp wrote:
> On Thu, Jul 07, 2011 at 09:24:49PM +0200, Stefan Richter wrote:
> > 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.
> > 
> > Alan Stern wrote:
> > > 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.)
-- 
Stefan Richter
-=====-==-== -=== --===
http://arcgraph.de/sr/

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

[Alan Stern]

On Thu, 7 Jul 2011, Stefan Richter wrote:

> > > 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.)

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

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

[Stefan Richter]

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.
> 
> 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.
-- 
Stefan Richter
-=====-==-== -=== -=---
http://arcgraph.de/sr/