urb timeout with bluetooth USB HCI on ARM (2.6.11-rc3)

Hi,

I'm writing to that list as my last resort in trying to fix a bug i'm facing. First of all let me say that this bug looks rather intricate to me, that I'm not certain that USB HCI is at fault (though I suspect it is, see detail below), and that I've spent a fair amount of time digging into code and documentation trying to find out what's going wrong. Apologies for the lengthy mail either.

I'm using 2.6.11-rc3 + AT91RM9200 patches, cross-compiled with gcc 3.3.3.

The issue happens when I try to use a bluetooth USB dongle on an ARM demo board: I can configure it, but I can't create any connection nor scan the local network (with 'hcitool'), for I take urb timeout errors when doing so.

Here's a sample of the system logs when the bug happens (with both OHCI verbose debug and HCI USB verbose debug enabled):

Jan  1 01:01:17 ptx-ek kernel: hci_usb_tx_process: hci0
Jan  1 01:01:17 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: RET
c03eaa78 dev=2 ep=1in-intr flags=0 len=6/16 stat=0
Jan  1 01:01:17 ptx-ek kernel: drivers/usb/host/ohci-dbg.c:
data(6/16): 0e 04 01 16 0c 00 stat:0
Jan  1 01:01:17 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eaa78
type 4 status 0 count 6 flags 0
Jan  1 01:01:17 ptx-ek kernel: __recv_frame: hci0 type 4 data c1c28f84 count 6
Jan  1 01:01:17 ptx-ek kernel: __recv_frame: new packet len 6
Jan  1 01:01:17 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: SUB
c03eaa78 dev=2 ep=1in-intr flags=0 len=0/16 stat=-115
Jan  1 01:01:17 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eaa78
type 4 resubmit status 0
Jan  1 01:01:17 ptx-ek kernel: at91rm9200-ohci at91rm9200-ohci: urb
c03eab04 path 2 ep2in 5c160000 cc 5 --> status -110
Jan  1 01:01:18 ptx-ek kernel: at91rm9200-ohci at91rm9200-ohci: urb c03eab04 td
ffc070c0 (1) cc 5, len=0/1028
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: RET
c03eab04 dev=2 ep=2in-bulk flags=0 len=0/1028 stat=-110
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c:
data(0/1028): stat:-110
Jan  1 01:01:18 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eab04
type 2 status -110 count 0 flags 0
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: SUB
c03eab04 dev=2 ep=2in-bulk flags=0 len=0/1028 stat=-115
Jan  1 01:01:18 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eab04
type 2 resubmit status 0
Jan  1 01:01:18 ptx-ek kernel: at91rm9200-ohci at91rm9200-ohci: urb
c03eab04 path 2 ep2in 5c160000 cc 5 --> status -110
Jan  1 01:01:18 ptx-ek kernel: at91rm9200-ohci at91rm9200-ohci: urb c03eab04 td
ffc07100 (1) cc 5, len=0/1028
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: RET
c03eab04 dev=2 ep=2in-bulk flags=0 len=0/1028 stat=-110
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c:
data(0/1028): stat:-110
Jan  1 01:01:18 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eab04
type 2 status -110 count 0 flags 0
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: SUB
c03eab04 dev=2 ep=2in-bulk flags=0 len=0/1028 stat=-115
Jan  1 01:01:18 ptx-ek kernel: hci_usb_rx_complete: hci0 urb c03eab04
type 2 resubmit status 0
Jan  1 01:01:18 ptx-ek kernel: hci_usb_send_frame: hci0 type 1 len 4
Jan  1 01:01:18 ptx-ek kernel: hci_usb_tx_process: hci0
Jan  1 01:01:18 ptx-ek kernel: hci_usb_send_ctrl: hci0 skb c030ae94 len 4
Jan  1 01:01:18 ptx-ek kernel: __tx_submit: hci0 urb c15708d4 type 1
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: SUB
c15708d4 dev=2 ep=0out-ctrl flags=0 len=0/4 stat=-115
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: setup(8):
20 00 00 00 00 00 04 00
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: data(0/4): 1a 0c 01
03 stat:-115
Jan  1 01:01:18 ptx-ek kernel: drivers/usb/host/ohci-dbg.c: RET
c15708d4 dev=2 ep=0out-ctrl flags=0 len=4/4 stat=0
Jan  1 01:01:18 ptx-ek kernel: hci_usb_tx_complete: hci0 urb c15708d4
status 0 flags 0
Jan  1 01:01:18 ptx-ek kernel: hci_usb_tx_process: hci0

As one can see, at some point when processing received frames, a timeout occurs ("status = -110") on endpoint 2 IN (bulk endpoint). The faulty endpoint is always the same, and that fact, plus the fact that it is OHCI complaining, first led me to think it was an OHCI bug.

I have posted to the linux-usb-devel mailing list for about that:
http://marc.theaimsgroup.com/?l=linux-usb-devel&m=110839632914184&w=2
http://marc.theaimsgroup.com/?l=linux-usb-devel&m=110872463928902&w=2

but the answer I got pointed me toward either a hardware bug from the device (dismissed as it works fine on a x86 machine and the bug is reproducible with various dongles) or *maybe* a bug in the BT HCI USB driver.

Besides, of all the devices I've been able to test on that machine (mice, hubs, mass storage, usbnet...), BT dongles are the *only ones failing*, hence my suspecting that the HCI driver is the culprit somehow.

Back to the log I've pasted: I've looked at the hci_usb_rx_complete() code, and as the log shows, when the timeout is caught, the urb is resubmitted and (as it seems) finaly accepted by the USB subsystem ("resubmit status 0"). However, hcitool will timeout anyway:

# hcitool scan
Scanning ...
Inquiry failed: Connection timed out

I also noticed that "count" remains null for all the fauly urbs, which surprised me a bit (wouldn't it grow if data is processed?).

So my questions are:

1) Is that a known bug? (who knows... :-) )
2) Is it possible that I'm hitting some corner case bug in the HCI driver?
3) Any clue about how to fix this?

I've tried tracking down that bug through the various layers involved (HCI USB, OHCI, USB core, looking at the various code paths), still, I haven't been able to find the root cause of that timeout, so any help would be much appreciated.

TIA

Thibaut VARENE
PA-RISC Linux Hacker
http://www.parisc-linux.org/


-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel

Hi Tia,

not that I know of.

Yes, this is maybe possible. The hci_usb driver is not the cleanest one, but it works quite good for almost every system at the moment.

The hci_usb driver contains some extra parameters that may can help you. Try "isoc=0" or "reset=1" and post the content of /proc/bus/usb/devices.

Regards

Marcel

-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel

Hi,

Looking at the code, "isoc" is only available when CONFIG_BT_HCIUSB_SCO is enabled, which wasn't my case. AFAICT it's used for disabling SCO protocol at runtime in the code, but just to make absolutely sure I rebuilt the module with SCO support enabled, tried various values for isoc=, none changed anything.

tried with "reset=1", didn't change anything either

FWIW, it's almost impossible to debug with CONFIG_BT_HCIUSB_DEBUG force set on, for the machine is so slowed down that the timeouts would actually be meaningful. Maybe this is why this config option isn't available from the config menu ;)

Thanks for your help

Thibaut VARENE

PS: Please CC me in answers, I'm not subscribed (used Gmane to avoid breaking the thread).

-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel

Hi Thibaut,

if both not helps, then I think that it a ARM and USB related problem. Since I don't have any of these platform, I can't help you here.

Regards

Marcel

-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel

Me again, forgot to paste that info:

# cat /proc/bus/usb/devices

T:  Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12  MxCh= 2
B:  Alloc= 22/900 us ( 2%), #Int=  1, #Iso=  0
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS= 8 #Cfgs=  1
P:  Vendor=0000 ProdID=0000 Rev= 2.06
S:  Manufacturer=Linux 2.6.11-rc3-usbtest ohci_hcd
S:  Product=AT91RM9200 OHCI
S:  SerialNumber=at91rm9200-ohci
C:* #Ifs= 1 Cfg#= 1 Atr=c0 MxPwr=  0mA
I:  If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=01 Lev=01 Prnt=01 Port=01 Cnt=01 Dev#=  2 Spd=12  MxCh= 0
D:  Ver= 1.10 Cls=e0(unk. ) Sub=01 Prot=01 MxPS=64 #Cfgs=  1
P:  Vendor=0a12 ProdID=0001 Rev= 5.25
C:* #Ifs= 3 Cfg#= 1 Atr=c0 MxPwr=  0mA
I:  If#= 0 Alt= 0 #EPs= 3 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=81(I) Atr=03(Int.) MxPS=  16 Ivl=1ms
E:  Ad=02(O) Atr=02(Bulk) MxPS=  64 Ivl=0ms
E:  Ad=82(I) Atr=02(Bulk) MxPS=  64 Ivl=0ms
I:  If#= 1 Alt= 0 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=   0 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=   0 Ivl=1ms
I:  If#= 1 Alt= 1 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=   9 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=   9 Ivl=1ms
I:  If#= 1 Alt= 2 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=  17 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  17 Ivl=1ms
I:  If#= 1 Alt= 3 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=  25 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  25 Ivl=1ms
I:  If#= 1 Alt= 4 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=  33 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  33 Ivl=1ms
I:  If#= 1 Alt= 5 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=(none)
E:  Ad=03(O) Atr=01(Isoc) MxPS=  49 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  49 Ivl=1ms
I:  If#= 2 Alt= 0 #EPs= 0 Cls=fe(app. ) Sub=01 Prot=00 Driver=(none)

Damn, I think that's a hint. Here's what it looks like on a x86 machine:

$ cat /proc/bus/usb/devices

T:  Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12  MxCh= 2
B:  Alloc= 27/900 us ( 3%), #Int=  1, #Iso=  2
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS= 8 #Cfgs=  1
P:  Vendor=0000 ProdID=0000 Rev= 2.06
S:  Manufacturer=Linux 2.6.8.1-4-686 uhci_hcd
S:  Product=Intel Corp. 82801AA USB
S:  SerialNumber=0000:00:1f.2
C:* #Ifs= 1 Cfg#= 1 Atr=c0 MxPwr=  0mA
I:  If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#=  9 Spd=12  MxCh= 0
D:  Ver= 1.10 Cls=e0(unk. ) Sub=01 Prot=01 MxPS=64 #Cfgs=  1
P:  Vendor=0a12 ProdID=0001 Rev= 5.25
C:* #Ifs= 3 Cfg#= 1 Atr=c0 MxPwr=  0mA
I:  If#= 0 Alt= 0 #EPs= 3 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=81(I) Atr=03(Int.) MxPS=  16 Ivl=1ms
E:  Ad=02(O) Atr=02(Bulk) MxPS=  64 Ivl=0ms
E:  Ad=82(I) Atr=02(Bulk) MxPS=  64 Ivl=0ms
I:  If#= 1 Alt= 0 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=   0 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=   0 Ivl=1ms
I:  If#= 1 Alt= 1 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=   9 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=   9 Ivl=1ms
I:  If#= 1 Alt= 2 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=  17 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  17 Ivl=1ms
I:  If#= 1 Alt= 3 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=  25 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  25 Ivl=1ms
I:  If#= 1 Alt= 4 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=  33 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  33 Ivl=1ms
I:  If#= 1 Alt= 5 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=hci_usb
E:  Ad=03(O) Atr=01(Isoc) MxPS=  49 Ivl=1ms
E:  Ad=83(I) Atr=01(Isoc) MxPS=  49 Ivl=1ms
I:  If#= 2 Alt= 0 #EPs= 0 Cls=fe(app. ) Sub=01 Prot=00 Driver=(none)

Notice the "Driver=" field differences. Maybe that'd explain the symptoms?

Thanks in advance

Thibaut VARENE

-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel

Hi Thibaut,

the extra endpoints are for the SCO support. See the specification for more details.

Regards

Marcel

-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
Bluez-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel