Bluetooth TX Timeout Issue

[ratherDashing]

Seems to be an issue with the 3.1 kernel: https://bugs.archlinux.org/task/27449

Steps to recreate:

• Run bluetooth-agent 0000
• Try to pair phone with computer

Background information:

hci0: Type: BR/EDR Bus: USB
BD Address: 00:02:72:BB:E5:54 ACL MTU: 1022:8 SCO MTU: 121:3
UP RUNNING PSCAN
RX bytes:18134 acl:205 sco:0 events:632 errors:0
TX bytes:14192 acl:221 sco:0 commands:195 errors:0
Features: 0xff 0xfe 0x0d 0xfe 0x98 0x7f 0x79 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF
Link mode: SLAVE ACCEPT
Name: 'raspberrypi-0'
Class: 0x420100
Service Classes: Networking, Telephony
Device Class: Computer, Uncategorized
HCI Version: 3.0 (0x5) Revision: 0x9999
LMP Version: 3.0 (0x5) Subversion: 0x9999
Manufacturer: Atheros Communications, Inc. (69)

Distro: Raspbian
Kernel: [ 0.000000] Linux version 3.1.9+ (dc4@dc4-arm-01) (gcc version 4.5.1 (Broadcom-2708) ) #168 PREEMPT Sat Jul 14 18:56:31 BST 2012

[popcornmix]

Well, latest firmware is now 3.2.27. Also the USB driver has been udpated. Can you test again?
You could also try adding:
dwc_otg.microframe_schedule=1
to cmdline.txt.

[gregd72002]

I'm facing the same issue. Just tested it with the latest kernel:
Linux raspberrypi 3.2.27+ #60 PREEMPT Thu Aug 23 15:33:51 BST 2012 armv6l GNU/Linux

And the issues is still there.

It looks like we need kernel 3.3 to fix it (based on the archlinux bug report)
or the following patches:
http://article.gmane.org/gmane.linux.bluez.kernel/19950/
http://article.gmane.org/gmane.linux.bluez.kernel/19951/

[popcornmix]

@gregd72002
Have you tried applying the patches? Does it fix it?

[gregd72002]

No, I have not. I do not have the environment just now to compile it.

[gregd72002]

Tried it overnight and it works! However the patches do no apply cleanly.. Will try to issue a diff in a moment

[gregd72002]

This is a consolidated patch that fixes the issue in the current kernel sources.

I also tested it myself by issuing some scan commands and all seems to be fine!

diff -rupN linux.old/include/net/bluetooth/hci_core.h linux.new/include/net/bluetooth/hci_core.h
--- linux.old/include/net/bluetooth/hci_core.h  2012-08-25 10:09:56.532713215 +0100
+++ linux.new/include/net/bluetooth/hci_core.h  2012-08-25 10:17:33.167036880 +0100
@@ -130,7 +130,7 @@ struct hci_dev {
    __u8        major_class;
    __u8        minor_class;
    __u8        features[8];
-   __u8        extfeatures[8];
+   __u8        host_features[8];
    __u8        commands[64];
    __u8        ssp_mode;
    __u8        hci_ver;
@@ -618,7 +618,7 @@ void hci_conn_del_sysfs(struct hci_conn
 #define lmp_le_capable(dev)        ((dev)->features[4] & LMP_LE)

 /* ----- Extended LMP capabilities ----- */
-#define lmp_host_le_capable(dev)   ((dev)->extfeatures[0] & LMP_HOST_LE)
+#define lmp_host_le_capable(dev)   ((dev)->host_features[0] & LMP_HOST_LE)

 /* ----- HCI protocols ----- */
 struct hci_proto {
diff -rupN linux.old/net/bluetooth/hci_event.c linux.new/net/bluetooth/hci_event.c
--- linux.old/net/bluetooth/hci_event.c 2012-08-25 10:11:25.409662054 +0100
+++ linux.new/net/bluetooth/hci_event.c 2012-08-25 10:18:06.035908486 +0100
@@ -695,7 +695,14 @@ static void hci_cc_read_local_ext_featur
    if (rp->status)
        return;

-   memcpy(hdev->extfeatures, rp->features, 8);
+   switch (rp->page) {
+   case 0:
+       memcpy(hdev->features, rp->features, 8);
+       break;
+   case 1:
+       memcpy(hdev->host_features, rp->features, 8);
+       break;
+   }

    hci_req_complete(hdev, HCI_OP_READ_LOCAL_EXT_FEATURES, rp->status);
 }

[gregd72002]

Right, this does work partially on my brand-less dongle. The timeout issue now appears randomly. While I was able to pair one device once now the timeout issue is back. Not sure what it depends on.

Also, I tried to use a different bluetooth dongle (Belkin mini) and with this one nothing works at all..

I believe we really need kernel-3.3/3.4 in here... any timeframes for this?

[gregd72002]

Did some debugging:

[  940.548222] Bluetooth: Generic Bluetooth USB driver ver 0.6
[  940.548424] hci_register_dev: c8594800 name  bus 1 owner bf296d08
[  940.557617] hci_register_sysfs: c8594800 name hci0 bus 1
[  940.560798] hci_power_on: hci0
[  940.560857] hci_dev_get: 0
[  940.560878] hci_dev_open: hci0 c8594800
[  940.560970] __hci_request: hci0 start
[  940.561014] hci_init_req: hci0 0
[  940.561054] hci_send_cmd: hci0 opcode 0xc03 plen 0
[  940.561112] hci_send_cmd: skb len 3
[  940.561181] hci_cmd_task: hci0 cmd 1
[  940.561248] hci_send_frame: hci0 type 1 len 3
[  940.561387] hci_send_cmd: hci0 opcode 0x1003 plen 0
[  940.561484] hci_send_cmd: skb len 3
[  940.561527] hci_send_cmd: hci0 opcode 0x1001 plen 0
[  940.561600] hci_cmd_task: hci0 cmd 0
[  940.561655] hci_send_cmd: skb len 3
[  940.561722] hci_cmd_task: hci0 cmd 0
[  940.561756] hci_send_cmd: hci0 opcode 0x1005 plen 0
[  940.561792] hci_send_cmd: skb len 3
[  940.561810] hci_send_cmd: hci0 opcode 0x1009 plen 0
[  940.561862] hci_cmd_task: hci0 cmd 0
[  940.561915] hci_send_cmd: skb len 3
[  940.561934] hci_send_cmd: hci0 opcode 0xc23 plen 0
[  940.561969] hci_cmd_task: hci0 cmd 0
[  940.562007] hci_send_cmd: skb len 3
[  940.562042] hci_send_cmd: hci0 opcode 0xc14 plen 0
[  940.562084] hci_cmd_task: hci0 cmd 0
[  940.562136] hci_send_cmd: skb len 3
[  940.562172] hci_send_cmd: hci0 opcode 0xc25 plen 0
[  940.562207] hci_cmd_task: hci0 cmd 0
[  940.562260] hci_send_cmd: skb len 3
[  940.562296] hci_send_cmd: hci0 opcode 0xc05 plen 1
[  940.562332] hci_cmd_task: hci0 cmd 0
[  940.562384] hci_send_cmd: skb len 4
[  940.562420] hci_send_cmd: hci0 opcode 0xc16 plen 2
[  940.562455] hci_cmd_task: hci0 cmd 0
[  940.562507] hci_send_cmd: skb len 5
[  940.562543] hci_send_cmd: hci0 opcode 0xc12 plen 7
[  940.562587] hci_cmd_task: hci0 cmd 0
[  940.562618] hci_send_cmd: skb len 10
[  940.562674] hci_cmd_task: hci0 cmd 0
[  940.562793] hci_sock_dev_event: hdev hci0 event 1
[  940.562861] hci_send_to_sock: hdev   (null) len 8
[  940.563467] usbcore: registered new interface driver btusb
[  940.861966] hci_rx_task: hci0
[  940.862040] hci_cc_reset: hci0 status 0x0
[  940.862079] hci_req_complete: hci0 command 0x0c03 result 0x00
[  940.862145] hci_cmd_task: hci0 cmd 1
[  940.862192] hci_send_frame: hci0 type 1 len 3
[  940.863942] hci_rx_task: hci0
[  940.864011] hci_cc_read_local_features: hci0 status 0x0
[  940.864056] hci_cc_read_local_features: hci0 features 0xffff8ffe9bff7983
[  940.864103] hci_cmd_task: hci0 cmd 1
[  940.864164] hci_send_frame: hci0 type 1 len 3
[  940.865963] hci_rx_task: hci0
[  940.866034] hci_cc_read_local_version: hci0 status 0x0
[  940.866075] hci_cc_read_local_version: hci0 manufacturer 15 hci ver 4:20868
[  940.866121] hci_send_cmd: hci0 opcode 0xc01 plen 8
[  940.866175] hci_send_cmd: skb len 11
[  940.866211] hci_send_cmd: hci0 opcode 0x1002 plen 0
[  940.866248] hci_send_cmd: skb len 3
[  940.866284] hci_send_cmd: hci0 opcode 0xc56 plen 1
[  940.866444] hci_send_cmd: skb len 4
[  940.866508] hci_send_cmd: hci0 opcode 0xc45 plen 1
[  940.866561] hci_send_cmd: skb len 4
[  940.866596] hci_send_cmd: hci0 opcode 0xc58 plen 0
[  940.866641] hci_send_cmd: skb len 3
[  940.866676] hci_send_cmd: hci0 opcode 0x1004 plen 1
[  940.866727] hci_send_cmd: skb len 4
[  940.866802] hci_cmd_task: hci0 cmd 1
[  940.866874] hci_send_frame: hci0 type 1 len 3
[  940.867920] hci_rx_task: hci0
[  940.867979] hci_cc_read_buffer_size: hci0 status 0x0
[  940.868024] hci_cc_read_buffer_size: hci0 acl mtu 1021:8 sco mtu 64:1
[  940.868066] hci_cmd_task: hci0 cmd 1
[  940.868117] hci_send_frame: hci0 type 1 len 3
[  940.868939] hci_rx_task: hci0
[  940.868994] hci_cc_read_bd_addr: hci0 status 0x0
[  940.869033] hci_req_complete: hci0 command 0x1009 result 0x00
[  940.869091] hci_cmd_task: hci0 cmd 1
[  940.869156] hci_send_frame: hci0 type 1 len 3
[  940.870930] hci_rx_task: hci0
[  940.870977] hci_cc_read_class_of_dev: hci0 status 0x0
[  940.871018] hci_cc_read_class_of_dev: hci0 class 0x000000
[  940.871075] hci_cmd_task: hci0 cmd 1
[  940.871138] hci_send_frame: hci0 type 1 len 3
[  940.876953] hci_rx_task: hci0
[  940.877025] hci_event_packet: hci0 event 0x69
[  940.877969] hci_rx_task: hci0
[  940.878035] hci_event_packet: hci0 event 0x0
[  940.878090] hci_event_packet: hci0 event 0x0
[  940.878134] hci_event_packet: hci0 event 0x0
[  940.878170] hci_event_packet: hci0 event 0x0
[  940.878208] hci_event_packet: hci0 event 0x0
[  940.878249] hci_event_packet: hci0 event 0x0
[  940.878285] hci_event_packet: hci0 event 0x0
[  940.878320] hci_event_packet: hci0 event 0x0
[  940.878964] hci_rx_task: hci0
[  940.879014] hci_event_packet: hci0 event 0x0
[  940.879054] hci_event_packet: hci0 event 0x0
[  940.879091] hci_event_packet: hci0 event 0x0
[  940.879129] hci_event_packet: hci0 event 0x0
[  940.879179] hci_event_packet: hci0 event 0x0
[  940.879215] hci_event_packet: hci0 event 0x0
[  940.879251] hci_event_packet: hci0 event 0x0
[  940.879287] hci_event_packet: hci0 event 0x0
[  940.879956] hci_rx_task: hci0
[  940.880020] hci_event_packet: hci0 event 0x0
[  940.880073] hci_event_packet: hci0 event 0x0
[  940.880118] hci_event_packet: hci0 event 0x0
[  940.880154] hci_event_packet: hci0 event 0x0
[  940.880191] hci_event_packet: hci0 event 0x0
[  940.880226] hci_event_packet: hci0 event 0x0
[  940.880268] hci_event_packet: hci0 event 0x0
[  940.880304] hci_event_packet: hci0 event 0x0
[  940.880964] hci_rx_task: hci0
[  940.881028] hci_event_packet: hci0 event 0x0
[  940.881081] hci_event_packet: hci0 event 0x0
[  940.881102] hci_event_packet: hci0 event 0x0
[  940.881154] hci_event_packet: hci0 event 0x0
[  940.881190] hci_event_packet: hci0 event 0x0
[  940.881226] hci_event_packet: hci0 event 0x0
[  940.881268] hci_event_packet: hci0 event 0x0
[  940.881303] hci_event_packet: hci0 event 0x0
[  940.883971] hci_rx_task: hci0
[  940.884040] hci_event_packet: hci0 event 0x0
[  940.884094] hci_event_packet: hci0 event 0x0
[  940.884139] hci_event_packet: hci0 event 0x0
[  940.884175] hci_event_packet: hci0 event 0x0
[  940.884211] hci_event_packet: hci0 event 0x0
[  940.884253] hci_event_packet: hci0 event 0x0
[  940.884289] hci_event_packet: hci0 event 0x0
[  940.884325] hci_event_packet: hci0 event 0x0
[  940.884958] hci_rx_task: hci0
[  940.885003] hci_event_packet: hci0 event 0x0
[  940.885042] hci_event_packet: hci0 event 0x0
[  940.885095] hci_event_packet: hci0 event 0x0
[  940.885123] hci_event_packet: hci0 event 0x0
[  940.885159] hci_event_packet: hci0 event 0x0
[  940.885195] hci_event_packet: hci0 event 0x0
[  940.885232] hci_event_packet: hci0 event 0x0
[  940.885269] hci_event_packet: hci0 event 0x0
[  940.885967] hci_rx_task: hci0
[  940.886028] hci_event_packet: hci0 event 0x0
[  940.886081] hci_event_packet: hci0 event 0x0
[  940.886135] hci_event_packet: hci0 event 0x0
[  940.886172] hci_event_packet: hci0 event 0x0
[  940.886208] hci_event_packet: hci0 event 0x0
[  940.886261] hci_event_packet: hci0 event 0x0
[  940.886298] hci_event_packet: hci0 event 0x0
[  940.886450] hci_event_packet: hci0 event 0x0
[  940.886966] hci_rx_task: hci0
[  940.887017] hci_event_packet: hci0 event 0x0
[  940.887057] hci_event_packet: hci0 event 0x0
[  940.887108] hci_event_packet: hci0 event 0x0
[  940.887150] hci_event_packet: hci0 event 0x0
[  940.887186] hci_event_packet: hci0 event 0x0
[  940.887221] hci_event_packet: hci0 event 0x0
[  940.887259] hci_event_packet: hci0 event 0x0
[  940.887295] hci_event_packet: hci0 event 0x0
[  940.887965] hci_rx_task: hci0
[  940.888015] hci_event_packet: hci0 event 0x0
[  940.888054] hci_event_packet: hci0 event 0x0
[  940.888092] hci_event_packet: hci0 event 0x0
[  940.888131] hci_event_packet: hci0 event 0x0
[  940.888166] hci_event_packet: hci0 event 0x0
[  940.888202] hci_event_packet: hci0 event 0x0
[  940.888244] hci_event_packet: hci0 event 0x0
[  940.888279] hci_event_packet: hci0 event 0x0
[  940.888961] hci_rx_task: hci0
[  940.889010] hci_event_packet: hci0 event 0x0
[  940.889049] hci_event_packet: hci0 event 0x0
[  940.889085] hci_event_packet: hci0 event 0x0
[  940.889127] hci_event_packet: hci0 event 0x0
[  940.889163] hci_event_packet: hci0 event 0x0
[  940.889198] hci_event_packet: hci0 event 0x0
[  940.889242] hci_event_packet: hci0 event 0x0
[  940.889283] hci_event_packet: hci0 event 0x0
[  940.889967] hci_rx_task: hci0
[  940.890014] hci_event_packet: hci0 event 0x0
[  940.890053] hci_event_packet: hci0 event 0x0
[  940.890104] hci_event_packet: hci0 event 0x0
[  940.890147] hci_event_packet: hci0 event 0x0
[  940.890181] hci_event_packet: hci0 event 0x0
[  940.890217] hci_event_packet: hci0 event 0x0
[  940.890254] hci_event_packet: hci0 event 0x0
[  941.866443] Bluetooth: hci0 command tx timeout
[  941.866522] hci_cmd_task: hci0 cmd 1
[  941.866585] hci_send_frame: hci0 type 1 len 3
[  942.866455] Bluetooth: hci0 command tx timeout
[  942.866564] hci_cmd_task: hci0 cmd 1
[  942.866638] hci_send_frame: hci0 type 1 len 4
[  943.866492] Bluetooth: hci0 command tx timeout
[  943.866569] hci_cmd_task: hci0 cmd 1
[  943.866635] hci_send_frame: hci0 type 1 len 5
[  943.868358] hci_rx_task: hci0
[  943.868426] hci_event_packet: hci0 event 0x0
[  943.868491] hci_conn_request_evt: hci0 bdaddr 00:00:CF:E4:00:16 type 0x0
[  943.868553] sco_connect_ind: hdev hci0, bdaddr 00:00:CF:E4:00:16
[  943.868613] hci_inquiry_cache_lookup: cache c8594bdc, 00:00:CF:E4:00:16
[  943.868673] hci_conn_add: hci0 dst 00:00:CF:E4:00:16
[  943.868789] hci_conn_init_sysfs: conn c8587200
[  943.868848] hci_send_cmd: hci0 opcode 0x429 plen 21
[  943.868915] hci_send_cmd: skb len 24
[  943.868969] hci_remote_version_evt: hci0
[  943.869010] hci_cmd_task: hci0 cmd 0
[  944.866530] Bluetooth: hci0 command tx timeout
[  944.866607] hci_cmd_task: hci0 cmd 1
[  944.866681] hci_send_frame: hci0 type 1 len 10
[  944.944545] hci_rx_task: hci0
[  944.944601] hci_cc_delete_stored_link_key: hci0 status 0x0
[  944.944641] hci_req_complete: hci0 command 0x0c12 result 0x00
[  944.944708] hci_cmd_task: hci0 cmd 1
[  944.944755] hci_send_frame: hci0 type 1 len 11
[  944.946609] hci_rx_task: hci0
[  944.946658] hci_cc_set_event_mask: hci0 status 0x0
[  944.946699] hci_req_complete: hci0 command 0x0c01 result 0x00
[  944.946818] hci_cmd_task: hci0 cmd 1
[  944.946878] hci_send_frame: hci0 type 1 len 3
[  945.316991] usb 1-1.3.2: reset full-speed USB device number 6 using dwc_otg
[  945.647063] usb 1-1.3.1: reset full-speed USB device number 5 using dwc_otg
[  945.857047] usb 1-1.3.1: reset full-speed USB device number 5 using dwc_otg
[  945.946586] Bluetooth: hci0 command tx timeout
[  945.946659] hci_cmd_task: hci0 cmd 1
[  945.946738] hci_send_frame: hci0 type 1 len 4
[  946.946611] Bluetooth: hci0 command tx timeout
[  946.946671] hci_cmd_task: hci0 cmd 1
[  946.946747] hci_send_frame: hci0 type 1 len 4
[  947.717055] usb 1-1.3.1: reset full-speed USB device number 5 using dwc_otg
[  947.937177] usb 1-1.3.1: reset full-speed USB device number 5 using dwc_otg
[  947.946651] Bluetooth: hci0 command tx timeout
[  947.946788] hci_cmd_task: hci0 cmd 1
[  947.946885] hci_send_frame: hci0 type 1 len 3
[  948.457167] usb 1-1.3.2: reset full-speed USB device number 6 using dwc_otg
[  948.946676] Bluetooth: hci0 command tx timeout
[  948.946749] hci_cmd_task: hci0 cmd 1
[  948.946814] hci_send_frame: hci0 type 1 len 4
[  948.948068] hci_rx_task: hci0
[  948.948135] hci_cc_read_local_commands: hci0 status 0x0
[  948.948190] hci_send_cmd: hci0 opcode 0x80f plen 2
[  948.948236] hci_send_cmd: skb len 5
[  948.948274] hci_req_complete: hci0 command 0x1002 result 0x00
[  948.948339] hci_event_packet: hci0 event 0x10
[  948.948392] hci_inquiry_complete_evt: hci0 status 1
[  948.948427] hci_req_complete: hci0 command 0x0401 result 0x01
[  948.948467] hci_conn_check_pending: hdev hci0
[  948.948519] hci_event_packet: hci0 event 0x0
[  948.948554] hci_event_packet: hci0 event 0x0
[  948.948617] hci_event_packet: hci0 event 0x0
[  948.948655] hci_cmd_task: hci0 cmd 1
[  948.948698] hci_send_frame: hci0 type 1 len 24
[  949.227131] usb 1-1.3.1: reset full-speed USB device number 5 using dwc_otg
[  949.946695] Bluetooth: hci0 command tx timeout
[  949.946786] hci_cmd_task: hci0 cmd 1
[  949.946837] hci_send_frame: hci0 type 1 len 5
[  950.556840] __hci_request: TIMEOUT
[  950.556893] __hci_request: hci0 end: err -110
[  950.946690] Bluetooth: hci0 command tx timeout
[  950.946786] hci_cmd_task: hci0 cmd 1

and one more run of the same case but it fails in a different stage?

[  164.541215] Bluetooth: Core ver 2.16
[  164.543562] NET: Registered protocol family 31
[  164.543591] Bluetooth: HCI device and connection manager initialized
[  164.543611] Bluetooth: HCI socket layer initialized
[  164.543625] Bluetooth: L2CAP socket layer initialized
[  164.543698] Bluetooth: SCO socket layer initialized
[  205.951115] Bluetooth: Generic Bluetooth USB driver ver 0.6
[  205.951335] bluetooth:hci_register_dev: c84da000 name  bus 1 owner bf239d08
[  205.951619] bluetooth:hci_register_sysfs: c84da000 name hci0 bus 1
[  205.954824] bluetooth:hci_power_on: hci0
[  205.954861] bluetooth:hci_dev_get: 0
[  205.954880] bluetooth:hci_dev_open: hci0 c84da000
[  205.954974] bluetooth:__hci_request: hci0 start
[  205.954997] bluetooth:hci_init_req: hci0 0
[  205.955047] bluetooth:hci_send_cmd: hci0 opcode 0xc03 plen 0
[  205.955114] bluetooth:hci_send_cmd: skb len 3
[  205.955191] bluetooth:hci_cmd_task: hci0 cmd 1
[  205.955252] bluetooth:hci_send_frame: hci0 type 1 len 3
[  205.955350] bluetooth:hci_send_cmd: hci0 opcode 0x1003 plen 0
[  205.955528] bluetooth:hci_send_cmd: skb len 3
[  205.955585] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.955621] bluetooth:hci_send_cmd: hci0 opcode 0x1001 plen 0
[  205.955660] bluetooth:hci_send_cmd: skb len 3
[  205.955698] bluetooth:hci_send_cmd: hci0 opcode 0x1005 plen 0
[  205.955735] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.955792] bluetooth:hci_send_cmd: skb len 3
[  205.955829] bluetooth:hci_send_cmd: hci0 opcode 0x1009 plen 0
[  205.955865] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.955907] bluetooth:hci_send_cmd: skb len 3
[  205.955943] bluetooth:hci_send_cmd: hci0 opcode 0xc23 plen 0
[  205.955979] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956054] bluetooth:hci_send_cmd: skb len 3
[  205.956093] bluetooth:hci_send_cmd: hci0 opcode 0xc14 plen 0
[  205.956130] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956170] bluetooth:hci_send_cmd: skb len 3
[  205.956208] bluetooth:hci_send_cmd: hci0 opcode 0xc25 plen 0
[  205.956243] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956289] bluetooth:hci_send_cmd: skb len 3
[  205.956326] bluetooth:hci_send_cmd: hci0 opcode 0xc05 plen 1
[  205.956362] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956428] bluetooth:hci_send_cmd: skb len 4
[  205.956466] bluetooth:hci_send_cmd: hci0 opcode 0xc16 plen 2
[  205.956502] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956542] bluetooth:hci_send_cmd: skb len 5
[  205.956579] bluetooth:hci_send_cmd: hci0 opcode 0xc12 plen 7
[  205.956614] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956661] bluetooth:hci_send_cmd: skb len 10
[  205.956735] bluetooth:hci_cmd_task: hci0 cmd 0
[  205.956839] bluetooth:hci_sock_dev_event: hdev hci0 event 1
[  205.956887] bluetooth:hci_send_to_sock: hdev   (null) len 8
[  205.957509] usbcore: registered new interface driver btusb
[  205.959127] bluetooth:hci_rx_task: hci0
[  205.959195] bluetooth:hci_cc_reset: hci0 status 0x0
[  205.959237] bluetooth:hci_req_complete: hci0 command 0x0c03 result 0x00
[  205.959304] bluetooth:hci_cmd_task: hci0 cmd 1
[  205.959350] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.950997] Bluetooth: hci0 command tx timeout
[  206.951085] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.951166] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.952235] bluetooth:hci_rx_task: hci0
[  206.952304] bluetooth:hci_cc_read_local_version: hci0 status 0x0
[  206.952367] bluetooth:hci_cc_read_local_version: hci0 manufacturer 15 hci ver 4:20868
[  206.952428] bluetooth:hci_send_cmd: hci0 opcode 0xc01 plen 8
[  206.952484] bluetooth:hci_send_cmd: skb len 11
[  206.952521] bluetooth:hci_send_cmd: hci0 opcode 0x1002 plen 0
[  206.952565] bluetooth:hci_send_cmd: skb len 3
[  206.952625] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.952692] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.955263] bluetooth:hci_rx_task: hci0
[  206.955335] bluetooth:hci_cc_read_buffer_size: hci0 status 0x0
[  206.955378] bluetooth:hci_cc_read_buffer_size: hci0 acl mtu 1021:8 sco mtu 64:1
[  206.955444] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.955491] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.957223] bluetooth:hci_rx_task: hci0
[  206.957301] bluetooth:hci_cc_read_bd_addr: hci0 status 0x0
[  206.957341] bluetooth:hci_req_complete: hci0 command 0x1009 result 0x00
[  206.957387] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.957455] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.959230] bluetooth:hci_rx_task: hci0
[  206.959301] bluetooth:hci_cc_read_class_of_dev: hci0 status 0x0
[  206.959340] bluetooth:hci_cc_read_class_of_dev: hci0 class 0x000000
[  206.959384] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.959447] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.976246] bluetooth:hci_rx_task: hci0
[  206.976320] bluetooth:hci_cc_read_local_name: hci0 status 0x0
[  206.976388] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.976454] bluetooth:hci_send_frame: hci0 type 1 len 3
[  206.978251] bluetooth:hci_rx_task: hci0
[  206.978316] bluetooth:hci_cc_read_voice_setting: hci0 status 0x0
[  206.978356] bluetooth:hci_cc_read_voice_setting: hci0 voice setting 0x0060
[  206.978411] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.978471] bluetooth:hci_send_frame: hci0 type 1 len 4
[  206.980220] bluetooth:hci_rx_task: hci0
[  206.980269] bluetooth:hci_cc_set_event_flt: hci0 status 0x0
[  206.980310] bluetooth:hci_req_complete: hci0 command 0x0c05 result 0x00
[  206.980368] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.980433] bluetooth:hci_send_frame: hci0 type 1 len 5
[  206.982259] bluetooth:hci_rx_task: hci0
[  206.982326] bluetooth:hci_cc_write_ca_timeout: hci0 status 0x0
[  206.982365] bluetooth:hci_req_complete: hci0 command 0x0c16 result 0x00
[  206.982420] bluetooth:hci_cmd_task: hci0 cmd 1
[  206.982480] bluetooth:hci_send_frame: hci0 type 1 len 10
[  207.060284] bluetooth:hci_rx_task: hci0
[  207.060357] bluetooth:hci_cc_delete_stored_link_key: hci0 status 0x0
[  207.060397] bluetooth:hci_req_complete: hci0 command 0x0c12 result 0x00
[  207.060485] bluetooth:hci_cmd_task: hci0 cmd 1
[  207.060552] bluetooth:hci_send_frame: hci0 type 1 len 11
[  207.062256] bluetooth:hci_rx_task: hci0
[  207.062330] bluetooth:hci_cc_set_event_mask: hci0 status 0x0
[  207.062373] bluetooth:hci_req_complete: hci0 command 0x0c01 result 0x00
[  207.062429] bluetooth:hci_cmd_task: hci0 cmd 1
[  207.062489] bluetooth:hci_send_frame: hci0 type 1 len 3
[  208.061037] Bluetooth: hci0 command tx timeout
[  208.061111] bluetooth:hci_cmd_task: hci0 cmd 1
[  215.951426] bluetooth:__hci_request: TIMEOUT
[  215.951479] bluetooth:__hci_request: hci0 end: err -110

So, what does it tell us? What is the next step?

[Diaoul]

@gregd72002: I am interested in how you did to enable that much logging, how did you achieve this?

[gregd72002]

Dialoul: you need to compile kernel with CONFIG_DYNAMIC_DEBUG option (http://www.mjmwired.net/kernel/Documentation/dynamic-debug-howto.txt)

then once using the new kernel mount debugfs:

mount -t debugfs none /sys/kernel/debug/

and activate debug for items you interested in (refer to dynamic-debug-howto.txt for more info)):

echo -n "file hci_core.c +pf" > /sys/kernel/debug/dynamic_debug/control
echo -n "file hci_event.c +pf" > /sys/kernel/debug/dynamic_debug/control
echo -n "file mgmt.c +pf" > /sys/kernel/debug/dynamic_debug/control
echo -n "file btusb.c +pf" > /sys/kernel/debug/dynamic_debug/control
echo -n "module bluetooth +pf" > /sys/kernel/debug/dynamic_debug/control
echo -n "module btusb +pf" > /sys/kernel/debug/dynamic_debug/control

Then load the module you interested in and view the debug in 'dmesg'

[gregd72002]

All my investigations are leading to an issue with USB subsystem and not bluetooth subsystem...

Cross referencing to a possible root cause: #19
raspberrypi/firmware#19

[gregd72002]

Good progress!! Resolved!!

As thought - nothing to do with bluetooth subsystem.

Modify your cmdline.txt to have:

dwc_otg.microframe_schedule=1 dwc_otg.speed=1

my full cmdline.txt looks like:

dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline dwc_otg.microframe_schedule=1 dwc_otg.speed=1 rootwait

and everything works now as expected!

Just to share my findings:

1. the issue with kernel 3.1.x and 3.2.x that is mentioned in the initial comment is to do with broken bluetooth dongles; this is ones that have issues with providing features lists (extfeatures).
2. the above issue was also resolved in kernels >3.3; so I tried to incorporate kernel 3.5.4 bluetooth system into RPi kernel and this did not resolve my problem either
3. the timeout issue I had was appearing randomly on a different occasions so nothing to do really with initiation
4. thus, usb was suspected to be broken...

[popcornmix]

@gregd72002
Glad it's working. Are both microframe_schedule and speed required?
(in latest firmware microframe_schedule is actually on by default, but can be disabled with =0)

[gregd72002]

@popcornmix
I just tried it and yes, indeed one just need 'speed' option, microframe_schedule is not required based on my last hour testing