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