Software versions:
Kernel v5.4.199 with patch "Bluetooth: hci_event: Ignore multiple conn complete events" from Soenke Huster.
Bluez 5.64
After running multiple concurrent connect/info/disconnect/remove cycles while scan is turned on (all done with bluetoothctl), scan eventually stops working, and it is no longer possible to turn scan on or off. The show command indicates that the device is still scanning, and the state cannot be changed.
The scan was turned on with "scan le" in bluetoothctl. bluetoothctl was also used to connect to the endpoint devices.
In the bluetoothd log, there are messages like this:
update_discovery_filter() filters were equal, deciding to not restart the scan.
This message does not occur when the test is running normally.
Here is the tail end of btmon which halts after the problem occurs:
@ MGMT Command: S.. (0x0024) plen 1 {0x0001} [hci0] 2022-06-24 18:17:12.624762
Address type: 0x06
LE Public
LE Random
< HCI Command:.. (0x08|0x000c) plen 2 #24633 [hci0] 2022-06-24 18:17:12.627487
Scanning: Disabled (0x00)
Filter duplicates: Disabled (0x00)
> HCI Event: Command... (0x0e) plen 4 #24634 [hci0] 2022-06-24 18:17:12.629378
LE Set Scan Enable (0x08|0x000c) ncmd 1
Status: Success (0x00)
@ MGMT Event: Dis.. (0x0013) plen 2 {0x0001} [hci0] 2022-06-24 18:17:12.629839
Address type: 0x06
LE Public
LE Random
Discovery: Disabled (0x00)
< HCI Command:.. (0x08|0x0005) plen 6 #24635 [hci0] 2022-06-24 18:17:12.630071
Address: C8:8E:7B:1E:9A:58 (Static)
> HCI Event: LE Meta.. (0x3e) plen 43 #24636 [hci0] 2022-06-24 18:17:12.630361
LE Advertising Report (0x02)
Num reports: 1
Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Address type: Random (0x01)
Address: 34:42:82:95:CB:3D (Non-Resolvable)
Data length: 31
Company: Microsoft (6)
Data: 01092002f69644aca805d759f0b1220b44947a78f52828a5ba9387
RSSI: -58 dBm (0xc6)
> HCI Event: Command... (0x0e) plen 4 #24637 [hci0] 2022-06-24 18:17:12.631360
LE Set Random Address (0x08|0x0005) ncmd 1
Status: Success (0x00)
< HCI Command:.. (0x08|0x000b) plen 7 #24638 [hci0] 2022-06-24 18:17:12.631790
Type: Passive (0x00)
Interval: 60.000 msec (0x0060)
Window: 30.000 msec (0x0030)
Own address type: Random (0x01)
Filter policy: Ignore not in accept list (0x01)
> HCI Event: Command... (0x0e) plen 4 #24639 [hci0] 2022-06-24 18:17:12.633365
LE Set Scan Parameters (0x08|0x000b) ncmd 1
Status: Success (0x00)
< HCI Command:.. (0x08|0x000c) plen 2 #24640 [hci0] 2022-06-24 18:17:12.633787
Scanning: Enabled (0x01)
Filter duplicates: Enabled (0x01)
> HCI Event: Command... (0x0e) plen 4 #24641 [hci0] 2022-06-24 18:17:12.635411
LE Set Scan Enable (0x08|0x000c) ncmd 1
Status: Success (0x00)
Here is the bluetoothd debug output near the time when the error first occurs:
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_C8_7B_FB_0E_8C_BC
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_C8_7B_FB_0E_8C_BC
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_free() 0xc09df0
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:start_discovery() sender :1.9921
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter()
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_filter_to_mgmt_cp()
Jun 24 18:17:36 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter() filters were equal, deciding to not restart the scan.
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_C6_F9_1C_2E_EA_E1
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_C6_F9_1C_2E_EA_E1
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_free() 0xc0aed8
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_C9_47_35_4D_C3_EC
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_C9_47_35_4D_C3_EC
Jun 24 18:17:39 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_free() 0xc1a218
Jun 24 18:17:42 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_D3_87_9A_19_E7_BE
Jun 24 18:17:42 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_D3_87_9A_19_E7_BE
Jun 24 18:17:42 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/device.c:device_free() 0xc5ae88
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_disconnect() owner :1.9921
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_remove() owner :1.9921
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_free() 0xc1b130
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter()
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_filter_to_mgmt_cp()
Jun 24 18:17:46 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter() filters were equal, deciding to not restart the scan.
Jun 24 18:18:10 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:start_discovery() sender :1.9922
Jun 24 18:18:10 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter()
Jun 24 18:18:10 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:discovery_filter_to_mgmt_cp()
Jun 24 18:18:10 ecc8 daemon.debug bluetoothd[28264]: ../bluez-5.64/src/adapter.c:update_discovery_filter() filters were equal, deciding to not restart the scan.
Any suggestions for further analysis would be appreciated.
John Klug
