Hello,
I recently got a Intel Dual Band Wireless-AC 7260 card, which works very
well as a 802.11 wlan module. So I am now trying to break the Bluetooth
part of it instead :)
And I do find some issues with that... The most important one is that I
cannot get it to work properly with autosuspend enabled.
I currently have two btusb devices in my laptop, the Intel device and an
older Lenovo Broadcom-based device. Autosuspend is enabled for all
USB devices.
nemi:/tmp# hciconfig
hci1: Type: BR/EDR Bus: USB
BD Address: 0C:8B:FD:08:09:75 ACL MTU: 1021:5 SCO MTU: 96:5
UP RUNNING PSCAN
RX bytes:965 acl:0 sco:0 events:48 errors:0
TX bytes:963 acl:0 sco:0 commands:48 errors:0
hci0: Type: BR/EDR Bus: USB
BD Address: 00:23:4D:F0:D9:1A ACL MTU: 1021:8 SCO MTU: 64:1
UP RUNNING PSCAN ISCAN
RX bytes:885 acl:0 sco:0 events:38 errors:0
TX bytes:894 acl:0 sco:0 commands:38 errors:0
The Lenovo device works as expected, with autosuspend. Reading the
version info as a simple HCI test:
nemi:/tmp# hciconfig hci0 version
hci0: Type: BR/EDR Bus: USB
BD Address: 00:23:4D:F0:D9:1A ACL MTU: 1021:8 SCO MTU: 64:1
HCI Version: 2.1 (0x4) Revision: 0x518f
LMP Version: 2.1 (0x4) Subversion: 0x424c
Manufacturer: Broadcom Corporation (15)
But the Intel device fails if suspended (and will fail for any HCI
command):
nemi:/tmp# hciconfig hci1 version
Can't read version info hci1: Connection timed out (110)
The driver is of course the same, and the configuration of these devices
are similar:
nemi:/tmp# ls -l /sys/class/bluetooth/
total 0
lrwxrwxrwx 1 root root 0 Jul 3 13:44 hci0 -> ../../devices/pci0000:00/0000:00:1a.1/usb4/4-2/4-2:1.0/bluetooth/hci0
lrwxrwxrwx 1 root root 0 Jul 3 13:44 hci1 -> ../../devices/pci0000:00/0000:00:1d.1/usb7/7-1/7-1:1.0/bluetooth/hci1
nemi:/tmp# grep . /sys/class/bluetooth/hci*/device/supports_autosuspend
/sys/class/bluetooth/hci0/device/supports_autosuspend:1
/sys/class/bluetooth/hci1/device/supports_autosuspend:1
nemi:/tmp# grep . /sys/class/bluetooth/hci*/device/../power/control
/sys/class/bluetooth/hci0/device/../power/control:auto
/sys/class/bluetooth/hci1/device/../power/control:auto
nemi:/tmp# grep . /sys/class/bluetooth/hci*/device/../power/runtime_*
/sys/class/bluetooth/hci0/device/../power/runtime_active_kids:0
/sys/class/bluetooth/hci0/device/../power/runtime_active_time:48448
/sys/class/bluetooth/hci0/device/../power/runtime_enabled:enabled
/sys/class/bluetooth/hci0/device/../power/runtime_status:suspended
/sys/class/bluetooth/hci0/device/../power/runtime_suspended_time:1502332
/sys/class/bluetooth/hci0/device/../power/runtime_usage:0
/sys/class/bluetooth/hci1/device/../power/runtime_active_kids:0
/sys/class/bluetooth/hci1/device/../power/runtime_active_time:79528
/sys/class/bluetooth/hci1/device/../power/runtime_enabled:enabled
/sys/class/bluetooth/hci1/device/../power/runtime_status:suspended
/sys/class/bluetooth/hci1/device/../power/runtime_suspended_time:1470828
/sys/class/bluetooth/hci1/device/../power/runtime_usage:0
Turning off autosuspend for the Intel device makes it work:
nemi:/tmp# echo on > /sys/class/bluetooth/hci1/device/../power/control
nemi:/tmp# hciconfig hci1 version
hci1: Type: BR/EDR Bus: USB
BD Address: 0C:8B:FD:08:09:75 ACL MTU: 1021:5 SCO MTU: 96:5
HCI Version: 4.0 (0x6) Revision: 0x500
LMP Version: 4.0 (0x6) Subversion: 0x500
Manufacturer: Intel Corp. (2)
But this just does not seem right? Any modern USB device is supposed to
support autosuspend, right? I am using the firmware patch included in
the latest public firmware repo:
[ 4.652631] Bluetooth: hci1: read Intel version: 370710018002030d00
[ 4.656988] Bluetooth: hci1: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 4.963497] Bluetooth: hci1: Intel Bluetooth firmware patch completed and activated
While looking at this, I also noticed a minor issue with the USB
descriptors. It cannot be classified as a bug, but it does look like
somebody just forgot to set the iManufacturer, iProduct and iSerial
string indexes in the device descriptor:
Bus 007 Device 002: ID 8087:07dc Intel Corp.
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 224 Wireless
bDeviceSubClass 1 Radio Frequency
bDeviceProtocol 1 Bluetooth
bMaxPacketSize0 64
idVendor 0x8087 Intel Corp.
idProduct 0x07dc
bcdDevice 0.01
iManufacturer 0
iProduct 0
iSerial 0
bNumConfigurations 1
[..]
because trying to pull some string descriptors from the device revealed
that indexes 1, 2 and 3 exist without being referenced anywhere:
1: Intel(R) Corporation
2: Intel(R) Wilkins Peak 2x2
3: 001122334455 WP_A0
The serial number doesn't look right, but the two others should fit
nicely as iManufacturer and iProduct.
Bjørn
Alan Stern <[email protected]> writes:
> On Thu, 4 Jul 2013, Bjørn Mork wrote:
>
>> > It may be that the device simply takes longer to resume than it should.
>> > Or longer than btusb expects it to, which may not be the same thing.
>>
>> Yes, that is what it looks like. But the URBs are submitted as part of
>> the resume callback. Shouldn't the device be alive and kicking when
>> this is called? At least from the USB point of view, which is all the
>> driver can possibly know anything about? Is the problem that the
>> firmware finishes the USB resume before actually being ready to respond
>> to the HCI command?
>
> I don't know. The USB spec gives devices 10 ms to recover during a
> resume; after that they are supposed to be ready to operate normally.
> This delay is already built into usbcore and it is visible in your
> usbmon trace.
>
> There is one notable difference between your failure and success
> traces. Failure:
>
>> ffff88021ace62c0 3675041611 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
>> ffff88022228d140 3675041721 S Co:002:00 s 01 0b 0000 0001 0000 0
>> ffff88021ace62c0 3675042361 C Co:002:00 0 3 >
>> ffff88022228d140 3675042409 C Co:002:00 0 0
>> ffff88020c40f380 3675043359 C Ii:002:01 0 6 = 0f040101 010b
>> ffff88020c40f380 3675043429 S Ii:002:01 -115 64 <
>
> Success:
>
>> ffff88020c40f200 88163963 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
>> ffff88020c752980 88165215 C Ii:002:01 0 14 = 0e0c0101 10000600 05060200 0005
>> ffff88020c752980 88165281 S Ii:002:01 -115 64 <
>> ffff88020c40f200 88165327 C Co:002:00 0 3 >
>
> In the failure case, a Set-Interface request gets sent before the
> interrupt URB completes. Maybe that accounts for the unexpected
> behavior.
Maybe. But the device does send a message which translates as a valid
HCI message, so it looks like everything is OK up to and including the
USB layer.
I tried to figure out the exact meaning of that message, but that's not
straight forward unless you are familiar with the Bluetooth specs. Which
I'm certainly not. What I did find out is only what the HCI debug code
also could tell me:
0f - HCI_EV_CMD_STATUS
04 - length: 4
01 - status: 1
01 - ncmds: 1
010b - opcode: 0x0b01
Enabling the dynamic debugging in hci_core and hci_event makes this
clear, along with the fact that HCI core ignores this event:
Jul 5 12:27:21 nemi kernel: [44750.608222] btusb_tx_complete:574: hci1 urb ffff880231a10c00 status 0 count 3
Jul 5 12:27:21 nemi kernel: [44750.609223] btusb_intr_complete:281: hci1 urb ffff880231a109c0 status 0 count 6
Jul 5 12:27:21 nemi kernel: [44750.609297] hci_rx_work:3463: hci1
Jul 5 12:27:21 nemi kernel: [44750.609346] hci_rx_work:3492: hci1 Event packet
Jul 5 12:27:21 nemi kernel: [44750.609361] hci_cmd_status_evt:2418: hci1 opcode 0x0b01
Jul 5 12:27:21 nemi kernel: [44750.609371] hci_req_cmd_complete:3406: opcode 0x0b01 status 0x01
Jul 5 12:27:21 nemi kernel: [44750.609641] hci_dev_get:691: 1
The "hci_cmd_status_evt" message shows that we hit the default
do-nothing handler for events unknown to hci_event.c. For some reason
this cancels the command timer:
if (opcode != HCI_OP_NOP)
del_timer(&hdev->cmd_timer);
But changing that only leads to the timer expiring ang logging
Jul 5 12:27:23 nemi kernel: [44752.532142] Bluetooth: hci1 command 0x1001 tx timeout
Jul 5 12:27:23 nemi kernel: [44752.532233] hci_cmd_work:3519: hci1 cmd_cnt 1 cmd queued 0
a few seconds later (0x1001 is HCI_OP_READ_LOCAL_VERSION, so that's the
command we're waiting for). Proper handling of the 0x0b01 event is most
likely required to continue here.
I do assume the device means to signal something by sending that 0x0b01
event, and based on the observed behaviour and existing code I guess
that something translates to "not ready yet - please resend last
command" or similar. But I haven't been able to find any definition of
that event anywhere, so this is based on pure speculation.
Anyway, unless someone from the Bluetooth list shouts out, then I am
going to conclude that the device, USB core and btusb all behave
correctly, but that waking up this device (and likely other recent
devices) can fail because the HCI core fails to handle a link state
event it should handle.
I don't have any proposed fix, except ugly hacks to let the device have
some more time. So I am hoping someone knowing Bluetooth will come up
with better ideas.
Bjørn
On Thu, 4 Jul 2013, Bjørn Mork wrote:
> > It may be that the device simply takes longer to resume than it should.
> > Or longer than btusb expects it to, which may not be the same thing.
>
> Yes, that is what it looks like. But the URBs are submitted as part of
> the resume callback. Shouldn't the device be alive and kicking when
> this is called? At least from the USB point of view, which is all the
> driver can possibly know anything about? Is the problem that the
> firmware finishes the USB resume before actually being ready to respond
> to the HCI command?
I don't know. The USB spec gives devices 10 ms to recover during a
resume; after that they are supposed to be ready to operate normally.
This delay is already built into usbcore and it is visible in your
usbmon trace.
There is one notable difference between your failure and success
traces. Failure:
> ffff88021ace62c0 3675041611 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
> ffff88022228d140 3675041721 S Co:002:00 s 01 0b 0000 0001 0000 0
> ffff88021ace62c0 3675042361 C Co:002:00 0 3 >
> ffff88022228d140 3675042409 C Co:002:00 0 0
> ffff88020c40f380 3675043359 C Ii:002:01 0 6 = 0f040101 010b
> ffff88020c40f380 3675043429 S Ii:002:01 -115 64 <
Success:
> ffff88020c40f200 88163963 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
> ffff88020c752980 88165215 C Ii:002:01 0 14 = 0e0c0101 10000600 05060200 0005
> ffff88020c752980 88165281 S Ii:002:01 -115 64 <
> ffff88020c40f200 88165327 C Co:002:00 0 3 >
In the failure case, a Set-Interface request gets sent before the
interrupt URB completes. Maybe that accounts for the unexpected
behavior.
Alan Stern
Alan Stern <[email protected]> writes:
> The relative order of those two completions doesn't mean anything,
> because they are on different endpoints and they happened during the
> same frame. It just happens that uhci-hcd scans interrupt URBs before
> bulk URBs when looking for completions, but it could easily be the
> other way around.
Thanks. I should know that. Sorry for the confusion...
> It may be that the device simply takes longer to resume than it should.
> Or longer than btusb expects it to, which may not be the same thing.
Yes, that is what it looks like. But the URBs are submitted as part of
the resume callback. Shouldn't the device be alive and kicking when
this is called? At least from the USB point of view, which is all the
driver can possibly know anything about? Is the problem that the
firmware finishes the USB resume before actually being ready to respond
to the HCI command?
I'm including an usbmon dump of this sequence below:
Jul 4 09:03:54 nemi kernel: [13047.695364] btusb_send_frame:716: hci1
Jul 4 09:03:54 nemi kernel: [13047.697048] uhci_hcd 0000:00:1d.1: setting latency timer to 64
Jul 4 09:03:55 nemi kernel: [13047.771270] btusb_resume:1560: intf ffff880230fb5800
Jul 4 09:03:55 nemi kernel: [13047.771284] btusb_resume:1560: intf ffff880230dc2800
Jul 4 09:03:55 nemi kernel: [13047.771293] btusb_submit_intr_urb:322: hci1
Jul 4 09:03:55 nemi kernel: [13047.771331] btusb_submit_bulk_urb:410: hci1
Jul 4 09:03:55 nemi kernel: [13047.771392] btusb_submit_bulk_urb:410: hci1
Jul 4 09:03:55 nemi kernel: [13047.772229] btusb_tx_complete:574: hci1 urb ffff88021ace62c0 status 0 count 3
Jul 4 09:03:55 nemi kernel: [13047.773232] btusb_intr_complete:281: hci1 urb ffff88020c40f380 status 0 count 6
Jul 4 09:03:57 nemi kernel: [13049.808289] btusb_suspend:1516: intf ffff880230dc2800
Jul 4 09:03:57 nemi kernel: [13049.810384] btusb_intr_complete:281: hci1 urb ffff88020c40f380 status -2 count 0
Jul 4 09:03:57 nemi kernel: [13049.811353] btusb_bulk_complete:369: hci1 urb ffff88020c40f140 status -2 count 0
Jul 4 09:03:57 nemi kernel: [13049.812348] btusb_bulk_complete:369: hci1 urb ffff88020c40f680 status -2 count 0
Jul 4 09:03:57 nemi kernel: [13049.812599] btusb_suspend:1516: intf ffff880230fb5800
nemi:/tmp# cat /sys/kernel/debug/usb/usbmon/7t
ffff88020c40f380 3674990429 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88020c40f380 3674990490 C Ci:001:00 0 4 = 07010000
ffff88020c40f380 3674990546 S Ci:001:00 s a3 00 0000 0002 0004 4 <
ffff88020c40f380 3674990567 C Ci:001:00 0 4 = 00010000
ffff8802300c1680 3674990585 S Ii:001:01 -115 2 <
ffff88020c40f380 3674990669 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88020c40f380 3674990690 C Ci:001:00 0 4 = 07010000
ffff88020c40f380 3674990731 S Co:001:00 s 23 01 0002 0001 0000 0
ffff88020c40f380 3674990753 C Co:001:00 0 0
ffff88020c40f380 3675022455 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88020c40f380 3675022508 C Ci:001:00 0 4 = 03010400
ffff88020c40f380 3675038376 S Co:001:00 s 23 01 0012 0001 0000 0
ffff88020c40f380 3675038408 C Co:001:00 0 0
ffff88020c40f380 3675038457 S Ci:002:00 s 80 00 0000 0000 0002 2 <
ffff88020c40f380 3675040416 C Ci:002:00 0 2 = 0300
ffff88020c40f380 3675040496 S Co:002:00 s 00 01 0001 0000 0000 0
ffff88020c40f380 3675041362 C Co:002:00 0 0
ffff88020c40f380 3675041465 S Ii:002:01 -115 64 <
ffff88020c40f680 3675041501 S Bi:002:02 -115 1028 <
ffff88020c40f140 3675041561 S Bi:002:02 -115 1028 <
ffff88021ace62c0 3675041611 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
ffff88022228d140 3675041721 S Co:002:00 s 01 0b 0000 0001 0000 0
ffff88021ace62c0 3675042361 C Co:002:00 0 3 >
ffff88022228d140 3675042409 C Co:002:00 0 0
ffff88020c40f380 3675043359 C Ii:002:01 0 6 = 0f040101 010b
ffff88020c40f380 3675043429 S Ii:002:01 -115 64 <
ffff88020c40f380 3677080502 C Ii:002:01 -2 0
ffff88020c40f380 3677080554 S Ii:002:01 -115 64 <
ffff88020c40f380 3677080574 E Ii:002:01 -1 0
ffff88020c40f140 3677081484 C Bi:002:02 -2 0
ffff88020c40f140 3677081522 S Bi:002:02 -115 1028 <
ffff88020c40f140 3677081541 E Bi:002:02 -1 0
ffff88020c40f680 3677082485 C Bi:002:02 -2 0
ffff88020c40f680 3677082515 S Bi:002:02 -115 1028 <
ffff88020c40f680 3677082534 E Bi:002:02 -1 0
ffff88020c40f680 3677082804 S Co:002:00 s 00 03 0001 0000 0000 0
ffff88020c40f680 3677083460 C Co:002:00 0 0
ffff88020c40f680 3677084334 S Co:001:00 s 23 03 0002 0001 0000 0
ffff88020c40f680 3677084357 C Co:001:00 0 0
ffff8802300c1680 3677098476 C Ii:001:01 -2 0
So the 6 bytes returned in this case are "0f040101 010b". I assume
anyone familiar with HCI commands will immediately understand what that
means?
For reference, the 14 expected bytes are:
ffff88020c40f200 88163963 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
ffff88020c752980 88165215 C Ii:002:01 0 14 = 0e0c0101 10000600 05060200 0005
ffff88020c752980 88165281 S Ii:002:01 -115 64 <
ffff88020c40f200 88165327 C Co:002:00 0 3 >
Bjørn
On Wed, 3 Jul 2013, Bjørn Mork wrote:
> Bjørn Mork <[email protected]> writes:
>
> > Ah, this is probably a timing issue.
>
> It definitely is, and I believe it is a generic problem with the btusb
> driver and not with this particular device. That's just where I was
> "lucky" enough to see it.
>
> Enabling a bit of debugging in btusb, I see this for a hci version
> command with wakeup actually working:
>
>
> Jul 3 15:47:44 nemi kernel: [ 8864.982520] btusb_send_frame:716: hci1
> Jul 3 15:47:44 nemi kernel: [ 8864.984197] uhci_hcd 0000:00:1d.1: setting latency timer to 64
> Jul 3 15:47:44 nemi kernel: [ 8865.059400] btusb_resume:1560: intf ffff880230fb5800
> Jul 3 15:47:44 nemi kernel: [ 8865.059414] btusb_resume:1560: intf ffff880230dc2800
> Jul 3 15:47:44 nemi kernel: [ 8865.059423] btusb_submit_intr_urb:322: hci1
> Jul 3 15:47:44 nemi kernel: [ 8865.059462] btusb_submit_bulk_urb:410: hci1
> Jul 3 15:47:44 nemi kernel: [ 8865.059510] btusb_submit_bulk_urb:410: hci1
> Jul 3 15:47:44 nemi kernel: [ 8865.060262] btusb_tx_complete:574: hci1 urb ffff88021f778540 status 0 count 3
> Jul 3 15:47:44 nemi kernel: [ 8865.061266] btusb_intr_complete:281: hci1 urb ffff88021f778900 status 0 count 14
> Jul 3 15:47:46 nemi kernel: [ 8867.060121] btusb_suspend:1516: intf ffff880230dc2800
> Jul 3 15:47:46 nemi kernel: [ 8867.061333] btusb_intr_complete:281: hci1 urb ffff88021f778900 status -2 count 0
> Jul 3 15:47:46 nemi kernel: [ 8867.062307] btusb_bulk_complete:369: hci1 urb ffff88021f7780c0 status -2 count 0
> Jul 3 15:47:46 nemi kernel: [ 8867.068305] btusb_bulk_complete:369: hci1 urb ffff88021f7783c0 status -2 count 0
> Jul 3 15:47:46 nemi kernel: [ 8867.068373] btusb_suspend:1516: intf ffff880230fb5800
>
>
> and then repeating the exact same and seeing a failing one:
>
> Jul 3 15:47:58 nemi kernel: [ 8878.765249] btusb_send_frame:716: hci1
> Jul 3 15:47:58 nemi kernel: [ 8878.766855] uhci_hcd 0000:00:1d.1: setting latency timer to 64
> Jul 3 15:47:58 nemi kernel: [ 8878.839639] btusb_resume:1560: intf ffff880230fb5800
> Jul 3 15:47:58 nemi kernel: [ 8878.839654] btusb_resume:1560: intf ffff880230dc2800
> Jul 3 15:47:58 nemi kernel: [ 8878.839663] btusb_submit_intr_urb:322: hci1
> Jul 3 15:47:58 nemi kernel: [ 8878.839707] btusb_submit_bulk_urb:410: hci1
> Jul 3 15:47:58 nemi kernel: [ 8878.839756] btusb_submit_bulk_urb:410: hci1
> Jul 3 15:47:58 nemi kernel: [ 8878.840318] btusb_intr_complete:281: hci1 urb ffff88021f778300 status 0 count 6
> Jul 3 15:47:58 nemi kernel: [ 8878.840397] btusb_tx_complete:574: hci1 urb ffff88021f7783c0 status 0 count 3
> Jul 3 15:48:00 nemi kernel: [ 8880.840253] btusb_suspend:1516: intf ffff880230dc2800
> Jul 3 15:48:00 nemi kernel: [ 8880.842343] btusb_intr_complete:281: hci1 urb ffff88021f778300 status -2 count 0
> Jul 3 15:48:00 nemi kernel: [ 8880.843562] btusb_bulk_complete:369: hci1 urb ffff88021f778cc0 status -2 count 0
> Jul 3 15:48:00 nemi kernel: [ 8880.844326] btusb_bulk_complete:369: hci1 urb ffff88021f778c00 status -2 count 0
> Jul 3 15:48:00 nemi kernel: [ 8880.844705] btusb_suspend:1516: intf ffff880230fb5800
>
>
> Notice how the interrupt completion runs before the tx completion in the
> failing case? I believe you have the problem right there...
The relative order of those two completions doesn't mean anything,
because they are on different endpoints and they happened during the
same frame. It just happens that uhci-hcd scans interrupt URBs before
bulk URBs when looking for completions, but it could easily be the
other way around.
It may be that the device simply takes longer to resume than it should.
Or longer than btusb expects it to, which may not be the same thing.
Alan Stern
Bjørn Mork <[email protected]> writes:
> Ah, this is probably a timing issue.
It definitely is, and I believe it is a generic problem with the btusb
driver and not with this particular device. That's just where I was
"lucky" enough to see it.
Enabling a bit of debugging in btusb, I see this for a hci version
command with wakeup actually working:
Jul 3 15:47:44 nemi kernel: [ 8864.982520] btusb_send_frame:716: hci1
Jul 3 15:47:44 nemi kernel: [ 8864.984197] uhci_hcd 0000:00:1d.1: setting latency timer to 64
Jul 3 15:47:44 nemi kernel: [ 8865.059400] btusb_resume:1560: intf ffff880230fb5800
Jul 3 15:47:44 nemi kernel: [ 8865.059414] btusb_resume:1560: intf ffff880230dc2800
Jul 3 15:47:44 nemi kernel: [ 8865.059423] btusb_submit_intr_urb:322: hci1
Jul 3 15:47:44 nemi kernel: [ 8865.059462] btusb_submit_bulk_urb:410: hci1
Jul 3 15:47:44 nemi kernel: [ 8865.059510] btusb_submit_bulk_urb:410: hci1
Jul 3 15:47:44 nemi kernel: [ 8865.060262] btusb_tx_complete:574: hci1 urb ffff88021f778540 status 0 count 3
Jul 3 15:47:44 nemi kernel: [ 8865.061266] btusb_intr_complete:281: hci1 urb ffff88021f778900 status 0 count 14
Jul 3 15:47:46 nemi kernel: [ 8867.060121] btusb_suspend:1516: intf ffff880230dc2800
Jul 3 15:47:46 nemi kernel: [ 8867.061333] btusb_intr_complete:281: hci1 urb ffff88021f778900 status -2 count 0
Jul 3 15:47:46 nemi kernel: [ 8867.062307] btusb_bulk_complete:369: hci1 urb ffff88021f7780c0 status -2 count 0
Jul 3 15:47:46 nemi kernel: [ 8867.068305] btusb_bulk_complete:369: hci1 urb ffff88021f7783c0 status -2 count 0
Jul 3 15:47:46 nemi kernel: [ 8867.068373] btusb_suspend:1516: intf ffff880230fb5800
and then repeating the exact same and seeing a failing one:
Jul 3 15:47:58 nemi kernel: [ 8878.765249] btusb_send_frame:716: hci1
Jul 3 15:47:58 nemi kernel: [ 8878.766855] uhci_hcd 0000:00:1d.1: setting latency timer to 64
Jul 3 15:47:58 nemi kernel: [ 8878.839639] btusb_resume:1560: intf ffff880230fb5800
Jul 3 15:47:58 nemi kernel: [ 8878.839654] btusb_resume:1560: intf ffff880230dc2800
Jul 3 15:47:58 nemi kernel: [ 8878.839663] btusb_submit_intr_urb:322: hci1
Jul 3 15:47:58 nemi kernel: [ 8878.839707] btusb_submit_bulk_urb:410: hci1
Jul 3 15:47:58 nemi kernel: [ 8878.839756] btusb_submit_bulk_urb:410: hci1
Jul 3 15:47:58 nemi kernel: [ 8878.840318] btusb_intr_complete:281: hci1 urb ffff88021f778300 status 0 count 6
Jul 3 15:47:58 nemi kernel: [ 8878.840397] btusb_tx_complete:574: hci1 urb ffff88021f7783c0 status 0 count 3
Jul 3 15:48:00 nemi kernel: [ 8880.840253] btusb_suspend:1516: intf ffff880230dc2800
Jul 3 15:48:00 nemi kernel: [ 8880.842343] btusb_intr_complete:281: hci1 urb ffff88021f778300 status -2 count 0
Jul 3 15:48:00 nemi kernel: [ 8880.843562] btusb_bulk_complete:369: hci1 urb ffff88021f778cc0 status -2 count 0
Jul 3 15:48:00 nemi kernel: [ 8880.844326] btusb_bulk_complete:369: hci1 urb ffff88021f778c00 status -2 count 0
Jul 3 15:48:00 nemi kernel: [ 8880.844705] btusb_suspend:1516: intf ffff880230fb5800
Notice how the interrupt completion runs before the tx completion in the
failing case? I believe you have the problem right there...
Bjørn
Oliver Neukum <[email protected]> writes:
> On Wednesday 03 July 2013 14:08:00 Bjørn Mork wrote:
>> But this just does not seem right? Any modern USB device is supposed to
>> support autosuspend, right? I am using the firmware patch included in
>
> What should be and what is may be different although it oughn't be.
>
>> the latest public firmware repo:
>
> Does the device respond to standard request, that is what does lsusb do?
Yes, it does. Standard USB requests seems to wake the device. Running
"lsusb -vd 8087:07dc" from suspended state works fine for example:
nemi:/tmp# grep . /sys/bus/usb/devices/7-1/power/runtime_status; lsusb -vd 8087:07dc >/dev/null ; grep . /sys/bus/usb/devices/7-1/power/runtime_status
suspended
active
usbmon trace of this:
nemi:/tmp# cat /sys/kernel/debug/usb/usbmon/7t
ffff88021ae42680 3655354231 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88021ae42680 3655354476 C Ci:001:00 0 4 = 07010000
ffff88021ae42680 3655354683 S Ci:001:00 s a3 00 0000 0002 0004 4 <
ffff88021ae42680 3655354825 C Ci:001:00 0 4 = 00010000
ffff8802300c1680 3655354960 S Ii:001:01 -115 2 <
ffff88021ae42680 3655355508 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88021ae42680 3655355903 C Ci:001:00 0 4 = 07010000
ffff88021ae42680 3655356070 S Co:001:00 s 23 01 0002 0001 0000 0
ffff88021ae42680 3655356248 C Co:001:00 0 0
ffff88022cac6ec0 3655386101 S Ci:001:00 s a3 00 0000 0001 0004 4 <
ffff88022cac6ec0 3655386152 C Ci:001:00 0 4 = 03010400
ffff88021ae42680 3655402102 S Co:001:00 s 23 01 0012 0001 0000 0
ffff88021ae42680 3655402133 C Co:001:00 0 0
ffff88021ae42680 3655402178 S Ci:002:00 s 80 00 0000 0000 0002 2 <
ffff88021ae42680 3655404198 C Ci:002:00 0 2 = 0300
ffff88021ae42680 3655404311 S Co:002:00 s 00 01 0001 0000 0000 0
ffff88021ae42680 3655405219 C Co:002:00 0 0
ffff88021ae42680 3655405422 S Ii:002:01 -115 64 <
ffff88022cac6ec0 3655405459 S Bi:002:02 -115 1028 <
ffff88022cac6e00 3655405510 S Bi:002:02 -115 1028 <
ffff88022cac6d40 3655407116 S Ci:002:00 s 80 06 0600 0000 000a 10 <
ffff88022cac6c80 3655407277 S Co:002:00 s 01 0b 0000 0001 0000 0
ffff88022cac6d40 3655408225 C Ci:002:00 -32 0
ffff88022cac6d40 3655408514 S Ci:002:00 s 80 06 0a00 0000 0004 4 <
ffff88022cac6c80 3655409220 C Co:002:00 0 0
ffff88022cac6d40 3655409258 C Ci:002:00 0 0
ffff88022cac6d40 3655409528 S Ci:002:00 s 80 00 0000 0000 0002 2 <
ffff88022cac6d40 3655410194 C Ci:002:00 0 2 = 0100
And then when suspending:
ffff88021ae42680 3657411219 C Ii:002:01 -2 0
ffff88021ae42680 3657411253 S Ii:002:01 -115 64 <
ffff88021ae42680 3657411298 E Ii:002:01 -1 0
ffff88022cac6e00 3657412234 C Bi:002:02 -2 0
ffff88022cac6e00 3657412261 S Bi:002:02 -115 1028 <
ffff88022cac6e00 3657412280 E Bi:002:02 -1 0
ffff88022cac6ec0 3657413234 C Bi:002:02 -2 0
ffff88022cac6ec0 3657413261 S Bi:002:02 -115 1028 <
ffff88022cac6ec0 3657413281 E Bi:002:02 -1 0
ffff88022cac6ec0 3657413557 S Co:002:00 s 00 03 0001 0000 0000 0
ffff88022cac6ec0 3657414209 C Co:002:00 0 0
ffff88022cac6ec0 3657414531 S Co:001:00 s 23 03 0002 0001 0000 0
ffff88022cac6ec0 3657414565 C Co:001:00 0 0
ffff8802300c1680 3657430065 C Ii:001:01 -2 0
Ah, this is probably a timing issue. The HCI commands also wake the
device, but too late most of the time. This fails:
nemi:/tmp# grep . /sys/bus/usb/devices/7-1/power/runtime_status; hciconfig hci1 version ; grep . /sys/bus/usb/devices/7-1/power/runtime_status
suspended
Can't read version info hci1: Connection timed out (110)
active
But repeating the command makes the second attempt work:
nemi:/tmp# grep . /sys/bus/usb/devices/7-1/power/runtime_status; hciconfig hci1 version; hciconfig hci1 version ; grep . /sys/bus/usb/devices/7-1/power/runtime_status
suspended
Can't read version info hci1: Connection timed out (110)
hci1: Type: BR/EDR Bus: USB
BD Address: 0C:8B:FD:08:09:75 ACL MTU: 1021:5 SCO MTU: 96:5
HCI Version: 4.0 (0x6) Revision: 0x500
LMP Version: 4.0 (0x6) Subversion: 0x500
Manufacturer: Intel Corp. (2)
active
Bjørn
On Wednesday 03 July 2013 14:08:00 Bj?rn Mork wrote:
> But this just does not seem right? Any modern USB device is supposed to
> support autosuspend, right? I am using the firmware patch included in
What should be and what is may be different although it oughn't be.
> the latest public firmware repo:
Does the device respond to standard request, that is what does lsusb do?
Regards
Oliver