Endless print of uhci_result_common: failed with status 440000

Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

Hi

While debugging resume problem with Intel HW I've been hitting problem
with endless print of  usb 1.1 error message on my T61.
(See my other similar post
http://marc.info/?l=linux-kernel&m=130221292724436&w=2)

This time the problem is generated by Bluetooth device.

Often just only several messages are printed - and then machine
suspend - so the log usually contains only several such message - if
at all - however today with debugging and serial console logging -
I've seen several times - that suspend resulted in endless unbreakable
loop.

As a workaround - one could just disable BT device:
"echo disable >/proc/acpi/ibm/bluetooth"

Here is the log:
[    0.000000] Linux version 2.6.39-rc2-00005-gf04d4dc (kabi@linux)
(gcc version 4.6.0 20110331 (Red Hat 4.6.0-2) (GCC) ) #119 SMP PREEMPT
Wed Apr 6 15:27:55 CEST 2011
[    0.000000] Command line: ro root=/dev/sda2 selinux=0 kmemleak=off
lockdep.prove_locking=0 lockdep.lock_stat=0 SYSFONT=latarcyrheb-sun16
LANG=cs_CZ.UTF-8 KEYTABLE=us systemd.log_level=info
systemd.log_target=kmsg systemd.sysv_console=true
console=ttyS0,115200n8 console=tty drm.debug=0xe
..
[   63.850237] usb 2-1: new full speed USB device number 5 using uhci_hcd
[   64.003946] usb 2-1: skipped 1 descriptor after interface
[   64.015946] usb 2-1: default language 0x0409
[   64.032516] usb 2-1: udev 5, busnum 2, minor = 132
[   64.039699] usb 2-1: New USB device found, idVendor=0a5c, idProduct=2110
[   64.048507] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   64.057788] usb 2-1: Product: BCM2045B
[   64.063791] usb 2-1: Manufacturer: Broadcom Corp
[   64.071394] usb 2-1: usb_probe_device
[   64.077084] usb 2-1: configuration #1 chosen from 1 choice
[   64.087013] usb 2-1: adding 2-1:1.0 (config #1, interface 0)
[   64.094665] btusb 2-1:1.0: usb_probe_interface
[   64.100942] btusb 2-1:1.0: usb_probe_interface - got id
[   64.109662] uhci_hcd 0000:00:1a.0: reserve dev 5 ep81-INT, period
1, phase 0, 23 us
[   64.119576] usb 2-1: adding 2-1:1.1 (config #1, interface 1)
[   64.127950] usb 2-1: adding 2-1:1.2 (config #1, interface 2)
[   64.136924] btusb 2-1:1.2: usb_probe_interface
[   64.144332] btusb 2-1:1.2: usb_probe_interface - got id
[   64.152571] usb 2-1: adding 2-1:1.3 (config #1, interface 3)
[   64.160897] btusb 2-1:1.3: usb_probe_interface
[   64.167823] btusb 2-1:1.3: usb_probe_interface - got id
...
[  100.534903] [drm:intel_sdvo_debug_write], SDVOB: W: 0B
           (SDVO_CMD_GET_ATTACHED_DISPLAYS)
[  100.548392] [drm:intel_sdvo_read_response], SDVOB: R: (Success) 00 00
[  100.560152] [drm:intel_sdvo_detect], SDVO response 0 0 [1]
[  100.565826] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1] disconnected
[  100.574551] [drm:drm_mode_getconnector], [CONNECTOR:15:?]
[  100.580044] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1]
[  100.587672] [drm:intel_sdvo_debug_write], SDVOB: W: 0B
           (SDVO_CMD_GET_ATTACHED_DISPLAYS)
[  100.601411] [drm:intel_sdvo_read_response], SDVOB: R: (Success) 00 00
[  100.613202] [drm:intel_sdvo_detect], SDVO response 0 0 [1]
[  100.618808] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1] disconnected
[  101.802287] [drm:drm_mode_addfb], [FB:18]
[  102.142272] [drm:intel_crtc_cursor_set],
[  102.146471] [drm:intel_crtc_cursor_set], cursor off
[  103.346753] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0002
[  103.352278] usb 2-1: uhci_result_common: failed with status 440000
[  103.357592] usb 2-1: uhci_result_common: failed with status 440000
[  103.364864] usb 2-1: uhci_result_common: failed with status 440000
[  103.368183] usb 2-1: uhci_result_common: failed with status 440000
[  103.377457] usb 2-1: uhci_result_common: failed with status 440000
[  103.380772] usb 2-1: uhci_result_common: failed with status 440000
[  103.390052] usb 2-1: uhci_result_common: failed with status 440000
[  103.393370] usb 2-1: uhci_result_common: failed with status 440000
[  103.402631] usb 2-1: uhci_result_common: failed with status 440000
[  103.405948] usb 2-1: uhci_result_common: failed with status 440000
[  103.415211] usb 2-1: uhci_result_common: failed with status 440000
[  103.418532] usb 2-1: uhci_result_common: failed with status 440000
[  103.427791] usb 2-1: uhci_result_common: failed with status 440000
[  103.431111] usb 2-1: uhci_result_common: failed with status 440000
[  103.440365] usb 2-1: uhci_result_common: failed with status 440000
[  103.443686] usb 2-1: uhci_result_common: failed with status 440000
[  103.452932] usb 2-1: uhci_result_common: failed with status 440000
[  103.456247] usb 2-1: uhci_result_common: failed with status 440000
[  103.465501] usb 2-1: uhci_result_common: failed with status 440000
[  103.468821] usb 2-1: uhci_result_common: failed with status 440000
[  103.478074] usb 2-1: uhci_result_common: failed with status 440000
[  103.481394] usb 2-1: uhci_result_common: failed with status 440000
[  103.490630] usb 2-1: uhci_result_common: failed with status 440000
[  103.493950] usb 2-1: uhci_result_common: failed with status 440000
[  103.503202] usb 2-1: uhci_result_common: failed with status 440000
[  103.506521] usb 2-1: uhci_result_common: failed with status 440000
[  103.515763] usb 2-1: uhci_result_common: failed with status 440000
[  103.519084] usb 2-1: uhci_result_common: failed with status 440000
[  103.528341] usb 2-1: uhci_result_common: failed with status 440000
[  103.531661] usb 2-1: uhci_result_common: failed with status 440000
[  103.540907] usb 2-1: uhci_result_common: failed with status 440000
---repeating ---
[  141.696075] usb 2-1: uhci_result_common: failed with status 440000
[  141.699335] usb 2-1: uhci_result_common: failed with status 440000
[  141.708504] usb 2-1: uhci_result_common: failed with status 440000
[  141.711826] usb 2-1: uhci_result_common: failed with status 440000
[  141.720950] usb 2-1: uhci_result_common: failed with status 440000
--- decided to turn off laptop ---

Googling it - seems it's common issue of this BT chipset - but I think
is should not cause suspend deadlock ??

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

On Fri, 8 Apr 2011, Zdenek Kabelac wrote:

> Hi
> 
> While debugging resume problem with Intel HW I've been hitting problem
> with endless print of  usb 1.1 error message on my T61.
> (See my other similar post
> http://marc.info/?l=linux-kernel&m=130221292724436&w=2)

This is essentially the same problem.

> This time the problem is generated by Bluetooth device.
> 
> Often just only several messages are printed - and then machine
> suspend - so the log usually contains only several such message - if
> at all - however today with debugging and serial console logging -
> I've seen several times - that suspend resulted in endless unbreakable
> loop.
> 
> As a workaround - one could just disable BT device:
> "echo disable >/proc/acpi/ibm/bluetooth"

...

> Googling it - seems it's common issue of this BT chipset - but I think
> is should not cause suspend deadlock ??

Are you sure anything is deadlocked?  What happens if you disable 
CONFIG_USB_DEBUG?

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>
>> Hi
>>
>> While debugging resume problem with Intel HW I've been hitting problem
>> with endless print of  usb 1.1 error message on my T61.
>> (See my other similar post
>> http://marc.info/?l=linux-kernel&m=130221292724436&w=2)
>
> This is essentially the same problem.
>
>> This time the problem is generated by Bluetooth device.
>>
>> Often just only several messages are printed - and then machine
>> suspend - so the log usually contains only several such message - if
>> at all - however today with debugging and serial console logging -
>> I've seen several times - that suspend resulted in endless unbreakable
>> loop.
>>
>> As a workaround - one could just disable BT device:
>> "echo disable >/proc/acpi/ibm/bluetooth"
>
> ...
>
>> Googling it - seems it's common issue of this BT chipset - but I think
>> is should not cause suspend deadlock ??
>
> Are you sure anything is deadlocked?  What happens if you disable
> CONFIG_USB_DEBUG?
>


Ok - I've disabled this config option - now kernel writes this:
(when I keep bt device enabled)

usb 3-1: USB disconnect, device number 2
btusb_bulk_complete: hci0 urb ffff88012b94ca50 failed to resubmit (19)
btusb_intr_complete: hci0 urb ffff88012b94c000 failed to resubmit (19)
btusb_bulk_complete: hci0 urb ffff88012b94c948 failed to resubmit (19)
btusb_send_frame: hci0 urb ffff880113dd0528 submission failed
------------[ cut here ]------------
WARNING: at lib/debugobjects.c:262 debug_print_object+0x7c/0x8d()
Hardware name: 6464CTO
ODEBUG: free active (active state 0) object type: timer_list hint:
hci_cmd_timer+0x0/0x46 [bluetooth]
Modules linked in: hidp ip6table_filter
systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
 ip6_tables ebtable_nat ebtables xt_CHECKSUM iptable_mangle tun bridge
ipv6 stp llc sunrpc rfcomm acpi_cpufreq freq_table mperf bnep
xt_physdev ipt_MASQUERADE iptable_nat nf_nat snd_hda_codec_analog arc4
iwl3945 snd_hda_intel snd_hda_codec snd_hwdep r852 snd_seq sm_common
snd_seq_device microcode btusb nand iwl_legacy nand_ids r592 nand_ecc
memstick mtd snd_pcm mac80211 i2c_i801 joydev iTCO_wdt bluetooth
iTCO_vendor_support cfg80211 thinkpad_acpi e1000e snd_timer rfkill
snd_page_alloc wmi snd soundcore virtio_net kvm_intel kvm uinput
sdhci_pci yenta_socket sdhci mmc_core i915 drm_kms_helper drm
i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
Pid: 21, comm: khubd Not tainted 2.6.39-0.rc2.git0.0.fc16.x86_64 #1
Call Trace:
 [<ffffffff81056af8>] warn_slowpath_common+0x83/0x9b
 [<ffffffff81056bb3>] warn_slowpath_fmt+0x46/0x48
 [<ffffffff8125c173>] debug_print_object+0x7c/0x8d
 [<ffffffffa023718c>] ? hci_send_acl+0x27c/0x27c [bluetooth]
 [<ffffffff8125c961>] debug_check_no_obj_freed+0x96/0x175
 [<ffffffffa02438e9>] ? bt_host_release+0x16/0x18 [bluetooth]
 [<ffffffff811202ac>] slab_free_hook+0x6b/0x74
 [<ffffffff811223a8>] kfree+0x8e/0xf2
 [<ffffffffa02438e9>] bt_host_release+0x16/0x18 [bluetooth]
 [<ffffffff813160da>] device_release+0x4c/0x81
 [<ffffffff8124e89b>] kobject_release+0x11d/0x154
 [<ffffffff8124e77e>] ? kobject_del+0x36/0x36
 [<ffffffff8124fccf>] kref_put+0x43/0x4d
 [<ffffffff8124e6e1>] kobject_put+0x45/0x49
 [<ffffffff81315b1b>] put_device+0x17/0x19
 [<ffffffffa02389a2>] hci_free_dev+0x26/0x2a [bluetooth]
 [<ffffffffa0390cbb>] btusb_disconnect+0xbd/0xc6 [btusb]
 [<ffffffff81378b18>] usb_unbind_interface+0x5c/0x124
 [<ffffffff8131932e>] __device_release_driver+0x7c/0xd5
 [<ffffffff813193ac>] device_release_driver+0x25/0x32
 [<ffffffff81318edb>] bus_remove_device+0xc4/0xd4
 [<ffffffff81316812>] device_del+0x13c/0x18a
 [<ffffffff81376d6e>] usb_disable_device+0x8c/0x178
 [<ffffffff8136f6d1>] usb_disconnect+0xd0/0x135
 [<ffffffff813716ab>] hub_thread+0x741/0x119d
 [<ffffffff81087164>] ? trace_hardirqs_on+0xd/0xf
 [<ffffffff810734fc>] ? __init_waitqueue_head+0x4b/0x4b
 [<ffffffff81370f6a>] ? usb_remote_wakeup+0x64/0x64
 [<ffffffff81072d8d>] kthread+0xa8/0xb0
 [<ffffffff814c4ba4>] kernel_thread_helper+0x4/0x10
 [<ffffffff814bd254>] ? retint_restore_args+0x13/0x13
 [<ffffffff81072ce5>] ? __init_kthread_worker+0x5a/0x5a
 [<ffffffff814c4ba0>] ? gs_change+0x13/0x13
---[ end trace a7aecbf020e621f2 ]---
PM: Syncing filesystems ... done.
PM: Preparing system for mem sleep


Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/8 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
> 2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
>> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>>
>>> Hi
>>>
>>> While debugging resume problem with Intel HW I've been hitting problem
>>> with endless print of  usb 1.1 error message on my T61.
>>> (See my other similar post
>>> http://marc.info/?l=linux-kernel&m=130221292724436&w=2)
>>
>> This is essentially the same problem.
>>
>>> This time the problem is generated by Bluetooth device.
>>>
>>> Often just only several messages are printed - and then machine
>>> suspend - so the log usually contains only several such message - if
>>> at all - however today with debugging and serial console logging -
>>> I've seen several times - that suspend resulted in endless unbreakable
>>> loop.
>>>
>>> As a workaround - one could just disable BT device:
>>> "echo disable >/proc/acpi/ibm/bluetooth"
>>
>> ...
>>
>>> Googling it - seems it's common issue of this BT chipset - but I think
>>> is should not cause suspend deadlock ??
>>
>> Are you sure anything is deadlocked?  What happens if you disable
>> CONFIG_USB_DEBUG?
>>
>
>
> Ok - I've disabled this config option - now kernel writes this:
> (when I keep bt device enabled)
>
> usb 3-1: USB disconnect, device number 2
> btusb_bulk_complete: hci0 urb ffff88012b94ca50 failed to resubmit (19)
> btusb_intr_complete: hci0 urb ffff88012b94c000 failed to resubmit (19)
> btusb_bulk_complete: hci0 urb ffff88012b94c948 failed to resubmit (19)
> btusb_send_frame: hci0 urb ffff880113dd0528 submission failed
> ------------[ cut here ]------------
> WARNING: at lib/debugobjects.c:262 debug_print_object+0x7c/0x8d()
> Hardware name: 6464CTO
> ODEBUG: free active (active state 0) object type: timer_list hint:
> hci_cmd_timer+0x0/0x46 [bluetooth]
> Modules linked in: hidp ip6table_filter
> systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
>  ip6_tables ebtable_nat ebtables xt_CHECKSUM iptable_mangle tun bridge
> ipv6 stp llc sunrpc rfcomm acpi_cpufreq freq_table mperf bnep
> xt_physdev ipt_MASQUERADE iptable_nat nf_nat snd_hda_codec_analog arc4
> iwl3945 snd_hda_intel snd_hda_codec snd_hwdep r852 snd_seq sm_common
> snd_seq_device microcode btusb nand iwl_legacy nand_ids r592 nand_ecc
> memstick mtd snd_pcm mac80211 i2c_i801 joydev iTCO_wdt bluetooth
> iTCO_vendor_support cfg80211 thinkpad_acpi e1000e snd_timer rfkill
> snd_page_alloc wmi snd soundcore virtio_net kvm_intel kvm uinput
> sdhci_pci yenta_socket sdhci mmc_core i915 drm_kms_helper drm
> i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
> Pid: 21, comm: khubd Not tainted 2.6.39-0.rc2.git0.0.fc16.x86_64 #1


ooops - different kernel - I'll need another reboot.
(But anyway probably interested as well)

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/8 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
> 2011/4/8 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
>> 2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
>>> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>>>
>>>> Hi
>>>>
>>>> While debugging resume problem with Intel HW I've been hitting problem
>>>> with endless print of  usb 1.1 error message on my T61.
>>>> (See my other similar post
>>>> http://marc.info/?l=linux-kernel&m=130221292724436&w=2)
>>>
>>> This is essentially the same problem.
>>>
>>>> This time the problem is generated by Bluetooth device.
>>>>
>>>> Often just only several messages are printed - and then machine
>>>> suspend - so the log usually contains only several such message - if
>>>> at all - however today with debugging and serial console logging -
>>>> I've seen several times - that suspend resulted in endless unbreakable
>>>> loop.
>>>>
>>>> As a workaround - one could just disable BT device:
>>>> "echo disable >/proc/acpi/ibm/bluetooth"
>>>
>>> ...
>>>
>>>> Googling it - seems it's common issue of this BT chipset - but I think
>>>> is should not cause suspend deadlock ??
>>>
>>> Are you sure anything is deadlocked?  What happens if you disable
>>> CONFIG_USB_DEBUG?
>>>
>>
>>
>> Ok - I've disabled this config option - now kernel writes this:
>> (when I keep bt device enabled)
>>
>> usb 3-1: USB disconnect, device number 2
>> btusb_bulk_complete: hci0 urb ffff88012b94ca50 failed to resubmit (19)
>> btusb_intr_complete: hci0 urb ffff88012b94c000 failed to resubmit (19)
>> btusb_bulk_complete: hci0 urb ffff88012b94c948 failed to resubmit (19)
>> btusb_send_frame: hci0 urb ffff880113dd0528 submission failed
>> ------------[ cut here ]------------
>> WARNING: at lib/debugobjects.c:262 debug_print_object+0x7c/0x8d()
>> Hardware name: 6464CTO
>> ODEBUG: free active (active state 0) object type: timer_list hint:
>> hci_cmd_timer+0x0/0x46 [bluetooth]
>> Modules linked in: hidp ip6table_filter
>> systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
>>  ip6_tables ebtable_nat ebtables xt_CHECKSUM iptable_mangle tun bridge
>> ipv6 stp llc sunrpc rfcomm acpi_cpufreq freq_table mperf bnep
>> xt_physdev ipt_MASQUERADE iptable_nat nf_nat snd_hda_codec_analog arc4
>> iwl3945 snd_hda_intel snd_hda_codec snd_hwdep r852 snd_seq sm_common
>> snd_seq_device microcode btusb nand iwl_legacy nand_ids r592 nand_ecc
>> memstick mtd snd_pcm mac80211 i2c_i801 joydev iTCO_wdt bluetooth
>> iTCO_vendor_support cfg80211 thinkpad_acpi e1000e snd_timer rfkill
>> snd_page_alloc wmi snd soundcore virtio_net kvm_intel kvm uinput
>> sdhci_pci yenta_socket sdhci mmc_core i915 drm_kms_helper drm
>> i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
>> Pid: 21, comm: khubd Not tainted 2.6.39-0.rc2.git0.0.fc16.x86_64 #1
>
>
> ooops - different kernel - I'll need another reboot.
> (But anyway probably interested as well)
>


So now I've retested again with my own kernel build - where I've
disable USB_DEBUG.
It's somewhat harder to hit the problem - but 2 times I've ended with
laptop - which
sent this into  '/var/log/messages'

[   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
to resubmit (19)
[   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
to resubmit (19)
[   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
to resubmit (19)
[   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
[   54.127633] systemd[1]: Service bluetooth.target is not needed
anymore. Stopping.

These are the last lines catched by serial console:

[   53.340232] usb 1-1: new full speed USB device number 4 using uhci_hcd
[   53.505588] usb 1-1: New USB device found, idVendor=0a5c, idProduct=2110
[   53.513035] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   53.520876] usb 1-1: Product: BCM2045B
[   53.524775] usb 1-1: Manufacturer: Broadcom Corp
[   53.846908] usb 1-1: USB disconnect, device number 4
[   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
to resubmit (19)
[   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
to resubmit (19)
[   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
to resubmit (19)
[   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
[   54.127633] systemd[1]: Service bluetooth.target is not needed
anymore. Stopping.
[   54.205292] PM: Syncing filesystems ... done.
[   54.216056] PM: Preparing system for mem sleep

And system was 'dead' - (Moon sign on laptop was already blinking at
this moment)

I've strong believe - it's the moment  where USB_DEBUG version was
printing those lines in endless loop.
(Or let say it this way:   More then few minutes loop  - as maybe it
will end within a week - but I don't have that much time to wait ;))

Seems like Fedora rawhide kernel with KObject debugging gives here
valuable hint ??

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

On Fri, 8 Apr 2011, Zdenek Kabelac wrote:

> So now I've retested again with my own kernel build - where I've
> disable USB_DEBUG.
> It's somewhat harder to hit the problem - but 2 times I've ended with
> laptop - which
> sent this into  '/var/log/messages'
> 
> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
> to resubmit (19)
> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
> to resubmit (19)
> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
> to resubmit (19)
> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
> [   54.127633] systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.

Evidently the software undock messed up the Bluetooth device somehow.

> These are the last lines catched by serial console:
> 
> [   53.340232] usb 1-1: new full speed USB device number 4 using uhci_hcd
> [   53.505588] usb 1-1: New USB device found, idVendor=0a5c, idProduct=2110
> [   53.513035] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> [   53.520876] usb 1-1: Product: BCM2045B
> [   53.524775] usb 1-1: Manufacturer: Broadcom Corp
> [   53.846908] usb 1-1: USB disconnect, device number 4

It's odd that the Bluetooth device should disconnect shortly after
being detected.  However there have been other reports recently about
similar problems with Bluetooth.

> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
> to resubmit (19)
> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
> to resubmit (19)
> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
> to resubmit (19)
> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
> [   54.127633] systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.
> [   54.205292] PM: Syncing filesystems ... done.
> [   54.216056] PM: Preparing system for mem sleep
> 
> And system was 'dead' - (Moon sign on laptop was already blinking at
> this moment)

Why did the system suspend like this?  A software undock shouldn't 
cause a suspend.

> I've strong believe - it's the moment  where USB_DEBUG version was
> printing those lines in endless loop.
> (Or let say it this way:   More then few minutes loop  - as maybe it
> will end within a week - but I don't have that much time to wait ;))

Those debugging messages will continue for as long as the hardware
fails to respond properly.

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>
>> So now I've retested again with my own kernel build - where I've
>> disable USB_DEBUG.
>> It's somewhat harder to hit the problem - but 2 times I've ended with
>> laptop - which
>> sent this into  '/var/log/messages'
>>
>> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
>> to resubmit (19)
>> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
>> to resubmit (19)
>> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
>> to resubmit (19)
>> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
>> [   54.127633] systemd[1]: Service bluetooth.target is not needed
>> anymore. Stopping.
>
> Evidently the software undock messed up the Bluetooth device somehow.
>
>> These are the last lines catched by serial console:
>>
>> [   53.340232] usb 1-1: new full speed USB device number 4 using uhci_hcd
>> [   53.505588] usb 1-1: New USB device found, idVendor=0a5c, idProduct=2110
>> [   53.513035] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
>> [   53.520876] usb 1-1: Product: BCM2045B
>> [   53.524775] usb 1-1: Manufacturer: Broadcom Corp
>> [   53.846908] usb 1-1: USB disconnect, device number 4
>
> It's odd that the Bluetooth device should disconnect shortly after
> being detected.  However there have been other reports recently about
> similar problems with Bluetooth.
>

Most probably because I've run  in the loop

while : ; do pm-suspend ; sleep 5; done

for debug purposes...


>> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
>> to resubmit (19)
>> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
>> to resubmit (19)
>> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
>> to resubmit (19)
>> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
>> [   54.127633] systemd[1]: Service bluetooth.target is not needed
>> anymore. Stopping.
>> [   54.205292] PM: Syncing filesystems ... done.
>> [   54.216056] PM: Preparing system for mem sleep
>>
>> And system was 'dead' - (Moon sign on laptop was already blinking at
>> this moment)
>
> Why did the system suspend like this?  A software undock shouldn't
> cause a suspend.

pm-suspend - with  script executed on suspend which undocks laptop
(otherwise when I'd forget to press button on docking station before
suspend - it would stay 'red' mode - thus all buses are connected -
and as I've noticed in past - it's not working well, when I unplug
laptop in this 'still connected'  mode - so this software 'undock'
solved this problem)


>
>> I've strong believe - it's the moment  where USB_DEBUG version was
>> printing those lines in endless loop.
>> (Or let say it this way:   More then few minutes loop  - as maybe it
>> will end within a week - but I don't have that much time to wait ;))
>
> Those debugging messages will continue for as long as the hardware
> fails to respond properly.

Which is probably 'forever' when the machine is suspending.
(note - even SysRq+B  no longer works at this moment)

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: TEXT/PLAIN; charset=UTF-8, Size: 2415 bytes --]

On Fri, 8 Apr 2011, Zdenek Kabelac wrote:

> Most probably because I've run  in the loop
> 
> while : ; do pm-suspend ; sleep 5; done
> 
> for debug purposes...
> 
> 
> >> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
> >> to resubmit (19)
> >> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
> >> to resubmit (19)
> >> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
> >> to resubmit (19)
> >> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
> >> [   54.127633] systemd[1]: Service bluetooth.target is not needed
> >> anymore. Stopping.
> >> [   54.205292] PM: Syncing filesystems ... done.
> >> [   54.216056] PM: Preparing system for mem sleep
> >>
> >> And system was 'dead' - (Moon sign on laptop was already blinking at
> >> this moment)
> >
> > Why did the system suspend like this?  A software undock shouldn't
> > cause a suspend.
> 
> pm-suspend - with  script executed on suspend which undocks laptop
> (otherwise when I'd forget to press button on docking station before
> suspend - it would stay 'red' mode - thus all buses are connected -
> and as I've noticed in past - it's not working well, when I unplug
> laptop in this 'still connected'  mode - so this software 'undock'
> solved this problem)

All right.  It looks like there are two possible sources of problems 
here: the undock and the suspend.  It would be best to debug them 
separately.

For example, if you change the loop above to just do the undock and
redock without suspending, do the problems still occur?

Another thing to try: Suspend by doing "echo ram >/sys/power/state" 
instead of running pm_suspend.

> >> I've strong believe - it's the moment  where USB_DEBUG version was
> >> printing those lines in endless loop.
> >> (Or let say it this way:   More then few minutes loop  - as maybe it
> >> will end within a week - but I don't have that much time to wait ;))
> >
> > Those debugging messages will continue for as long as the hardware
> > fails to respond properly.
> 
> Which is probably 'forever' when the machine is suspending.
> (note - even SysRq+B  no longer works at this moment)

No, when the machine is suspending there should not be any errors
because there should not be any USB traffic.  All the ongoing transfers
are cancelled as part of the suspend transition, and they start up
again during resume.

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>
>> Most probably because I've run  in the loop
>>
>> while : ; do pm-suspend ; sleep 5; done
>>
>> for debug purposes...
>>
>>
>> >> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
>> >> to resubmit (19)
>> >> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
>> >> to resubmit (19)
>> >> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
>> >> to resubmit (19)
>> >> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
>> >> [   54.127633] systemd[1]: Service bluetooth.target is not needed
>> >> anymore. Stopping.
>> >> [   54.205292] PM: Syncing filesystems ... done.
>> >> [   54.216056] PM: Preparing system for mem sleep
>> >>
>> >> And system was 'dead' - (Moon sign on laptop was already blinking at
>> >> this moment)
>> >
>> > Why did the system suspend like this?  A software undock shouldn't
>> > cause a suspend.
>>
>> pm-suspend - with  script executed on suspend which undocks laptop
>> (otherwise when I'd forget to press button on docking station before
>> suspend - it would stay 'red' mode - thus all buses are connected -
>> and as I've noticed in past - it's not working well, when I unplug
>> laptop in this 'still connected'  mode - so this software 'undock'
>> solved this problem)
>
> All right.  It looks like there are two possible sources of problems
> here: the undock and the suspend.  It would be best to debug them
> separately.
>
> For example, if you change the loop above to just do the undock and
> redock without suspending, do the problems still occur?
>
> Another thing to try: Suspend by doing "echo ram >/sys/power/state"
> instead of running pm_suspend.

hmm - using   "echo mem >/sys/power/state" revealed probably
completely new problem - unsure how this is related to this USB
problem - but it leaves the machine in completely 'frozen' picture on
desktop after resume.

So here is cut&paste captured on serial console:
(Kernel without USB_DEBUG - bluetooth enabled)


[   69.823480] usb 1-1: new full speed USB device number 4 using uhci_hcd
[   69.988817] usb 1-1: New USB device found, idVendor=0a5c, idProduct=2110
[   69.996003] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   70.003598] usb 1-1: Product: BCM2045B
[   70.007502] usb 1-1: Manufacturer: Broadcom Corp
[   70.195677] [drm:drm_mode_addfb], [FB:20]
[   70.835976] [drm:intel_crtc_cursor_set],
[   70.840222] [drm:intel_crtc_cursor_set], cursor off
[   83.104217] PM: Syncing filesystems ... done.
[   83.123943] PM: Preparing system for mem sleep
[   83.487149] [drm:drm_crtc_helper_set_config],
[   83.487159] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:9]
#connectors=1 (x y) (0 0)
[   83.487184] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   83.487199] [drm:intel_pipe_set_base_atomic], Writing base 00040000
00000000 0 0 6720
[   83.487210] [drm:intel_update_fbc],
[   83.487215] [drm:intel_update_fbc], framebuffer not tiled,
disabling compression
[   83.540219] [drm:intel_wait_for_vblank], vblank wait timed out
[   83.549459] [drm:drm_crtc_helper_set_config],
[   83.549461] [drm:drm_crtc_helper_set_config], [CRTC:3] [NOFB]
[   83.549466] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   83.549470] [drm:drm_crtc_helper_set_config],
[   83.549472] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:9]
#connectors=1 (x y) (0 0)
[   83.549476] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   83.549480] [drm:drm_crtc_helper_set_config],
[   83.549482] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:9]
#connectors=1 (x y) (0 0)
[   83.549487] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   83.549496] [drm:drm_crtc_helper_set_config],
[   83.549498] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:9]
#connectors=1 (x y) (0 0)
[   83.549503] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   83.677743] Freezing user space processes ... (elapsed 0.01 seconds) done.
[   83.699503] Freezing remaining freezable tasks ... (elapsed 0.01
seconds) done.
[   83.719492] PM: Entering mem sleep
[   83.907367] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   83.913525] sd 0:0:0:0: [sda] Stopping disk
[   83.966276] ACPI handle has no context!
[   83.970256] sdhci-pci 0000:15:00.3: PCI INT C disabled
[   83.970908] ACPI handle has no context!
[   83.970920] sdhci-pci 0000:15:00.2: PCI INT C disabled
[   83.970932] ACPI handle has no context!
[   83.971441] ehci_hcd 0000:00:1d.7: PCI INT D disabled
[   83.971471] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[   83.971493] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[   83.971513] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[   83.983368] ehci_hcd 0000:00:1a.7: PCI INT C disabled
[   83.983390] uhci_hcd 0000:00:1a.1: PCI INT B disabled
[   83.983412] uhci_hcd 0000:00:1a.0: PCI INT A disabled
[   84.024003] ACPI handle has no context!
[   84.027316] [drm:i915_get_vblank_counter], trying to get vblank
count for disabled pipe A
[   84.040136] i915 0000:00:02.0: power state changed by ACPI to D3
[   84.048371] ata_piix 0000:00:1f.1: PCI INT C disabled
[   84.140794] HDA Intel 0000:00:1b.0: PCI INT B disabled
[   84.232367] e1000e 0000:00:19.0: PCI INT A disabled
[   84.239070] e1000e 0000:00:19.0: PME# enabled
[   84.244989] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
[   84.266888] PM: suspend of devices complete after 542.028 msecs
[   84.303506] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D3
[   84.312368] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D3
[   84.321188] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D3
[   84.340108] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D3
[   84.363514] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D3
[   84.372737] PM: late suspend of devices complete after 97.756 msecs
[   84.382329] ACPI: Preparing to enter system sleep state S3
[   84.537222] PM: Saving platform NVS memory
[   84.546195] Disabling non-boot CPUs ...
[   84.696852] CPU 1 is now offline
[   84.701290] lockdep: fixing up alternatives.
[   84.708954] Extended CMOS year: 2000
[   84.710427] ACPI: Low-level resume complete
[   84.710427] PM: Restoring platform NVS memory
[   84.710427] Extended CMOS year: 2000
[   84.713945] Enabling non-boot CPUs ...
[   84.726051] lockdep: fixing up alternatives.
[   84.731868] Booting Node 0 Processor 1 APIC 0x1
[   84.738016] smpboot cpu 1: start_ip = 98000
[   84.840023] Switched to NOHz mode on CPU #1
[   84.961171] NMI watchdog enabled, takes one hw-pmu counter.
[   85.080214] CPU1 is up
[   85.163401] ACPI: Waking up from system sleep state S3
[   85.577324] i915 0000:00:02.0: restoring config space at offset 0x1
(was 0x900007, writing 0x900407)
[   85.668051] pci 0000:00:02.1: restoring config space at offset 0x1
(was 0x900000, writing 0x900007)
[   85.760192] uhci_hcd 0000:00:1a.0: restoring config space at offset
0x1 (was 0x2800005, writing 0x2800001)
[   85.870193] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   85.960397] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   86.049873] uhci_hcd 0000:00:1a.1: restoring config space at offset
0x1 (was 0x2800005, writing 0x2800001)
[   86.145114] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   86.237067] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   86.328166] ehci_hcd 0000:00:1a.7: restoring config space at offset
0x1 (was 0x2900106, writing 0x2900102)
[   86.424842] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
[   86.518539] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
[   86.611050] HDA Intel 0000:00:1b.0: restoring config space at
offset 0x1 (was 0x100106, writing 0x100102)
[   86.709495] pcieport 0000:00:1c.0: restoring config space at offset
0x7 (was 0x20002020, writing 0x2020)
[   86.809512] pcieport 0000:00:1c.0: restoring config space at offset
0x1 (was 0x100107, writing 0x100507)
[   86.909370] pcieport 0000:00:1c.1: restoring config space at offset
0x1 (was 0x100107, writing 0x100507)
[   87.008236] pcieport 0000:00:1c.2: restoring config space at offset
0x7 (was 0x20004040, writing 0x4040)
[   87.105678] pcieport 0000:00:1c.2: restoring config space at offset
0x1 (was 0x100107, writing 0x100507)
[   87.202295] pcieport 0000:00:1c.3: restoring config space at offset
0x7 (was 0x20005050, writing 0x5050)
[   87.297636] pcieport 0000:00:1c.3: restoring config space at offset
0x1 (was 0x100107, writing 0x100507)
[   87.392524] pcieport 0000:00:1c.4: restoring config space at offset
0x7 (was 0x20006060, writing 0x6060)
[   87.487333] pcieport 0000:00:1c.4: restoring config space at offset
0x1 (was 0x100107, writing 0x100507)
[   87.582082] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   87.673588] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   87.764008] uhci_hcd 0000:00:1d.0: restoring config space at offset
0x1 (was 0x2800005, writing 0x2800001)
[   87.859792] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   87.952042] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   88.043192] uhci_hcd 0000:00:1d.1: restoring config space at offset
0x1 (was 0x2800005, writing 0x2800001)
[   88.140915] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   88.236178] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   88.331564] uhci_hcd 0000:00:1d.2: restoring config space at offset
0x1 (was 0x2800005, writing 0x2800001)
[   88.432971] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   88.531873] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   88.630812] ehci_hcd 0000:00:1d.7: restoring config space at offset
0x1 (was 0x2900106, writing 0x2900102)
[   88.734966] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[   88.834679] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[   88.932211] pci 0000:00:1e.0: restoring config space at offset 0x1
(was 0x100005, writing 0x100007)
[   89.034469] ata_piix 0000:00:1f.1: restoring config space at offset
0x1 (was 0x2800005, writing 0x2880005)
[   89.138911] ahci 0000:00:1f.2: restoring config space at offset 0x1
(was 0x2b00007, writing 0x2b00407)
[   89.244561] iwl3945 0000:03:00.0: restoring config space at offset
0x1 (was 0x100106, writing 0x100506)
[   89.363389] sdhci-pci 0000:15:00.2: BAR 0: set to [mem
0xf8301000-0xf83010ff] (PCI address [0xf8301000-0xf83010ff])
[   89.474415] sdhci-pci 0000:15:00.2: restoring config space at
offset 0x3 (was 0x800000, writing 0x804000)
[   89.584892] sdhci-pci 0000:15:00.2: restoring config space at
offset 0x1 (was 0x2100000, writing 0x2100006)
[   89.706740] sdhci-pci 0000:15:00.3: BAR 0: set to [mem
0xf8301400-0xf83014ff] (PCI address [0xf8301400-0xf83014ff])
[   89.819749] sdhci-pci 0000:15:00.3: restoring config space at
offset 0x3 (was 0x800000, writing 0x804000)
[   89.934115] sdhci-pci 0000:15:00.3: restoring config space at
offset 0x1 (was 0x2100000, writing 0x2100006)
[   90.049768] PM: early resume of devices complete after 4472.864 msecs
[   90.163120] i915 0000:00:02.0: power state changed by ACPI to D0
[   90.171119] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[   90.179436] uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[   90.188527] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   90.196863] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
[   90.205181] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level,
low) -> IRQ 17
[   90.205504] i915 0000:00:02.0: power state changed by ACPI to D0
[   90.205513] i915 0000:00:02.0: setting latency timer to 64
[   90.206741] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
[   90.206751] ehci_hcd 0000:00:1a.7: PCI INT C -> GSI 22 (level, low) -> IRQ 22
[   90.206761] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[   90.206789] e1000e 0000:00:19.0: PME# disabled
[   90.206929] e1000e 0000:00:19.0: irq 48 for MSI/MSI-X
[   90.210156] uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
[   90.210163] uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21
[   90.210174] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[   90.210218] usb usb3: root hub lost power or was reset
[   90.210354] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   90.210360] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[   90.210367] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[   90.210377] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[   90.210415] usb usb4: root hub lost power or was reset
[   90.210440] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[   90.210452] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[   90.210490] usb usb5: root hub lost power or was reset
[   90.210512] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   90.210518] uhci_hcd 0000:00:1d.2: power state changed by ACPI to D0
[   90.210524] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[   90.210537] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[   90.210575] usb usb7: root hub lost power or was reset
[   90.210600] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[   90.210609] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[   90.210621] ehci_hcd 0000:00:1d.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19
[   90.210632] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[   90.210751] pci 0000:00:1e.0: setting latency timer to 64
[   90.210781] ata_piix 0000:00:1f.1: PCI INT C -> GSI 16 (level, low) -> IRQ 16
[   90.210791] ata_piix 0000:00:1f.1: setting latency timer to 64
[   90.210869] ata5: port disabled. ignoring.
[   90.210912] ahci 0000:00:1f.2: setting latency timer to 64
[   90.211116] sdhci-pci 0000:15:00.2: PCI INT C -> GSI 18 (level,
low) -> IRQ 18
[   90.211122] sdhci-pci 0000:15:00.2: Will use DMA mode even though
HW doesn't fully claim to support it.
[   90.211159] sdhci-pci 0000:15:00.3: PCI INT C -> GSI 18 (level,
low) -> IRQ 18
[   90.211176] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[   90.211215] usb usb1: root hub lost power or was reset
[   90.211426] sd 0:0:0:0: [sda] Starting disk
[   90.273703] [drm:intel_opregion_setup], graphic opregion physical
addr: 0xbf6ce61a
[   90.273745] [drm:intel_opregion_setup], Public ACPI methods supported
[   90.273748] [drm:intel_opregion_setup], SWSCI supported
[   90.273750] [drm:intel_opregion_setup], ASLE supported
[   90.276201] [drm:drm_crtc_helper_set_mode], [CRTC:4]
[   90.276206] [drm:intel_sdvo_debug_write], SDVOB: W: 05 00 00
           (SDVO_CMD_SET_ACTIVE_OUTPUTS)
[   90.282069] [drm:intel_sdvo_read_response], SDVOB: R: (Success)
[   90.284026] [drm:i915_get_vblank_counter], trying to get vblank
count for disabled pipe B
[   90.284033] [drm:i915_get_crtc_scanoutpos], trying to get
scanoutpos for disabled pipe B
[   90.284039] [drm:i915_get_vblank_counter], trying to get vblank
count for disabled pipe B
[   90.284049] [drm:intel_update_fbc],
[   90.284051] [drm:intel_update_fbc], framebuffer not tiled,
disabling compression
[   90.284055] [drm:i965_update_wm], self-refresh entries: 105, wm: 407
[   90.284058] [drm:i965_update_wm], self-refresh watermark: display
plane 407 cursor 32
[   90.284061] [drm:i965_update_wm], Setting FIFO watermarks - A: 8,
B: 8, C: 8, SR 407
[   90.284069] [drm:intel_crtc_mode_set], using SSC reference clock of 100 MHz
[   90.284205] [drm:intel_crtc_mode_set], Mode for pipe B:
[   90.284208] [drm:drm_mode_debug_printmodeline], Modeline
8:"1680x1050" 60 120600 1680 1712 1760 1888 1050 1051 1054 1065 0x48
0xa
[   90.340218] [drm:intel_pipe_set_base_atomic], Writing base 00040000
00000000 0 0 6720
[   90.340232] [drm:intel_update_fbc],
[   90.340238] [drm:intel_update_fbc], framebuffer not tiled,
disabling compression
[   90.712447] HDA Intel 0000:00:1b.0: setting latency timer to 64
[   90.715400] [drm:i965_update_wm], self-refresh entries: 105, wm: 407
[   90.715404] [drm:i965_update_wm], self-refresh watermark: display
plane 407 cursor 32
[   90.715409] [drm:i965_update_wm], Setting FIFO watermarks - A: 8,
B: 8, C: 8, SR 407
[   90.715414] [drm:drm_crtc_helper_set_mode], [ENCODER:6:LVDS-6] set
[MODE:8:1680x1050]
[   90.715418] [drm:i965_update_wm], self-refresh entries: 105, wm: 407
[   90.715421] [drm:i965_update_wm], self-refresh watermark: display
plane 407 cursor 32
[   90.715425] [drm:i965_update_wm], Setting FIFO watermarks - A: 8,
B: 8, C: 8, SR 407
[   90.715947] [drm:intel_update_fbc],
[   90.715949] [drm:intel_update_fbc], framebuffer not tiled,
disabling compression
[   90.715957] [drm:intel_panel_set_backlight], set backlight PWM = 12056400
[   90.715961] [drm:intel_panel_get_max_backlight], max backlight PWM = 12056655
[   90.715971] [drm:i915_driver_irq_handler], pipe B underrun
[   90.715975] [drm:intel_opregion_asle_intr], non asle set request??
[   90.715991] [drm:intel_sdvo_debug_write], SDVOB: W: 05 00 00
           (SDVO_CMD_SET_ACTIVE_OUTPUTS)
[   90.721822] [drm:intel_sdvo_read_response], SDVOB: R: (Success)
[   90.851051] HDA Intel 0000:00:1b.0: irq 49 for MSI/MSI-X
[   90.851262] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   90.851311] ata3: SATA link down (SStatus 0 SControl 300)
[   90.874395] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   90.883416] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE
LOCK) filtered out
[   90.893217] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES)
filtered out
[   90.904213] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   90.913208] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE
LOCK) filtered out
[   90.923136] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES)
filtered out
[   90.932873] ata1.00: configured for UDMA/100
[   91.083474] usb 1-2: reset full speed USB device number 2 using uhci_hcd
[   91.098920] [drm:intel_panel_get_max_backlight], max backlight PWM = 12056655
[   91.104116] ata4.00: ACPI cmd ef/03:42:00:00:00:a0 (SET FEATURES)
filtered out
[   91.104126] ata4.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES)
filtered out
[   91.104628] ata4.00: ACPI cmd e3/00:10:00:00:00:a0 (IDLE) succeeded
[   91.105134] ata4.00: ACPI cmd e3/00:03:00:00:00:a0 (IDLE) succeeded
[   91.120777] ata4.00: configured for UDMA/33
[   91.150057] [drm:intel_panel_set_backlight], set backlight PWM = 12056655
[   91.150057] [drm:intel_panel_get_max_backlight], max backlight PWM = 12056655
[   91.150057] [drm:intel_opregion_asle_intr], non asle set request??
[   91.150057] [drm:intel_opregion_asle_intr], non asle set request??
[   91.164389] thinkpad_acpi: ACPI backlight control delay disabled
[   91.337039] usb 1-1: reset full speed USB device number 4 using uhci_hcd
[   91.493268] btusb 1-1:1.0: no reset_resume for driver btusb?
[   91.503555] btusb 1-1:1.1: no reset_resume for driver btusb?
[   91.765796] PM: resume of devices complete after 1602.764 msecs
[   91.778515] PM: Finishing wakeup.
[   91.784420] Restarting tasks ... done.
[   91.847367] systemd[1]: Service bluetooth.target is not needed
anymore. Stopping.
[   91.859726] video LNXVIDEO:00: Restoring backlight state
[   91.869611] [drm:intel_panel_get_max_backlight], max backlight PWM = 12056655
[   91.874455] [drm:intel_panel_set_backlight], set backlight PWM = 12056655
[   91.874455] [drm:intel_panel_get_max_backlight], max backlight PWM = 12056655
[   91.874455] [drm:intel_opregion_asle_intr], non asle set request??
[   91.874455] [drm:intel_opregion_asle_intr], non asle set request??
[   91.874455] [drm:intel_opregion_asle_intr], non asle set request??
[   91.943715] [drm:drm_mode_setcrtc], [CRTC:4]
[   91.948282] [drm:drm_mode_setcrtc], [CONNECTOR:5:LVDS-1]
[   91.953874] [drm:drm_crtc_helper_set_config],
[   91.958817] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:20]
#connectors=1 (x y) (0 0)
[   91.967466] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   91.975357] [drm:intel_pipe_set_base_atomic], Writing base 02992000
00000000 0 0 7168
[   91.984015] [drm:intel_update_fbc],
[   91.987789] [drm:intel_update_fbc], framebuffer too large,
disabling compression
[   92.006896] [drm:drm_mode_getconnector], [CONNECTOR:5:?]
[   92.012550] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:5:LVDS-1]
[   92.020257] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:5:LVDS-1] probed modes :
[   92.029180] [drm:drm_mode_debug_printmodeline], Modeline
16:"1680x1050" 60 120600 1680 1712 1760 1888 1050 1051 1054 1065 0x48
0xa
[   92.041151] [drm:drm_mode_debug_printmodeline], Modeline
17:"1680x1050" 50 100530 1680 1712 1760 1888 1050 1051 1054 1065 0x40
0xa
[   92.053237] [drm:drm_mode_getconnector], [CONNECTOR:5:?]
[   92.060445] [drm:drm_mode_getconnector], [CONNECTOR:12:?]
[   92.065928] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:12:VGA-1]
[   92.081276] [drm:intel_crt_detect], CRT not detected via hotplug
[   92.088039] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:12:VGA-1] disconnected
[   92.097419] [drm:drm_mode_getconnector], [CONNECTOR:12:?]
[   92.103017] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:12:VGA-1]
[   92.120081] [drm:intel_crt_detect], CRT not detected via hotplug
[   92.127465] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:12:VGA-1] disconnected
[   92.138993] [drm:drm_mode_getconnector], [CONNECTOR:15:?]
[   92.144629] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1]
[   92.153455] [drm:intel_sdvo_debug_write], SDVOB: W: 0B
           (SDVO_CMD_GET_ATTACHED_DISPLAYS)
[   92.167960] [drm:intel_sdvo_read_response], SDVOB: R: (Success) 00 00
[   92.180699] [drm:intel_sdvo_detect], SDVO response 0 0 [1]
[   92.186348] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1] disconnected
[   92.195865] [drm:drm_mode_getconnector], [CONNECTOR:15:?]
[   92.201469] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1]
[   92.209019] [drm:intel_sdvo_debug_write], SDVOB: W: 0B
           (SDVO_CMD_GET_ATTACHED_DISPLAYS)
[   92.222524] [drm:intel_sdvo_read_response], SDVOB: R: (Success) 00 00
[   92.234736] [drm:intel_sdvo_detect], SDVO response 0 0 [1]
[   92.240592] [drm:drm_helper_probe_single_connector_modes],
[CONNECTOR:15:DVI-D-1] disconnected
[   92.516709] BUG: unable to handle kernel NULL pointer dereference
at           (null)
[   92.520001] IP: [<          (null)>]           (null)
[   92.520001] PGD 0
[   92.520001] Oops: 0010 [#1] PREEMPT SMP
[   92.520001] last sysfs file:
/sys/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:01/PNP0C09:00/PNP0C0A:00/power_supply/BAT0/voltage_now
[   92.520001] CPU 0
[   92.520001] Modules linked in: ip6_tables ebtable_nat ebtables
iptable_mangle xt_tcpudp tun bridge ipv6 stp llc sunrpc ipt_REJECT
xt_physdev xt_state iptable_filter ipt_MASQUERADE iptable_nat nf_nat
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
dm_mirror dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb
bluetooth virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr
aead crypto_algapi snd_hda_intel iwl3945 snd_hda_codec snd_seq
snd_seq_device iwl_legacy snd_pcm wmi psmouse mac80211 serio_raw
e1000e thinkpad_acpi snd_timer iTCO_wdt cfg80211 snd i2c_i801
soundcore snd_page_alloc iTCO_vendor_support nvram evdev i915
drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 usbhid hid
pcmcia sdhci_pci ehci_hcd uhci_hcd sdhci sr_mod mmc_core yenta_socket
cdrom usbcore video backlight [last unloaded: scsi_wait_scan]
[   92.520001]
[   92.520001] Pid: 0, comm: swapper Not tainted
2.6.39-rc2-00005-gf04d4dc #120 LENOVO 6464CTO/6464CTO
[   92.520001] RIP: 0010:[<0000000000000000>]  [<          (null)>]
       (null)
[   92.520001] RSP: 0018:ffff88013ba03de8  EFLAGS: 00010246
[   92.520001] RAX: ffffffff8180b020 RBX: ffff8801318d6350 RCX: 0000000000000000
[   92.520001] RDX: 0000000000000025 RSI: 0000000000000000 RDI: 0000000000000000
[   92.520001] RBP: ffff88013ba03ec0 R08: 0000000000000000 R09: 0000000000000000
[   92.520001] R10: 0000000000000000 R11: 0000000000000001 R12: ffffffff81b72340
[   92.520001] R13: ffff88013ba03e80 R14: 0000000000000102 R15: ffffffff81801fd8
[   92.520001] FS:  0000000000000000(0000) GS:ffff88013ba00000(0000)
knlGS:0000000000000000
[   92.520001] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   92.520001] CR2: 0000000000000000 CR3: 0000000001803000 CR4: 00000000000006f0
[   92.520001] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   92.520001] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   92.520001] Process swapper (pid: 0, threadinfo ffffffff81800000,
task ffffffff8180b020)
[   92.520001] Stack:
[   92.520001]  ffffffff81061b36 ffffffff81061aa1 0000000000000000
ffffffff8107a50f
[   92.520001]  ffff880100000000 ffff880139195900 ffffffff81801fd8
ffff88013ba0e0d8
[   92.520001]  ffff88013ba03f50 ffffffff81801fd8 ffffffff81801fd8
0000000000000000
[   92.520001] Call Trace:
[   92.520001]  <IRQ>
[   92.520001]  [<ffffffff81061b36>] ? run_timer_softirq+0x186/0x6c0
[   92.520001]  [<ffffffff81061aa1>] ? run_timer_softirq+0xf1/0x6c0
[   92.520001]  [<ffffffff8107a50f>] ? __run_hrtimer+0x7f/0x370
[   92.520001]  [<ffffffff8105870c>] __do_softirq+0xbc/0x3e0
[   92.520001]  [<ffffffff8149d2cc>] call_softirq+0x1c/0x30
[   92.520001]  [<ffffffff8100433d>] do_softirq+0x8d/0xc0
[   92.520001]  [<ffffffff81058d86>] irq_exit+0x96/0xd0
[   92.520001]  [<ffffffff8149daad>] smp_apic_timer_interrupt+0x6d/0x9a
[   92.520001]  [<ffffffff8149ce53>] apic_timer_interrupt+0x13/0x20
[   92.520001]  <EOI>
[   92.520001]  [<ffffffff810886cf>] ? tick_nohz_stop_sched_tick+0x2af/0x400
[   92.520001]  [<ffffffff8100119d>] cpu_idle+0x2d/0xd0
[   92.520001]  [<ffffffff81474e7c>] rest_init+0xd0/0xe4
[   92.520001]  [<ffffffff81474dac>] ? csum_partial_copy_generic+0x16c/0x16c
[   92.520001]  [<ffffffff81a6eb84>] start_kernel+0x388/0x393
[   92.520001]  [<ffffffff81a6e322>] x86_64_start_reservations+0x132/0x136
[   92.520001]  [<ffffffff81a6e416>] x86_64_start_kernel+0xf0/0xf7
[   92.520001] Code:  Bad RIP value.
[   92.520001] RIP  [<          (null)>]           (null)
[   92.520001]  RSP <ffff88013ba03de8>
[   92.520001] CR2: 0000000000000000
[   92.520001] [drm:drm_crtc_helper_set_config],
[   92.520001] [drm:drm_crtc_helper_set_config], [CRTC:4] [FB:9]
#connectors=1 (x y) (0 0)
[   92.520001] [drm:drm_crtc_helper_set_config], [CONNECTOR:5:LVDS-1]
to [CRTC:4]
[   92.520001] BUG: scheduling while atomic: swapper/0/0x00000103
[   92.520001] INFO: lockdep is turned off.
[   92.520001] Modules linked in: ip6_tables ebtable_nat ebtables
iptable_mangle xt_tcpudp tun bridge ipv6 stp llc sunrpc ipt_REJECT
xt_physdev xt_state iptable_filter ipt_MASQUERADE iptable_nat nf_nat
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
dm_mirror dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb
bluetooth virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr
aead crypto_algapi snd_hda_intel iwl3945 snd_hda_codec snd_seq
snd_seq_device iwl_legacy snd_pcm wmi psmouse mac80211 serio_raw
e1000e thinkpad_acpi snd_timer iTCO_wdt cfg80211 snd i2c_i801
soundcore snd_page_alloc iTCO_vendor_support nvram evdev i915
drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 usbhid hid
pcmcia sdhci_pci ehci_hcd uhci_hcd sdhci sr_mod mmc_core yenta_socket
cdrom usbcore video backlight [last unloaded: scsi_wait_scan]
[   92.520001] irq event stamp: 3031954
[   92.520001] hardirqs last  enabled at (3031954):
[<ffffffff81498217>] do_page_fault+0x2a7/0x550
[   92.520001] hardirqs last disabled at (3031953):
[<ffffffff81495843>] error_sti+0x5/0x6
[   92.520001] softirqs last  enabled at (3031948):
[<ffffffff810575c3>] _local_bh_enable+0x13/0x20
[   92.520001] softirqs last disabled at (3031949):
[<ffffffff8149d2cc>] call_softirq+0x1c/0x30
[   92.520001] CPU 0
[   92.520001] Modules linked in: ip6_tables ebtable_nat ebtables
iptable_mangle xt_tcpudp tun bridge ipv6 stp llc sunrpc ipt_REJECT
xt_physdev xt_state iptable_filter ipt_MASQUERADE iptable_nat nf_nat
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
dm_mirror dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb
bluetooth virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr
aead crypto_algapi snd_hda_intel iwl3945 snd_hda_codec snd_seq
snd_seq_device iwl_legacy snd_pcm wmi psmouse mac80211 serio_raw
e1000e thinkpad_acpi snd_timer iTCO_wdt cfg80211 snd i2c_i801
soundcore snd_page_alloc iTCO_vendor_support nvram evdev i915
drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 usbhid hid
pcmcia sdhci_pci ehci_hcd uhci_hcd sdhci sr_mod mmc_core yenta_socket
cdrom usbcore video backlight [last unloaded: scsi_wait_scan]
[   92.520001]
[   92.520001] Pid: 0, comm: swapper Not tainted
2.6.39-rc2-00005-gf04d4dc #120 LENOVO 6464CTO/6464CTO
[   92.520001] RIP: 0010:[<ffffffff810886cf>]  [<ffffffff810886cf>]
tick_nohz_stop_sched_tick+0x2af/0x400
[   92.520001] RSP: 0018:ffffffff81801eb8  EFLAGS: 00000202
[   92.520001] RAX: 00000000002e4389 RBX: 0000000000000001 RCX: 0000000000000000
[   92.520001] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff8180b020
[   92.520001] RBP: ffffffff81801f08 R08: 0000000000000000 R09: 0000000000000000
[   92.520001] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff8149ce4e
[   92.520001] R13: 000000158a6c17fe R14: 0000000100000001 R15: 00000000ffff0cda
[   92.520001] FS:  0000000000000000(0000) GS:ffff88013ba00000(0000)
knlGS:0000000000000000
[   92.520001] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   92.520001] CR2: ffffffffffffffd5 CR3: 0000000001803000 CR4: 00000000000006f0
[   92.520001] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   92.520001] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   92.520001] Process swapper (pid: 0, threadinfo ffffffff81800000,
task ffffffff8180b020)
[   92.520001] Stack:
[   92.520001]  00000021d451b4ce 00000000ffff0cda 000000158a394c32
00000000ffff0cda
[   92.520001]  ffffffffffffffff ffffffff81801fd8 ffffffff818945c8
ffff88013bf8b880
[   92.520001]  ffffffffffffffff 0000000000000000 ffffffff81801f28
ffffffff8100119d
[   92.520001] Call Trace:
[   92.520001]  [<ffffffff8100119d>] cpu_idle+0x2d/0xd0
[   92.520001]  [<ffffffff81474e7c>] rest_init+0xd0/0xe4
[   92.520001]  [<ffffffff81474dac>] ? csum_partial_copy_generic+0x16c/0x16c
[   92.520001]  [<ffffffff81a6eb84>] start_kernel+0x388/0x393
[   92.520001]  [<ffffffff81a6e322>] x86_64_start_reservations+0x132/0x136
[   92.520001]  [<ffffffff81a6e416>] x86_64_start_kernel+0xf0/0xf7
[   92.520001] Code: 00 48 8b 45 c8 48 89 83 d0 00 00 00 49 8b 47 70
4c 29 f0 48 89 83 c8 00 00 00 41 f7 c5 00 02 00 00 74 21 e8 04 7f 00
00 41 55 9d
[   92.520001]  8b 5d d8 4c 8b 65 e0 4c 8b 6d e8 4c 8b 75 f0 4c 8b 7d f8 c9
[   92.520001] Call Trace:
[   92.520001]  [<ffffffff8100119d>] cpu_idle+0x2d/0xd0
[   92.520001]  [<ffffffff81474e7c>] rest_init+0xd0/0xe4
[   92.520001]  [<ffffffff81474dac>] ? csum_partial_copy_generic+0x16c/0x16c
[   92.520001]  [<ffffffff81a6eb84>] start_kernel+0x388/0x393
[   92.520001]  [<ffffffff81a6e322>] x86_64_start_reservations+0x132/0x136
[   92.520001]  [<ffffffff81a6e416>] x86_64_start_kernel+0xf0/0xf7
[   93.421820] bad: scheduling from the idle thread!
[   93.423405] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow
Control: None




>
>> >> I've strong believe - it's the moment  where USB_DEBUG version was
>> >> printing those lines in endless loop.
>> >> (Or let say it this way:   More then few minutes loop  - as maybe it
>> >> will end within a week - but I don't have that much time to wait ;))
>> >
>> > Those debugging messages will continue for as long as the hardware
>> > fails to respond properly.
>>
>> Which is probably 'forever' when the machine is suspending.
>> (note - even SysRq+B  no longer works at this moment)
>
> No, when the machine is suspending there should not be any errors
> because there should not be any USB traffic.  All the ongoing transfers
> are cancelled as part of the suspend transition, and they start up
> again during resume.

Hmm so there could be some difference between  pm-suspend - and 'echo mem'
but why pm-suspend should initiate any USB traffic ??

Anyway I think current OOPS needs to be fixed first before any futher
debug could be done.

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/11 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
> 2011/4/8 Alan Stern <stern@rowland.harvard.edu>:
>> On Fri, 8 Apr 2011, Zdenek Kabelac wrote:
>>
>>> Most probably because I've run  in the loop
>>>
>>> while : ; do pm-suspend ; sleep 5; done
>>>
>>> for debug purposes...
>>>
>>>
>>> >> [   53.851937] btusb_intr_complete: hci0 urb ffff88011735c300 failed
>>> >> to resubmit (19)
>>> >> [   53.855223] btusb_bulk_complete: hci0 urb ffff88011735c540 failed
>>> >> to resubmit (19)
>>> >> [   53.867211] btusb_bulk_complete: hci0 urb ffff88011735c9c0 failed
>>> >> to resubmit (19)
>>> >> [   53.875279] btusb_send_frame: hci0 urb ffff880117204d80 submission failed
>>> >> [   54.127633] systemd[1]: Service bluetooth.target is not needed
>>> >> anymore. Stopping.
>>> >> [   54.205292] PM: Syncing filesystems ... done.
>>> >> [   54.216056] PM: Preparing system for mem sleep
>>> >>
>>> >> And system was 'dead' - (Moon sign on laptop was already blinking at
>>> >> this moment)
>>> >
>>> > Why did the system suspend like this?  A software undock shouldn't
>>> > cause a suspend.
>>>
>>> pm-suspend - with  script executed on suspend which undocks laptop
>>> (otherwise when I'd forget to press button on docking station before
>>> suspend - it would stay 'red' mode - thus all buses are connected -
>>> and as I've noticed in past - it's not working well, when I unplug
>>> laptop in this 'still connected'  mode - so this software 'undock'
>>> solved this problem)
>>
>> All right.  It looks like there are two possible sources of problems
>> here: the undock and the suspend.  It would be best to debug them
>> separately.
>>
>> For example, if you change the loop above to just do the undock and
>> redock without suspending, do the problems still occur?
>>
>> Another thing to try: Suspend by doing "echo ram >/sys/power/state"
>> instead of running pm_suspend.
>
> hmm - using   "echo mem >/sys/power/state" revealed probably
> completely new problem - unsure how this is related to this USB
> problem - but it leaves the machine in completely 'frozen' picture on
> desktop after resume.
>
> So here is cut&paste captured on serial console:
> (Kernel without USB_DEBUG - bluetooth enabled)
>
>

> [   92.222524] [drm:intel_sdvo_read_response], SDVOB: R: (Success) 00 00
> [   92.234736] [drm:intel_sdvo_detect], SDVO response 0 0 [1]
> [   92.240592] [drm:drm_helper_probe_single_connector_modes],
> [CONNECTOR:15:DVI-D-1] disconnected
> [   92.516709] BUG: unable to handle kernel NULL pointer dereference
> at           (null)
> [   92.520001] IP: [<          (null)>]           (null)
> [   92.520001] PGD 0
> [   92.520001] Oops: 0010 [#1] PREEMPT SMP
> [   92.520001] last sysfs file:
> /sys/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:01/PNP0C09:00/PNP0C0A:00/power_supply/BAT0/voltage_now
> [   92.520001] CPU 0


Ok - add some more memory debug:

[   13.347268] usb 1-1: USB disconnect, device number 3
[   13.348113] btusb_bulk_complete: hci0 urb ffff8801367f6528 failed
to resubmit (19)
[   13.349111] btusb_intr_complete: hci0 urb ffff8801367f6840 failed
to resubmit (19)
[   13.349143] btusb_bulk_complete: hci0 urb ffff8801367fa630 failed
to resubmit (19)
[   13.409856] general protection fault: 0000 [#1] PREEMPT SMP
[   13.413340] last sysfs file:
/sys/devices/pci0000:00/0000:00:19.0/net/eth0/uevent
[   13.413340] CPU 0
[   13.413340] Modules linked in: ipt_REJECT xt_physdev xt_state
iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
nf_conntrack nf_defrag_ipv4 ip_tables x_tables dm_mirror
dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb bluetooth
virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr aead
crypto_algapi iwl3945 iwl_legacy snd_hda_intel snd_hda_codec usbhid
snd_seq snd_seq_device mac80211 hid iTCO_wdt iTCO_vendor_support
snd_pcm psmouse i2c_i801 serio_raw cfg80211 thinkpad_acpi snd_timer
snd e1000e soundcore snd_page_alloc nvram wmi evdev i915
drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 pcmcia
uhci_hcd ehci_hcd sdhci_pci sdhci sr_mod mmc_core yenta_socket cdrom
usbcore video backlight [last unloaded: scsi_wait_scan]
[   13.413340]
[   13.413340] Pid: 815, comm: bluetoothd Not tainted
2.6.39-rc2-00144-gca71856 #121 LENOVO 6464CTO/6464CTO
[   13.413340] RIP: 0010:[<ffffffff8109ae43>]  [<ffffffff8109ae43>]
module_put+0x33/0x1b0
[   13.413340] RSP: 0018:ffff8801389e1d68  EFLAGS: 00010296
[   13.413340] RAX: ffffffffa04a32a6 RBX: 6b6b6b6b6b6b6b6b RCX: 0000000000000000
[   13.413340] RDX: 0000000000000000 RSI: ffffffffa04a32a6 RDI: ffffffff8109ae43
[   13.413340] RBP: ffff8801389e1d98 R08: 0000000000000000 R09: 0000000000000000
[   13.413340] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88013b028590
[   13.413340] R13: 00000000ffffffed R14: ffff8801390ac7b0 R15: 000000000000000a
[   13.413340] FS:  00007fe99d67d720(0000) GS:ffff88013ba00000(0000)
knlGS:0000000000000000
[   13.413340] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   13.413340] CR2: 00007fe99d4902b0 CR3: 0000000134dea000 CR4: 00000000000006f0
[   13.413340] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   13.413340] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   13.413340] Process bluetoothd (pid: 815, threadinfo
ffff8801389e0000, task ffff8801387d23a0)
[   13.413340] Stack:
[   13.413340]  ffff88013b028000 ffff88013b028000 ffff88013b028590
00000000ffffffed
[   13.413340]  ffff8801390ac7b0 000000000000000a ffff8801389e1de8
ffffffffa04a32a6
[   13.413340]  ffff8801389e1db8 ffffffff8124f11a ffff8801389e1dd8
00000000400448c9
[   13.413340] Call Trace:
[   13.413340]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.413340]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
[   13.413340]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]
[   13.413340]  [<ffffffff8107c0a3>] ? up_read+0x23/0x40
[   13.413340]  [<ffffffff813ca9c1>] sock_do_ioctl.constprop.17+0x21/0x60
[   13.413340]  [<ffffffff813caa62>] sock_ioctl+0x62/0x2d0
[   13.413340]  [<ffffffff8115f268>] do_vfs_ioctl+0x98/0x570
[   13.413340]  [<ffffffff8114d901>] ? fget_light+0x3c1/0x430
[   13.413340]  [<ffffffff8149ac1c>] ? sysret_check+0x27/0x62
[   13.413340]  [<ffffffff8115f7d1>] sys_ioctl+0x91/0xa0
[   13.413340]  [<ffffffff8149abeb>] system_call_fastpath+0x16/0x1b
[   13.413340] Code: 48 89 5d d8 4c 89 65 e0 4c 89 6d e8 4c 89 75 f0
4c 89 7d f8 0f 1f 44 00 00 48 85 ff 48 89 fb 74 49 bf 01 00 00 00 e8
dd be 3f 00
[   13.413340]  8b 83 40 02 00 00 65 ff 40 04 4c 8b 6d 08 0f 1f 44 00 00 83
[   13.413340] RIP  [<ffffffff8109ae43>] module_put+0x33/0x1b0
[   13.413340]  RSP <ffff8801389e1d68>
[   13.414647] ---[ end trace 061b48d6d00e7105 ]---
[   13.414651] note: bluetoothd[815] exited with preempt_count 1
[   13.414654] BUG: sleeping function called from invalid context at
kernel/rwsem.c:21
[   13.414657] in_atomic(): 1, irqs_disabled(): 0, pid: 815, name: bluetoothd
[   13.414658] INFO: lockdep is turned off.
[   13.414661] Pid: 815, comm: bluetoothd Tainted: G      D
2.6.39-rc2-00144-gca71856 #121
[   13.414663] Call Trace:
[   13.414667]  [<ffffffff81037ce7>] __might_sleep+0xf7/0x120
[   13.414672]  [<ffffffff81491eb6>] down_read+0x26/0x93
[   13.414677]  [<ffffffff810a6abb>] acct_collect+0x4b/0x1b0
[   13.414683]  [<ffffffff81054ba2>] do_exit+0x632/0x8e0
[   13.414686]  [<ffffffff81051ec9>] ? kmsg_dump+0x79/0x170
[   13.414690]  [<ffffffff81494b02>] oops_end+0xa2/0xf0
[   13.414694]  [<ffffffff81005ca8>] die+0x58/0x90
[   13.414697]  [<ffffffff81494462>] do_general_protection+0x162/0x170
[   13.414701]  [<ffffffff81493bf4>] ? restore_args+0x30/0x30
[   13.414704]  [<ffffffff81493daf>] general_protection+0x1f/0x30
[   13.414711]  [<ffffffffa04a32a6>] ? hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414717]  [<ffffffffa04a32a6>] ? hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414721]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414723]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414726]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414732]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414735]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
[   13.414742]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]
[   13.414746]  [<ffffffff8107c0a3>] ? up_read+0x23/0x40
[   13.414749]  [<ffffffff813ca9c1>] sock_do_ioctl.constprop.17+0x21/0x60
[   13.414752]  [<ffffffff813caa62>] sock_ioctl+0x62/0x2d0
[   13.414755]  [<ffffffff8115f268>] do_vfs_ioctl+0x98/0x570
[   13.414759]  [<ffffffff8114d901>] ? fget_light+0x3c1/0x430
[   13.414762]  [<ffffffff8149ac1c>] ? sysret_check+0x27/0x62
[   13.414765]  [<ffffffff8115f7d1>] sys_ioctl+0x91/0xa0
[   13.414768]  [<ffffffff8149abeb>] system_call_fastpath+0x16/0x1b
[   13.414789] BUG: scheduling while atomic: bluetoothd/815/0x10000002
[   13.414791] INFO: lockdep is turned off.
[   13.414792] Modules linked in: ipt_REJECT xt_physdev xt_state
iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
nf_conntrack nf_defrag_ipv4 ip_tables x_tables dm_mirror
dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb bluetooth
virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr aead
crypto_algapi iwl3945 iwl_legacy snd_hda_intel snd_hda_codec usbhid
snd_seq snd_seq_device mac80211 hid iTCO_wdt iTCO_vendor_support
snd_pcm psmouse i2c_i801 serio_raw cfg80211 thinkpad_acpi snd_timer
snd e1000e soundcore snd_page_alloc nvram wmi evdev i915
drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 pcmcia
uhci_hcd ehci_hcd sdhci_pci sdhci sr_mod mmc_core yenta_socket cdrom
usbcore video backlight [last unloaded: scsi_wait_scan]
[   13.414835] Pid: 815, comm: bluetoothd Tainted: G      D
2.6.39-rc2-00144-gca71856 #121
[   13.414837] Call Trace:
[   13.414841]  [<ffffffff8148775f>] __schedule_bug+0x72/0x77
[   13.414844]  [<ffffffff8148fe7d>] schedule+0xcbd/0xce0
[   13.414848]  [<ffffffff8111e51b>] ? unmap_vmas+0x3bb/0xa80
[   13.414852]  [<ffffffff81048328>] __cond_resched+0x18/0x30
[   13.414855]  [<ffffffff814901c5>] _cond_resched+0x35/0x40
[   13.414858]  [<ffffffff8111e973>] unmap_vmas+0x813/0xa80
[   13.414862]  [<ffffffff81493595>] ? _raw_spin_unlock_irqrestore+0x65/0x80
[   13.414867]  [<ffffffff811266bd>] exit_mmap+0xed/0x1c0
[   13.414870]  [<ffffffff8104caf3>] mmput+0x73/0x110
[   13.414873]  [<ffffffff81052550>] exit_mm+0x120/0x150
[   13.414877]  [<ffffffff8149360b>] ? _raw_spin_unlock_irq+0x5b/0x60
[   13.414880]  [<ffffffff810546c6>] do_exit+0x156/0x8e0
[   13.414883]  [<ffffffff81051ec9>] ? kmsg_dump+0x79/0x170
[   13.414886]  [<ffffffff81494b02>] oops_end+0xa2/0xf0
[   13.414889]  [<ffffffff81005ca8>] die+0x58/0x90
[   13.414892]  [<ffffffff81494462>] do_general_protection+0x162/0x170
[   13.414895]  [<ffffffff81493bf4>] ? restore_args+0x30/0x30
[   13.414899]  [<ffffffff81493daf>] general_protection+0x1f/0x30
[   13.414906]  [<ffffffffa04a32a6>] ? hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414912]  [<ffffffffa04a32a6>] ? hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414915]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414918]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414920]  [<ffffffff8109ae43>] ? module_put+0x33/0x1b0
[   13.414927]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
[   13.414930]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
[   13.414936]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]
[   13.414940]  [<ffffffff8107c0a3>] ? up_read+0x23/0x40
[   13.414943]  [<ffffffff813ca9c1>] sock_do_ioctl.constprop.17+0x21/0x60
[   13.414947]  [<ffffffff813caa62>] sock_ioctl+0x62/0x2d0
[   13.414950]  [<ffffffff8115f268>] do_vfs_ioctl+0x98/0x570
[   13.414953]  [<ffffffff8114d901>] ? fget_light+0x3c1/0x430
[   13.414957]  [<ffffffff8149ac1c>] ? sysret_check+0x27/0x62
[   13.414960]  [<ffffffff8115f7d1>] sys_ioctl+0x91/0xa0
[   13.414963]  [<ffffffff8149abeb>] system_call_fastpath+0x16/0x1b
[   14.411762] =============================================================================
[   14.411765] BUG kmalloc-4096: Poison overwritten
[   14.411767] -----------------------------------------------------------------------------
[   14.411768]
[   14.411771] INFO: 0xffff88013b028058-0xffff88013b028058. First byte
0x6a instead of 0x6b
[   14.411785] INFO: Allocated in hci_alloc_dev+0x30/0x90 [bluetooth]
age=1314 cpu=1 pid=565
[   14.411793] INFO: Freed in bt_host_release+0x16/0x20 [bluetooth]
age=305 cpu=0 pid=242
[   14.411796] INFO: Slab 0xffffea00044e88c0 objects=7 used=6
fp=0xffff88013b028000 flags=0x80000000000040c1
[   14.411799] INFO: Object 0xffff88013b028000 @offset=0 fp=0x          (null)
[   14.411801]
[   14.411803]   Object 0xffff88013b028000:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[   14.411814]   Object 0xffff88013b028010:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
....  skipped ....
[   14.413340]   Object 0xffff88013b028fc0:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[   14.413340]   Object 0xffff88013b028fd0:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[   14.413340]   Object 0xffff88013b028fe0:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[   14.413340]   Object 0xffff88013b028ff0:  6b 6b 6b 6b 6b 6b 6b 6b
6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk¥
[   14.413340]  Redzone 0xffff88013b029000:  bb bb bb bb bb bb bb bb
                      »»»»»»»»
[   14.413340]  Padding 0xffff88013b029040:  5a 5a 5a 5a 5a 5a 5a 5a
                      ZZZZZZZZ
[   14.413340] Pid: 842, comm: systemd-cgroups Tainted: G      D
2.6.39-rc2-00144-gca71856 #121
[   14.413340] Call Trace:
[   14.413340]  [<ffffffff8113d773>] print_trailer+0xf3/0x160
[   14.413340]  [<ffffffff8113d92d>] check_bytes_and_report+0xfd/0x140
[   14.413340]  [<ffffffff8113ea0a>] check_object+0x22a/0x270
[   14.413340]  [<ffffffff8116ff70>] ? seq_read+0x250/0x3f0
[   14.413340]  [<ffffffff8116ff70>] ? seq_read+0x250/0x3f0
[   14.413340]  [<ffffffff8148adab>] alloc_debug_processing+0x91/0x117
[   14.413340]  [<ffffffff8148b3e5>] __slab_alloc.constprop.25+0x2b1/0x2fe
[   14.413340]  [<ffffffff8116ff70>] ? seq_read+0x250/0x3f0
[   14.413340]  [<ffffffff8116fd5f>] ? seq_read+0x3f/0x3f0
[   14.413340]  [<ffffffff8116ff70>] ? seq_read+0x250/0x3f0
[   14.413340]  [<ffffffff8113ffc3>] kmem_cache_alloc_trace+0x243/0x250
[   14.413340]  [<ffffffff8116fd20>] ? seq_lseek+0x120/0x120
[   14.413340]  [<ffffffff8116ff70>] seq_read+0x250/0x3f0
[   14.413340]  [<ffffffff81496ce9>] ? sub_preempt_count+0xa9/0xe0
[   14.413340]  [<ffffffff8116fd20>] ? seq_lseek+0x120/0x120
[   14.413340]  [<ffffffff811a7dd3>] proc_reg_read+0x83/0xc0
[   14.413340]  [<ffffffff8114bb63>] vfs_read+0xb3/0x180
[   14.413340]  [<ffffffff8114bc7d>] sys_read+0x4d/0x90
[   14.413340]  [<ffffffff8149abeb>] system_call_fastpath+0x16/0x1b
[   14.413340] FIX kmalloc-4096: Restoring
0xffff88013b028058-0xffff88013b028058=0x6b
[   14.413340]
[   14.413340] FIX kmalloc-4096: Marking all objects used


So - it looks like disabling BT in runtime is not enough  to avoid problems ;)

So I've blacklisted  bluetooth & btusb -  and made quite several
suspend/resume cycles  -
and without  a single problem.

So I'll keep an eye on this - but so far complete deactivation of BT
either in BIOS or modules blacklisting solves the problem of weird
USB deadlocking.

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

On Mon, 11 Apr 2011, Zdenek Kabelac wrote:

> Ok - add some more memory debug:
> 
> [   13.347268] usb 1-1: USB disconnect, device number 3
> [   13.348113] btusb_bulk_complete: hci0 urb ffff8801367f6528 failed
> to resubmit (19)
> [   13.349111] btusb_intr_complete: hci0 urb ffff8801367f6840 failed
> to resubmit (19)
> [   13.349143] btusb_bulk_complete: hci0 urb ffff8801367fa630 failed
> to resubmit (19)
> [   13.409856] general protection fault: 0000 [#1] PREEMPT SMP
> [   13.413340] last sysfs file:
> /sys/devices/pci0000:00/0000:00:19.0/net/eth0/uevent
> [   13.413340] CPU 0
> [   13.413340] Modules linked in: ipt_REJECT xt_physdev xt_state
> iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
> nf_conntrack nf_defrag_ipv4 ip_tables x_tables dm_mirror
> dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb bluetooth
> virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr aead
> crypto_algapi iwl3945 iwl_legacy snd_hda_intel snd_hda_codec usbhid
> snd_seq snd_seq_device mac80211 hid iTCO_wdt iTCO_vendor_support
> snd_pcm psmouse i2c_i801 serio_raw cfg80211 thinkpad_acpi snd_timer
> snd e1000e soundcore snd_page_alloc nvram wmi evdev i915
> drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 pcmcia
> uhci_hcd ehci_hcd sdhci_pci sdhci sr_mod mmc_core yenta_socket cdrom
> usbcore video backlight [last unloaded: scsi_wait_scan]
> [   13.413340]
> [   13.413340] Pid: 815, comm: bluetoothd Not tainted
> 2.6.39-rc2-00144-gca71856 #121 LENOVO 6464CTO/6464CTO
> [   13.413340] RIP: 0010:[<ffffffff8109ae43>]  [<ffffffff8109ae43>]
> module_put+0x33/0x1b0
> [   13.413340] RSP: 0018:ffff8801389e1d68  EFLAGS: 00010296
> [   13.413340] RAX: ffffffffa04a32a6 RBX: 6b6b6b6b6b6b6b6b RCX: 0000000000000000
> [   13.413340] RDX: 0000000000000000 RSI: ffffffffa04a32a6 RDI: ffffffff8109ae43
> [   13.413340] RBP: ffff8801389e1d98 R08: 0000000000000000 R09: 0000000000000000
> [   13.413340] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88013b028590
> [   13.413340] R13: 00000000ffffffed R14: ffff8801390ac7b0 R15: 000000000000000a
> [   13.413340] FS:  00007fe99d67d720(0000) GS:ffff88013ba00000(0000)
> knlGS:0000000000000000
> [   13.413340] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [   13.413340] CR2: 00007fe99d4902b0 CR3: 0000000134dea000 CR4: 00000000000006f0
> [   13.413340] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   13.413340] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [   13.413340] Process bluetoothd (pid: 815, threadinfo
> ffff8801389e0000, task ffff8801387d23a0)
> [   13.413340] Stack:
> [   13.413340]  ffff88013b028000 ffff88013b028000 ffff88013b028590
> 00000000ffffffed
> [   13.413340]  ffff8801390ac7b0 000000000000000a ffff8801389e1de8
> ffffffffa04a32a6
> [   13.413340]  ffff8801389e1db8 ffffffff8124f11a ffff8801389e1dd8
> 00000000400448c9
> [   13.413340] Call Trace:
> [   13.413340]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
> [   13.413340]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
> [   13.413340]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]

> So - it looks like disabling BT in runtime is not enough  to avoid problems ;)
> 
> So I've blacklisted  bluetooth & btusb -  and made quite several
> suspend/resume cycles  -
> and without  a single problem.
> 
> So I'll keep an eye on this - but so far complete deactivation of BT
> either in BIOS or modules blacklisting solves the problem of weird
> USB deadlocking.

Clearly there's something going wrong in the Bluetooth drivers.  You 
should try posting some of this on the linux-bluetooth mailing list.

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
> On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
>
>> Ok - add some more memory debug:
>>
>> [   13.347268] usb 1-1: USB disconnect, device number 3
>> [   13.348113] btusb_bulk_complete: hci0 urb ffff8801367f6528 failed
>> to resubmit (19)
>> [   13.349111] btusb_intr_complete: hci0 urb ffff8801367f6840 failed
>> to resubmit (19)
>> [   13.349143] btusb_bulk_complete: hci0 urb ffff8801367fa630 failed
>> to resubmit (19)
>> [   13.409856] general protection fault: 0000 [#1] PREEMPT SMP
>> [   13.413340] last sysfs file:
>> /sys/devices/pci0000:00/0000:00:19.0/net/eth0/uevent
>> [   13.413340] CPU 0
>> [   13.413340] Modules linked in: ipt_REJECT xt_physdev xt_state
>> iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
>> nf_conntrack nf_defrag_ipv4 ip_tables x_tables dm_mirror
>> dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb bluetooth
>> virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr aead
>> crypto_algapi iwl3945 iwl_legacy snd_hda_intel snd_hda_codec usbhid
>> snd_seq snd_seq_device mac80211 hid iTCO_wdt iTCO_vendor_support
>> snd_pcm psmouse i2c_i801 serio_raw cfg80211 thinkpad_acpi snd_timer
>> snd e1000e soundcore snd_page_alloc nvram wmi evdev i915
>> drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 pcmcia
>> uhci_hcd ehci_hcd sdhci_pci sdhci sr_mod mmc_core yenta_socket cdrom
>> usbcore video backlight [last unloaded: scsi_wait_scan]
>> [   13.413340]
>> [   13.413340] Pid: 815, comm: bluetoothd Not tainted
>> 2.6.39-rc2-00144-gca71856 #121 LENOVO 6464CTO/6464CTO
>> [   13.413340] RIP: 0010:[<ffffffff8109ae43>]  [<ffffffff8109ae43>]
>> module_put+0x33/0x1b0
>> [   13.413340] RSP: 0018:ffff8801389e1d68  EFLAGS: 00010296
>> [   13.413340] RAX: ffffffffa04a32a6 RBX: 6b6b6b6b6b6b6b6b RCX: 0000000000000000
>> [   13.413340] RDX: 0000000000000000 RSI: ffffffffa04a32a6 RDI: ffffffff8109ae43
>> [   13.413340] RBP: ffff8801389e1d98 R08: 0000000000000000 R09: 0000000000000000
>> [   13.413340] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88013b028590
>> [   13.413340] R13: 00000000ffffffed R14: ffff8801390ac7b0 R15: 000000000000000a
>> [   13.413340] FS:  00007fe99d67d720(0000) GS:ffff88013ba00000(0000)
>> knlGS:0000000000000000
>> [   13.413340] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> [   13.413340] CR2: 00007fe99d4902b0 CR3: 0000000134dea000 CR4: 00000000000006f0
>> [   13.413340] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> [   13.413340] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> [   13.413340] Process bluetoothd (pid: 815, threadinfo
>> ffff8801389e0000, task ffff8801387d23a0)
>> [   13.413340] Stack:
>> [   13.413340]  ffff88013b028000 ffff88013b028000 ffff88013b028590
>> 00000000ffffffed
>> [   13.413340]  ffff8801390ac7b0 000000000000000a ffff8801389e1de8
>> ffffffffa04a32a6
>> [   13.413340]  ffff8801389e1db8 ffffffff8124f11a ffff8801389e1dd8
>> 00000000400448c9
>> [   13.413340] Call Trace:
>> [   13.413340]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
>> [   13.413340]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
>> [   13.413340]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]
>
>> So - it looks like disabling BT in runtime is not enough  to avoid problems ;)
>>
>> So I've blacklisted  bluetooth & btusb -  and made quite several
>> suspend/resume cycles  -
>> and without  a single problem.
>>
>> So I'll keep an eye on this - but so far complete deactivation of BT
>> either in BIOS or modules blacklisting solves the problem of weird
>> USB deadlocking.
>
> Clearly there's something going wrong in the Bluetooth drivers.  You
> should try posting some of this on the linux-bluetooth mailing list.

I've created:

https://bugzilla.kernel.org/show_bug.cgi?id=33062

and I'm cc-ing linux-bluetooth.

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/11 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
> 2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
>> On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
>>
>>> Ok - add some more memory debug:
>>>
>>> [   13.347268] usb 1-1: USB disconnect, device number 3
>>> [   13.348113] btusb_bulk_complete: hci0 urb ffff8801367f6528 failed
>>> to resubmit (19)
>>> [   13.349111] btusb_intr_complete: hci0 urb ffff8801367f6840 failed
>>> to resubmit (19)
>>> [   13.349143] btusb_bulk_complete: hci0 urb ffff8801367fa630 failed
>>> to resubmit (19)
>>> [   13.409856] general protection fault: 0000 [#1] PREEMPT SMP
>>> [   13.413340] last sysfs file:
>>> /sys/devices/pci0000:00/0000:00:19.0/net/eth0/uevent
>>> [   13.413340] CPU 0
>>> [   13.413340] Modules linked in: ipt_REJECT xt_physdev xt_state
>>> iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
>>> nf_conntrack nf_defrag_ipv4 ip_tables x_tables dm_mirror
>>> dm_region_hash dm_log dm_mod snd_hda_codec_analog btusb bluetooth
>>> virtio_net kvm_intel kvm arc4 ecb crypto_blkcipher cryptomgr aead
>>> crypto_algapi iwl3945 iwl_legacy snd_hda_intel snd_hda_codec usbhid
>>> snd_seq snd_seq_device mac80211 hid iTCO_wdt iTCO_vendor_support
>>> snd_pcm psmouse i2c_i801 serio_raw cfg80211 thinkpad_acpi snd_timer
>>> snd e1000e soundcore snd_page_alloc nvram wmi evdev i915
>>> drm_kms_helper drm i2c_algo_bit i2c_core uinput autofs4 pcmcia
>>> uhci_hcd ehci_hcd sdhci_pci sdhci sr_mod mmc_core yenta_socket cdrom
>>> usbcore video backlight [last unloaded: scsi_wait_scan]
>>> [   13.413340]
>>> [   13.413340] Pid: 815, comm: bluetoothd Not tainted
>>> 2.6.39-rc2-00144-gca71856 #121 LENOVO 6464CTO/6464CTO
>>> [   13.413340] RIP: 0010:[<ffffffff8109ae43>]  [<ffffffff8109ae43>]
>>> module_put+0x33/0x1b0
>>> [   13.413340] RSP: 0018:ffff8801389e1d68  EFLAGS: 00010296
>>> [   13.413340] RAX: ffffffffa04a32a6 RBX: 6b6b6b6b6b6b6b6b RCX: 0000000000000000
>>> [   13.413340] RDX: 0000000000000000 RSI: ffffffffa04a32a6 RDI: ffffffff8109ae43
>>> [   13.413340] RBP: ffff8801389e1d98 R08: 0000000000000000 R09: 0000000000000000
>>> [   13.413340] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88013b028590
>>> [   13.413340] R13: 00000000ffffffed R14: ffff8801390ac7b0 R15: 000000000000000a
>>> [   13.413340] FS:  00007fe99d67d720(0000) GS:ffff88013ba00000(0000)
>>> knlGS:0000000000000000
>>> [   13.413340] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>>> [   13.413340] CR2: 00007fe99d4902b0 CR3: 0000000134dea000 CR4: 00000000000006f0
>>> [   13.413340] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>>> [   13.413340] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>> [   13.413340] Process bluetoothd (pid: 815, threadinfo
>>> ffff8801389e0000, task ffff8801387d23a0)
>>> [   13.413340] Stack:
>>> [   13.413340]  ffff88013b028000 ffff88013b028000 ffff88013b028590
>>> 00000000ffffffed
>>> [   13.413340]  ffff8801390ac7b0 000000000000000a ffff8801389e1de8
>>> ffffffffa04a32a6
>>> [   13.413340]  ffff8801389e1db8 ffffffff8124f11a ffff8801389e1dd8
>>> 00000000400448c9
>>> [   13.413340] Call Trace:
>>> [   13.413340]  [<ffffffffa04a32a6>] hci_dev_open+0x96/0x3f0 [bluetooth]
>>> [   13.413340]  [<ffffffff8124f11a>] ? security_capable+0x2a/0x30
>>> [   13.413340]  [<ffffffffa04b0172>] hci_sock_ioctl+0x1e2/0x4b0 [bluetooth]
>>
>>> So - it looks like disabling BT in runtime is not enough  to avoid problems ;)
>>>
>>> So I've blacklisted  bluetooth & btusb -  and made quite several
>>> suspend/resume cycles  -
>>> and without  a single problem.
>>>
>>> So I'll keep an eye on this - but so far complete deactivation of BT
>>> either in BIOS or modules blacklisting solves the problem of weird
>>> USB deadlocking.
>>
>> Clearly there's something going wrong in the Bluetooth drivers.  You
>> should try posting some of this on the linux-bluetooth mailing list.
>
> I've created:
>
> https://bugzilla.kernel.org/show_bug.cgi?id=33062
>
> and I'm cc-ing linux-bluetooth.
>

In fact this Ooops might be related to:

http://marc.info/?l=linux-kernel&m=130207593728273&w=2

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

On Mon, 11 Apr 2011, Zdenek Kabelac wrote:

> > I've created:
> >
> > https://bugzilla.kernel.org/show_bug.cgi?id=33062
> >
> > and I'm cc-ing linux-bluetooth.
> >
> 
> In fact this Ooops might be related to:
> 
> http://marc.info/?l=linux-kernel&m=130207593728273&w=2

It might be.  Did you try reverting the patch mentioned in that email?

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
> On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
>
>> > I've created:
>> >
>> > https://bugzilla.kernel.org/show_bug.cgi?id=33062
>> >
>> > and I'm cc-ing linux-bluetooth.
>> >
>>
>> In fact this Ooops might be related to:
>>
>> http://marc.info/?l=linux-kernel&m=130207593728273&w=2
>
> It might be.  Did you try reverting the patch mentioned in that email?
>

Yep - it looks like the patch
http://marc.info/?l=linux-bluetooth&m=130230770920378&w=2
solved my problem with weird deadlocks.

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: TEXT/PLAIN; charset=UTF-8, Size: 647 bytes --]

On Tue, 12 Apr 2011, Zdenek Kabelac wrote:

> 2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
> > On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
> >
> >> > I've created:
> >> >
> >> > https://bugzilla.kernel.org/show_bug.cgi?id=33062
> >> >
> >> > and I'm cc-ing linux-bluetooth.
> >> >
> >>
> >> In fact this Ooops might be related to:
> >>
> >> http://marc.info/?l=linux-kernel&m=130207593728273&w=2
> >
> > It might be.  Did you try reverting the patch mentioned in that email?
> >
> 
> Yep - it looks like the patch
> http://marc.info/?l=linux-bluetooth&m=130230770920378&w=2
> solved my problem with weird deadlocks.

Okay, great!

Alan Stern

Re: Endless print of uhci_result_common: failed with status 440000

[Gustavo F. Padovan]

* Alan Stern <stern@rowland.harvard.edu> [2011-04-12 12:10:56 -0400]:

> On Tue, 12 Apr 2011, Zdenek Kabelac wrote:
> 
> > 2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
> > > On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
> > >
> > >> > I've created:
> > >> >
> > >> > https://bugzilla.kernel.org/show_bug.cgi?id=33062
> > >> >
> > >> > and I'm cc-ing linux-bluetooth.
> > >> >
> > >>
> > >> In fact this Ooops might be related to:
> > >>
> > >> http://marc.info/?l=linux-kernel&m=130207593728273&w=2
> > >
> > > It might be. ?Did you try reverting the patch mentioned in that email?
> > >
> > 
> > Yep - it looks like the patch
> > http://marc.info/?l=linux-bluetooth&m=130230770920378&w=2
> > solved my problem with weird deadlocks.

I pushed a patch that fixes this in a better way, it's on the bluetooth-2.6
tree (should arrive to linus tree in some days).

-- 
Gustavo F. Padovan
http://profusion.mobi

Re: Endless print of uhci_result_common: failed with status 440000

[Zdenek Kabelac]

2011/4/12 Gustavo F. Padovan <padovan@profusion.mobi>:
> * Alan Stern <stern@rowland.harvard.edu> [2011-04-12 12:10:56 -0400]:
>
>> On Tue, 12 Apr 2011, Zdenek Kabelac wrote:
>>
>> > 2011/4/11 Alan Stern <stern@rowland.harvard.edu>:
>> > > On Mon, 11 Apr 2011, Zdenek Kabelac wrote:
>> > >
>> > >> > I've created:
>> > >> >
>> > >> > https://bugzilla.kernel.org/show_bug.cgi?id=33062
>> > >> >
>> > >> > and I'm cc-ing linux-bluetooth.
>> > >> >
>> > >>
>> > >> In fact this Ooops might be related to:
>> > >>
>> > >> http://marc.info/?l=linux-kernel&m=130207593728273&w=2
>> > >
>> > > It might be. ?Did you try reverting the patch mentioned in that email?
>> > >
>> >
>> > Yep - it looks like the patch
>> > http://marc.info/?l=linux-bluetooth&m=130230770920378&w=2
>> > solved my problem with weird deadlocks.
>
> I pushed a patch that fixes this in a better way, it's on the bluetooth-2.6
> tree (should arrive to linus tree in some days).


hmm

Ok  - I assume you mean this patch:

http://git.kernel.org/?p=linux/kernel/git/padovan/bluetooth-2.6.git;a=commitdiff;h=b7d850641d2bc45b2320bfcb096f11406890ff3a

It seems to be detaching timer slightly differently as the one from
Keith probably.
Here is the trace I've got with older Keith's patch (which I've
believed was fine already)

iwl3945 0000:03:00.0: loaded firmware version 15.32.2.9
systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
------------[ cut here ]------------
WARNING: at lib/list_debug.c:30 __list_add+0x8f/0xa0()
Hardware name: 6464CTO
list_add corruption. prev->next should be next (ffff88013b139390), but
was 2020203a6c61746f. (prev=ffff880137b63350).
Modules linked in: sunrpc ipt_REJECT xt_physdev xt_state
iptable_filter ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4
nf_conntrack nf_defrag_ipv4 ip_tables x_tables btusb bluetooth
snd_hda_codec_analog arc4 ecb crypto_blkcipher cryptomgr aead
crypto_algapi snd_hda_intel iwl3945 snd_hda_codec snd_seq iwl_legacy
snd_seq_device mac80211 snd_pcm thinkpad_acpi cfg80211 snd_timer
e1000e psmouse snd serio_raw wmi soundcore i2c_i801 snd_page_alloc
nvram iTCO_wdt iTCO_vendor_support evdev i915 dm_mirror dm_region_hash
dm_log dm_mod drm_kms_helper drm i2c_algo_bit i2c_core autofs4 usbhid
hid pcmcia sdhci_pci sdhci ehci_hcd uhci_hcd mmc_core sr_mod cdrom
yenta_socket usbcore video backlight
Pid: 44, comm: kworker/1:2 Not tainted 2.6.39-rc3-00236-g115ab9e #7
Call Trace:
 [<ffffffff810501df>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff810502d6>] warn_slowpath_fmt+0x46/0x50
 [<ffffffff812988ef>] __list_add+0x8f/0xa0
 [<ffffffff810602f3>] internal_add_timer+0xb3/0x140
 [<ffffffff81062bd2>] mod_timer+0x152/0x450
 [<ffffffff81117bb6>] ? refresh_cpu_vm_stats+0x106/0x170
 [<ffffffff81062ee8>] add_timer+0x18/0x20
 [<ffffffff8106df4f>] queue_delayed_work_on+0xbf/0x140
 [<ffffffff8106f0d1>] queue_delayed_work+0x21/0x40
 [<ffffffff8106f10b>] schedule_delayed_work+0x1b/0x20
 [<ffffffff81117c71>] vmstat_update+0x51/0x60
 [<ffffffff81070c38>] process_one_work+0x1c8/0x6f0
 [<ffffffff81070bd7>] ? process_one_work+0x167/0x6f0
 [<ffffffff81493c44>] ? retint_restore_args+0xe/0xe
 [<ffffffff81117c20>] ? refresh_cpu_vm_stats+0x170/0x170
 [<ffffffff81071539>] worker_thread+0x159/0x340
 [<ffffffff810713e0>] ? rescuer_thread+0x240/0x240
 [<ffffffff810760fb>] kthread+0x9b/0xa0
 [<ffffffff8149b9d4>] kernel_thread_helper+0x4/0x10
 [<ffffffff810367a4>] ? finish_task_switch+0x74/0x110
 [<ffffffff8149367b>] ? _raw_spin_unlock_irq+0x3b/0x60
 [<ffffffff81493c44>] ? retint_restore_args+0xe/0xe
 [<ffffffff81076060>] ? __init_kthread_worker+0x70/0x70
 [<ffffffff8149b9d0>] ? gs_change+0xb/0xb
---[ end trace 9184dc8969677db3 ]---

I'll see whether new version will not show this warning.

Zdenek

Re: Endless print of uhci_result_common: failed with status 440000

[Alan Stern]

On Fri, 8 Apr 2011, Zdenek Kabelac wrote:

> Ok - I've disabled this config option - now kernel writes this:
> (when I keep bt device enabled)
> 
> usb 3-1: USB disconnect, device number 2
> btusb_bulk_complete: hci0 urb ffff88012b94ca50 failed to resubmit (19)
> btusb_intr_complete: hci0 urb ffff88012b94c000 failed to resubmit (19)
> btusb_bulk_complete: hci0 urb ffff88012b94c948 failed to resubmit (19)
> btusb_send_frame: hci0 urb ffff880113dd0528 submission failed
> ------------[ cut here ]------------
> WARNING: at lib/debugobjects.c:262 debug_print_object+0x7c/0x8d()
> Hardware name: 6464CTO
> ODEBUG: free active (active state 0) object type: timer_list hint:
> hci_cmd_timer+0x0/0x46 [bluetooth]
> Modules linked in: hidp ip6table_filter
> systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
>  ip6_tables ebtable_nat ebtables xt_CHECKSUM iptable_mangle tun bridge
> ipv6 stp llc sunrpc rfcomm acpi_cpufreq freq_table mperf bnep
> xt_physdev ipt_MASQUERADE iptable_nat nf_nat snd_hda_codec_analog arc4
> iwl3945 snd_hda_intel snd_hda_codec snd_hwdep r852 snd_seq sm_common
> snd_seq_device microcode btusb nand iwl_legacy nand_ids r592 nand_ecc
> memstick mtd snd_pcm mac80211 i2c_i801 joydev iTCO_wdt bluetooth
> iTCO_vendor_support cfg80211 thinkpad_acpi e1000e snd_timer rfkill
> snd_page_alloc wmi snd soundcore virtio_net kvm_intel kvm uinput
> sdhci_pci yenta_socket sdhci mmc_core i915 drm_kms_helper drm
> i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
> Pid: 21, comm: khubd Not tainted 2.6.39-0.rc2.git0.0.fc16.x86_64 #1
> Call Trace:
>  [<ffffffff81056af8>] warn_slowpath_common+0x83/0x9b
>  [<ffffffff81056bb3>] warn_slowpath_fmt+0x46/0x48
>  [<ffffffff8125c173>] debug_print_object+0x7c/0x8d
>  [<ffffffffa023718c>] ? hci_send_acl+0x27c/0x27c [bluetooth]
>  [<ffffffff8125c961>] debug_check_no_obj_freed+0x96/0x175
>  [<ffffffffa02438e9>] ? bt_host_release+0x16/0x18 [bluetooth]
>  [<ffffffff811202ac>] slab_free_hook+0x6b/0x74
>  [<ffffffff811223a8>] kfree+0x8e/0xf2
>  [<ffffffffa02438e9>] bt_host_release+0x16/0x18 [bluetooth]
>  [<ffffffff813160da>] device_release+0x4c/0x81
>  [<ffffffff8124e89b>] kobject_release+0x11d/0x154
>  [<ffffffff8124e77e>] ? kobject_del+0x36/0x36
>  [<ffffffff8124fccf>] kref_put+0x43/0x4d
>  [<ffffffff8124e6e1>] kobject_put+0x45/0x49
>  [<ffffffff81315b1b>] put_device+0x17/0x19
>  [<ffffffffa02389a2>] hci_free_dev+0x26/0x2a [bluetooth]
>  [<ffffffffa0390cbb>] btusb_disconnect+0xbd/0xc6 [btusb]
>  [<ffffffff81378b18>] usb_unbind_interface+0x5c/0x124
>  [<ffffffff8131932e>] __device_release_driver+0x7c/0xd5
>  [<ffffffff813193ac>] device_release_driver+0x25/0x32
>  [<ffffffff81318edb>] bus_remove_device+0xc4/0xd4
>  [<ffffffff81316812>] device_del+0x13c/0x18a
>  [<ffffffff81376d6e>] usb_disable_device+0x8c/0x178
>  [<ffffffff8136f6d1>] usb_disconnect+0xd0/0x135
>  [<ffffffff813716ab>] hub_thread+0x741/0x119d
>  [<ffffffff81087164>] ? trace_hardirqs_on+0xd/0xf
>  [<ffffffff810734fc>] ? __init_waitqueue_head+0x4b/0x4b
>  [<ffffffff81370f6a>] ? usb_remote_wakeup+0x64/0x64
>  [<ffffffff81072d8d>] kthread+0xa8/0xb0
>  [<ffffffff814c4ba4>] kernel_thread_helper+0x4/0x10
>  [<ffffffff814bd254>] ? retint_restore_args+0x13/0x13
>  [<ffffffff81072ce5>] ? __init_kthread_worker+0x5a/0x5a
>  [<ffffffff814c4ba0>] ? gs_change+0x13/0x13
> ---[ end trace a7aecbf020e621f2 ]---
> PM: Syncing filesystems ... done.
> PM: Preparing system for mem sleep

That looks like a bug in bt_host_release() or hci_free_dev().

Alan Stern