15.10: BT Command List not created: bluetooth:__hci_req_sync:298: hci1 end: err -ETIMEDOUT

[TJ]

$ hcitool dev
Devices:
 hci1 00:10:7A:4D:15:33
 hci0 00:1F:3A:E0:0A:AF

$ hcitool -i hci1 scan
Scanning ...
 00:0A:95:4B:BD:C2 Apple Wireless Keyboard

$ sudo systemctl restart bluetooth

$ journalctl -u bluetooth | grep adapter_service_add
Sep 03 19:39:12 hephaestion.lan.iam.tj bluetoothd[3973]: src/adapter.c:adapter_service_add() /org/bluez/hci0

$ bluetoothctl
[NEW] Controller 00:1F:3A:E0:0A:AF hephaestion.lan.iam.tj [default]
[NEW] Device 00:0A:95:4B:BD:C2 Apple Wireless Keyboard
[NEW] Device 00:07:61:3B:86:98 Bluetooth Travel Mouse
[NEW] Device 00:19:15:29:83:14 Think Outside Keyboard
[bluetooth]# list
Controller 00:1F:3A:E0:0A:AF hephaestion.lan.iam.tj [default]

[Simon Fels (morphis)]

Can you please do the following to generate a more verbose output:

$ sudo systemctl stop bluetooth

$ MGMT_DEBUG=1 sudo bluetoothd -n -d &> bluetoothd-multiple-adapters.log

In another terminal:

$ bluetoothctl
[bluetooth]# list

Please add all output here and attach the file bluetoothd-multiple-adapters.log

[TJ (tj)]

$ cat /etc/systemd/system/bluetooth.service
.include /lib/systemd/service/bluetooth.service

[Service]
ExecStart=/usr/lib/bluetooth/bluetoothd -d

$ journalctl -fu bluetooth | tee /tmp/bluetooth-multiple-adapters.log
...
<<<< Stop/Start bluetooth service
...
<<<< Insert 2nd USB adapter
Sep 04 23:46:32 hephaestion.lan.iam.tj bluetoothd[23908]: src/rfkill.c:rfkill_event() RFKILL event idx 5 type 2 op 0 soft 0 hard 0

$ bluetoothctl
[NEW] Controller 00:1F:3A:E0:0A:AF hephaestion.lan.iam.tj [default]
[NEW] Device 00:0A:95:4B:BD:C2 Apple Wireless Keyboard
[NEW] Device 00:07:61:3B:86:98 Bluetooth Travel Mouse
[NEW] Device 00:19:15:29:83:14 Think Outside Keyboard
[bluetooth]# list
Controller 00:1F:3A:E0:0A:AF hephaestion.lan.iam.tj [default]
[CHG] Device 00:07:61:3B:86:98 Connected: yes

$ hcitool dev
Devices:
 hci1 00:10:7A:4D:15:33
 hci0 00:1F:3A:E0:0A:AF

$ lsusb
# Built-in (hci0)
Bus 007 Device 003: ID 413c:8126 Dell Computer Corp. Wireless 355 Bluetooth
# Hot-plugged (hci1)
Bus 006 Device 011: ID 0bdb:1002 Ericsson Business Mobile Networks BV Bluetooth Device 1.2

[TJ (tj)]

I've been working on this some more. I noticed that even when both adapters are connected before bluetoothd starts, it does not find the 2nd adapter.

The problem appears to be in the read_index_list_complete() call-back, which sees only 1 controller despite the RFkill events reporting 3 devices, 2 BT (type 2) and 1 WiFi.

src/main.c:main() Entering main loop
src/rfkill.c:rfkill_event() RFKILL event idx 0 type 2 op 0 soft 0 hard 0
Bluetooth management interface 1.10 initialized
src/adapter.c:read_version_complete() sending read supported commands command
src/adapter.c:read_version_complete() sending read index list command
src/rfkill.c:rfkill_event() RFKILL event idx 1 type 1 op 0 soft 0 hard 0
src/rfkill.c:rfkill_event() RFKILL event idx 2 type 2 op 0 soft 0 hard 0
src/adapter.c:read_commands_complete() Number of commands: 61
src/adapter.c:read_commands_complete() Number of events: 34
src/adapter.c:read_commands_complete() enabling kernel-side connection control
src/adapter.c:read_index_list_complete() Number of controllers: 1

[TJ (tj)]

This looks to be a kernel issue in net/bluetooth/mgmt.c::read_index_list(). rp->num_controllers, etc., is set as hci_dev_list is iterated over. Some devices are not added due to test flags or quirk bits.

I'll check how 'hcitool dev' gathers its list of adapters.

[TJ (tj)]

I believe I've identified the root-cause:

$ hciconfig hci1 features
hci1: Type: BR/EDR Bus: USB
        BD Address: 00:10:7A:4D:15:33 ACL MTU: 672:8 SCO MTU: 255:255
        Features: 0xff 0xfb 0x01 0x00 0x00 0x00 0x00 0x00
                <3-slot packets> <5-slot packets> <encryption> <slot offset>
                <timing accuracy> <role switch> <hold mode> <sniff mode>
                <park state> <RSSI> <SCO link> <HV2 packets> <HV3 packets>
                <u-law log> <A-law log> <CVSD>

$ hciconfig hci1 commands
Can't read support commands on hci1: Input/output error (5)

I enabled dynamic_debug to get the BT_DBG() output:

echo 'file drivers/bluetooth/* +p' | sudo tee /sys/kernel/debug/dynamic_debug/control
echo 'file net/bluetooth/* +p' | sudo tee /sys/kernel/debug/dynamic_debug/control

The attached extract is from the kernel log when connecting the external USB Bluetooth device.

[TJ (tj)]

Extract from the kern.log:

Sep 10 00:17:36 hephaestion kernel: [21515.251265] hci1 end: err -110

-110 == -ETIMEDOUT

There are 2 functions that print the message "end: err %d":

net/bluetooth/hci_core.c::__hci_cmd_sync_ev()
net/bluetooth/hci_core.c::__hci_req_sync()

[TJ (tj)]

Another log, this time capturing the module, function, line-number and message.

Sep 10 00:52:44 hephaestion kernel: [23623.022036] bluetooth:hci_cmd_work:4358: hci1 cmd_cnt 1 cmd queued 4
Sep 10 00:52:44 hephaestion kernel: [23623.022044] bluetooth:hci_send_frame:3494: hci1 type 1 len 3
Sep 10 00:52:54 hephaestion kernel: [23633.012115] bluetooth:__hci_req_sync:298: hci1 end: err -110

[TJ (tj)]

I've now tested the device on two other systems with older releases; the results seem to point to a regression somewhere between v3.2 and v3.8:

FAILS: linux 3.8.0-35-generic, bluez 4.101-0ubuntu8b1 (same failure mode as Linux v4.2)
WORKS: linux 3.2.0-30-generic-pae, bluez 4.98-2ubuntu7 (shows up as an adapter after doing 'hciconfig hci1 up')

[Simon Fels (morphis)]

Please note that the kernel subsystem performs various initialization steps for each HCI controller. Depending on if a controller passes this it gets up in bluetoothd or not. If a HCI controller is still flagged with HCI_SETUP or HCI_CONFIG then something is wrong. Even if the controller turns up in hciconfig that doesn't mean it is usable through the MGMT kernel interface which is used by bluetoothd today.

If you're debugging this in the kernel look at __hci_init in net/bluetooth/hci_core.c and verify all HCI commands are sent correctly and no one gets an error. You can also log those HCI packages send across the wire with hcidump and analyze the output with wireshark.

Could you also please note which types of BT modules you're using?

Also as you changed the summary it's now pretty unclear to a new person reading this what the actual problem is ...

[TJ (tj)]

The actual problem is -ETIMEDOUT.

I'm doing git-bisect to find the offending commit(s).

[Daniel van Vugt (vanvugt)]

Thank you for reporting this bug to Ubuntu. Ubuntu 15.10 (wily) reached end-of-life on July 28, 2016.

See this document for currently supported Ubuntu releases:
https://wiki.ubuntu.com/Releases

Please upgrade to the latest version and re-test.

[Launchpad Janitor (janitor)]

[Expired for linux (Ubuntu) because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for bluez (Ubuntu) because there has been no activity for 60 days.]