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

Bug #1491988 reported by TJ
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
bluez (Ubuntu)
High
Unassigned
linux (Ubuntu)
High
Unassigned

Bug Description

$ 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]

Revision history for this message
Simon Fels (morphis) wrote :

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

Changed in bluez (Ubuntu):
status: New → Incomplete
Revision history for this message
TJ (tj) wrote :

$ 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)
Changed in bluez (Ubuntu):
status: Incomplete → Triaged
Revision history for this message
TJ (tj) wrote :

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

Revision history for this message
TJ (tj) wrote :

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.

Changed in bluez (Ubuntu):
status: Triaged → In Progress
assignee: nobody → TJ (tj)
importance: Undecided → High
Changed in linux (Ubuntu):
status: New → In Progress
importance: Undecided → High
assignee: nobody → TJ (tj)
Revision history for this message
TJ (tj) wrote :

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.

Revision history for this message
TJ (tj) wrote :

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()

Revision history for this message
TJ (tj) wrote :

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

Revision history for this message
TJ (tj) wrote :

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')

TJ (tj)
summary: - 15.10: Multiple Bluetooth controllers not found
+ 15.10: BT Command List not created: bluetooth:__hci_req_sync:298: hci1
+ end: err -ETIMEDOUT
Revision history for this message
Simon Fels (morphis) wrote :

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 ...

Revision history for this message
TJ (tj) wrote :

The actual problem is -ETIMEDOUT.

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

Revision history for this message
Daniel van Vugt (vanvugt) wrote :

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.

Changed in bluez (Ubuntu):
status: In Progress → Incomplete
Changed in linux (Ubuntu):
status: In Progress → Incomplete
Changed in bluez (Ubuntu):
assignee: TJ (tj) → nobody
Changed in linux (Ubuntu):
assignee: TJ (tj) → nobody
Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in linux (Ubuntu):
status: Incomplete → Expired
Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in bluez (Ubuntu):
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers