Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Discovery ceasing to deliver results after short time #572

Open
dezi opened this issue Aug 12, 2023 · 6 comments
Open

Discovery ceasing to deliver results after short time #572

dezi opened this issue Aug 12, 2023 · 6 comments

Comments

@dezi
Copy link

dezi commented Aug 12, 2023

Hi

bluetoothctl scan ceases to deliver results after a short time.

As You can see from the log, after deleting discovered devices
after the delete timeout period, no new advertisments are
discovered.

The controller is still in scan mode.

The full log, including a btmon dump at the same time:

scratch_108.txt

As You can see from the btmon log at end, the follwing command is issued:

< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6 #150 [hci0] 58.165001
Extended scan: Disabled (0x00)
Filter duplicates: Disabled (0x00)
Duration: 0 msec (0x0000)
Period: 0.00 sec (0x0000)

which finally terminates scanning...

See the following log:

=======================
gen8705:~$ hcitool
hcitool - HCI Tool ver 5.68

=======================
gen8705:~$ hciconfig -a
hci0: Type: Primary Bus: USB
BD Address: 84:1B:77:E2:ED:5B ACL MTU: 1021:4 SCO MTU: 96:6
UP RUNNING
RX bytes:51544278 acl:255 sco:0 events:1090421 errors:0
TX bytes:1215549 acl:242 sco:0 commands:36940 errors:0
Features: 0xbf 0xfe 0x0f 0xfe 0xdb 0xff 0x7b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH SNIFF
Link mode: PERIPHERAL ACCEPT
Name: 'liesa-gen8705'
Class: 0x6c0104
Service Classes: Rendering, Capturing, Audio, Telephony
Device Class: Computer, Desktop workstation
HCI Version: 5.2 (0xb) Revision: 0x237e
LMP Version: 5.2 (0xb) Subversion: 0x237e
Manufacturer: Intel Corp. (2)

=======================
gen8705:~$ bluetoothctl
Agent registered

[CHG] Controller 84:1B:77:E2:ED:5B Pairable: yes
[bluetooth]# version
Version 5.68
[bluetooth]# scan on
Discovery started
[CHG] Controller 84:1B:77:E2:ED:5B Discovering: yes
[CHG] Device D8:0F:99:31:37:5C RSSI: 0xffffffb4 (-76)
[DEL] Device 76:04:8A:D4:AD:69 76-04-8A-D4-AD-69
[DEL] Device 90:98:77:93:24:F2 Susi's Schlafzimmer
[CHG] Device 08:BF:08:5F:59:93 RSSI: 0xffffffc0 (-64)
[CHG] Device D8:0F:99:31:37:5C RSSI: 0xffffffbf (-65)
[CHG] Device D8:0F:99:31:37:5C TxPower: 0x0007 (7)
[CHG] Device 5D:E1:24:8C:5A:D0 RSSI: 0xffffffc1 (-63)
[CHG] Device 5D:E1:24:8C:5A:D0 TxPower: 0x000c (12)
[CHG] Device 0C:96:E6:27:B7:AC RSSI: 0xffffffac (-84)
[NEW] Device 90:98:77:93:24:F2 Susi's Schlafzimmer
[CHG] Device 0C:96:E6:27:B7:AC TxPower: 0x000a (10)
[NEW] Device FE:F7:54:71:C4:F3 iBKS Plus
[NEW] Device 1C:D6:BE:E3:0B:2A TV
[CHG] Device 90:98:77:93:24:F2 UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Device 90:98:77:93:24:F2 UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Device 90:98:77:93:24:F2 UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Device 90:98:77:93:24:F2 UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Device 90:98:77:93:24:F2 UUIDs: 00000000-0000-0000-0000-000000000000
[NEW] Device 76:04:8A:D4:AD:69 76-04-8A-D4-AD-69
[DEL] Device E4:17:C6:E6:62:A7 iBKS Plus
[NEW] Device ED:EB:1D:74:C3:68 ED-EB-1D-74-C3-68
[NEW] Device E4:17:C6:E6:62:A7 iBKS Plus
[CHG] Device 5D:E1:24:8C:5A:D0 RSSI: 0xffffffb6 (-74)
[CHG] Device 08:BF:08:5F:59:93 RSSI: 0xffffffb6 (-74)
[NEW] Device 84:EB:18:5F:35:AA SANITAS SBF70
[CHG] Device 08:BF:08:5F:59:93 RSSI: 0xffffffae (-82)
[DEL] Device 1C:D6:BE:E3:0B:2A TV
[CHG] Device 5D:E1:24:8C:5A:D0 ManufacturerData Key: 0x004c (76)
[CHG] Device 5D:E1:24:8C:5A:D0 ManufacturerData Value:
10 05 4a 1c c3 1f 65 ..J...e
[CHG] Device FE:F7:54:71:C4:F3 UUIDs: 0000feaa-0000-1000-8000-00805f9b34fb
[CHG] Device FE:F7:54:71:C4:F3 ServiceData Key: 0000feaa-0000-1000-8000-00805f9b34fb
[CHG] Device FE:F7:54:71:C4:F3 ServiceData Value:
10 ef 03 61 63 63 65 6e 74 2d 73 79 73 74 65 6d ...accent-system
73 07 s.
[NEW] Device 1C:D6:BE:E3:0B:2A TV
[DEL] Device 84:EB:18:5F:35:AA SANITAS SBF70
[DEL] Device 08:BF:08:5F:59:93 08-BF-08-5F-59-93
[DEL] Device D8:0F:99:31:37:5C Dezi's Dominator-XL
[DEL] Device 76:04:8A:D4:AD:69 76-04-8A-D4-AD-69
[DEL] Device 5D:E1:24:8C:5A:D0 5D-E1-24-8C-5A-D0
[DEL] Device FE:F7:54:71:C4:F3 iBKS Plus
[DEL] Device 90:98:77:93:24:F2 Susi's Schlafzimmer
[DEL] Device 1C:D6:BE:E3:0B:2A TV
[DEL] Device 0C:96:E6:27:B7:AC Dezi's Gästezimmer groß
[DEL] Device E4:17:C6:E6:62:A7 iBKS Plus
[DEL] Device ED:EB:1D:74:C3:68 ED-EB-1D-74-C3-68
[bluetooth]# scan on
Failed to start discovery: org.bluez.Error.InProgress
[bluetooth]#

=================================
Last few lines from btmon dump:

HCI Event: LE Meta Event (0x3e) plen 26 #149 [hci0] 54.161889
LE Extended Advertising Report (0x0d)
Num reports: 1
Entry 0
Event type: 0x001a
Props: 0x001a
Scannable
Scan response
Use legacy advertising PDUs
Data status: Complete
Legacy PDU Type: SCAN_RSP to an ADV_IND (0x001a)
Address type: Random (0x01)
Address: 62:F1:71:DC:61:EC (Resolvable)
Primary PHY: LE 1M
Secondary PHY: No packets
SID: no ADI field (0xff)
TX power: 127 dBm
RSSI: -91 dBm (0xa5)
Periodic advertising interval: 0.00 msec (0x0000)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Data length: 0x00
@ MGMT Event: Device Found (0x0012) plen 14 {0x0001} [hci0] 54.161980
LE Address: 62:F1:71:DC:61:EC (Resolvable)
RSSI: -91 dBm (0xa5)
Flags: 0x00000004
Not Connectable
Data length: 0
< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6 #150 [hci0] 58.165001
Extended scan: Disabled (0x00)
Filter duplicates: Disabled (0x00)
Duration: 0 msec (0x0000)
Period: 0.00 sec (0x0000)
HCI Event: Inquiry Complete (0x01) plen 1 #151 [hci0] 58.198477
Status: Success (0x00)
HCI Event: Command Complete (0x0e) plen 4 #152 [hci0] 58.205938
LE Set Extended Scan Enable (0x08|0x0042) ncmd 2
Status: Success (0x00)
@dezi dezi mentioned this issue Aug 12, 2023
Open
@dezi
Copy link
Author

dezi commented Aug 12, 2023 •
edited

Additional research:

the Start Discovery MGMT Command is repeated / refreshed every 16 seconds.

If the scan ceases to deliver, also the refresh is outstanding (not executed)

=> search for an error condition where the command is not issued.

The condition must pre pretty stochastic, some times it works for an hour,
sometimes only for a few minutes.

Regards dezi

grep from btmon log:

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 745.832501
Address type: 0x07
BR/EDR
LE Public
LE Random

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 761.831308
Address type: 0x07
BR/EDR
LE Public
LE Random

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 777.828046
Address type: 0x07
BR/EDR
LE Public
LE Random

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 793.830363
Address type: 0x07
BR/EDR
LE Public
LE Random

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 809.830755
Address type: 0x07
BR/EDR
LE Public
LE Random

MGMT Command: Start Discovery (0x0023) plen 1 {0x0001} [hci0] 825.832062
Address type: 0x07
BR/EDR
LE Public
LE Random

@dezi dezi mentioned this issue Aug 12, 2023
Open
@jsmif
Copy link

jsmif commented Sep 2, 2023 •
edited

I have observed something similar which is possibly related.

I am using a Raspberry Pi Zero W, running Raspbian, on which I have compiled and installed Bluetooth 5.66.

I am launching "bluetoothctl scan on > /tmp/btctl.txt" and "btcmon -w /tmp/btmon.log" from a cron job at startup.

If I do only that, the bluetoothctl runs fine basically forever. However, if I add in a script which runs gatttool against observed BLE addresses, bluetoothctl will stop working relatively quickly. The process is still running, it just shows a bunch of [DEL] statements at the end of the log, and then never updates ever again.

FWIW if I run a 2nd "bluetoothctl scan on" command, the results from that end up logging fo the first process' log, so I know it's still running, it's just the scanning has broken for some reason.

I'd appreciate any guidance for what additional info I can provide to help debug this issue.

Edit:
FWIW the Raspberry Pi Zero W is using the following BT chip:

HCI Version: 4.1 (0x7)  Revision: 0x1fc
LMP Version: 4.1 (0x7)  Subversion: 0x2209
Manufacturer: Broadcom Corporation (15)

Which according to this is a Cypress CYW43438. I would note @dezi's log says they're using an Intel chip.

And my btmon log ends with the following:

< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2                                                                                                                                                                              #2223 [hci0] 307.527544
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                                                         #2224 [hci0] 307.529258
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Device Found (0x0012) plen 43                                                                                                                                                                                      {0x0001} [hci0] 307.529332
        LE Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        RSSI: -84 dBm (0xac)
        Flags: 0x00000000
        Data length: 29
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        Service Data: HP Inc. (0xfdf7)
          Data: 01c11a88ce47fc533e0a6585d4e66db4180000000003
< HCI Command: LE Create Connection (0x08|0x000d) plen 25                                                                                                                                                                           #2225 [hci0] 307.530302
        Scan interval: 60.000 msec (0x0060)
        Scan window: 60.000 msec (0x0060)
        Filter policy: Accept list is not used (0x00)
        Peer address type: Public (0x00)
        Peer address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Own address type: Public (0x00)
        Min connection interval: 50.00 msec (0x0028)
        Max connection interval: 70.00 msec (0x0038)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                                                           #2226 [hci0] 307.530906
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                                                                                                                                                                                           #2227 [hci0] 307.634811
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 64
        Role: Central (0x00)
        Peer address type: Public (0x00)
        Peer address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Connection interval: 67.50 msec (0x0036)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Central clock accuracy: 0x00
@ MGMT Event: Device Connected (0x000b) plen 42                                                                                                                                                                                  {0x0001} [hci0] 307.634942
        LE Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Flags: 0x00000008
          Connection Locally Initiated
        Data length: 29
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        Service Data: HP Inc. (0xfdf7)
          Data: 01c11a88ce47fc533e0a6585d4e66db4180000000003
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                                                                                                                                                                    #2228 [hci0] 307.635287
        Handle: 64 Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                                                           #2229 [hci0] 307.640869
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 307.649442
@ RAW Close: btmon                                                                                                                                                                                                                      {0x0002} 307.649485
> HCI Event: LE Meta Event (0x3e) plen 12                                                                                                                                                                                           #2230 [hci0] 308.069275
      LE Read Remote Used Features (0x04)
        Status: Connection Failed to be Established (0x3e)
        Handle: 64 Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Features: 0x1f 0x00 0x00 0x08 0x00 0x00 0x00 0x00
          LE Encryption
          Connection Parameter Request Procedure
          Extended Reject Indication
          Peripheral-initiated Features Exchange
          LE Ping
          Remote Public Key Validation
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                                                      #2231 [hci0] 308.069295
        Status: Success (0x00)
        Handle: 64 Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Reason: Connection Failed to be Established (0x3e)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                                                {0x0001} [hci0] 308.069433
        LE Address: BE:E9:2F:91:24:17  (OUI BE-E9-2F)
        Reason: Unspecified (0x00)
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 561.500977
@ RAW Close: btmon                                                                                                                                                                                                                      {0x0002} 561.501573
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 561.809813
@ RAW Close: btmon                                                                                                                                                                                                                      {0x0002} 561.810391
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 562.772638
@ RAW Close: btmon                                                                                                                                                                                                                      {0x0002} 562.773131
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 563.670339
@ RAW Close: btmon

Perhaps something about connecting to that HP printer is causing a bluetoothctl crash?

@jsmif
Copy link

jsmif commented Sep 3, 2023

After some additional investigation I've found the following:

Status codes:

#define MGMT_STATUS_SUCCESS		0x00
#define MGMT_STATUS_AUTH_FAILED		0x05
#define MGMT_STATUS_DISCONNECTED	0x0e

Normal successful sequence

Sep  3 00:37:48 myPi bluetoothd[642]: src/device.c:device_set_legacy() legacy 0
Sep  3 00:37:53 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x0013
Sep  3 00:37:53 myPi bluetoothd[642]: src/adapter.c:discovering_callback() hci0 type 7 discovering 0 method 0
Sep  3 00:37:53 myPi bluetoothd[642]: src/adapter.c:trigger_start_discovery() 
Sep  3 00:37:53 myPi bluetoothd[642]: src/adapter.c:cancel_passive_scanning() 
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:start_discovery_timeout() 
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:start_discovery_timeout() adapter->current_discovery_filter == 0
Sep  3 00:37:58 myPi bluetoothd[642]: src/shared/mgmt.c:send_request() [0x0000] command 0x0023
Sep  3 00:37:58 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] command 0x0023 complete: 0x00
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:start_discovery_complete() status 0x00
Sep  3 00:37:58 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x0013
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:discovering_callback() hci0 type 7 discovering 1 method 0
Sep  3 00:37:58 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x0012
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:device_found_callback() hci0 addr 11:11:11:11:11:11, rssi -68 flags 0x0000 eir_len 18
Sep  3 00:37:58 myPi bluetoothd[642]: src/device.c:device_set_legacy() legacy 0
Sep  3 00:37:58 myPi bluetoothd[642]: src/device.c:device_set_flags() flags 26
Sep  3 00:37:58 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x0012
Sep  3 00:37:58 myPi bluetoothd[642]: src/adapter.c:device_found_callback() hci0 addr 22:22:22:22:22:22, rssi -54 flags 0x0000 eir_len 40

etc, continuing to discover devices

Failing / final sequence:

Sep  3 00:38:30 myPi bluetoothd[642]: src/device.c:device_set_legacy() legacy 0
Sep  3 00:38:30 myPi bluetoothd[642]: src/device.c:device_set_flags() flags 26
Sep  3 00:38:31 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x000b
Sep  3 00:38:31 myPi bluetoothd[642]: src/adapter.c:connected_callback() hci0 device 11:11:11:11:11:11 connected eir_len 19
Sep  3 00:38:35 myPi kernel: [  214.712142] Bluetooth: hci0: security requested but not available
Sep  3 00:38:35 myPi kernel: [  214.858483] Bluetooth: hci0: security requested but not available
Sep  3 00:38:35 myPi kernel: [  214.956310] Bluetooth: hci0: security requested but not available
Sep  3 00:38:35 myPi kernel: [  215.053879] Bluetooth: hci0: security requested but not available
Sep  3 00:38:39 myPi bluetoothd[642]: src/shared/mgmt.c:can_read_data() [0x0000] event 0x000c
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:dev_disconnected() Device 11:11:11:11:11:11 disconnected, reason 2
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:adapter_remove_connection() 
Sep  3 00:38:39 myPi bluetoothd[642]: plugins/policy.c:disconnect_cb() reason 2
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 11:11:11:11:11:11 type 2 status 0xe
Sep  3 00:38:39 myPi bluetoothd[642]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Sep  3 00:38:39 myPi bluetoothd[642]: src/device.c:device_bonding_failed() status 14 <- I think it's specifically this status which causes the final termination. It seems to handle status 5 gracefully enough?
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:resume_discovery() 
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:trigger_start_discovery() 
Sep  3 00:38:39 myPi bluetoothd[642]: src/adapter.c:cancel_passive_scanning() 
Sep  3 00:38:44 myPi bluetoothd[642]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_22_22_22_22_22_22
Sep  3 00:38:44 myPi bluetoothd[642]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_22_22_22_22_22_22
Sep  3 00:38:44 myPi bluetoothd[642]: src/device.c:device_free() 0x1516d58
Sep  3 00:38:44 myPi bluetoothd[642]: src/adapter.c:start_discovery_timeout() 
Sep  3 00:38:44 myPi bluetoothd[642]: src/adapter.c:start_discovery_timeout() adapter->current_discovery_filter == 0
Sep  3 00:38:45 myPi bluetoothd[642]: src/device.c:device_remove() Removing device /org/bluez/hci0/33_33_33_33_33_33
Sep  3 00:38:45 myPi bluetoothd[642]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/33_33_33_33_33_33
Sep  3 00:38:45 myPi bluetoothd[642]: src/device.c:device_free() 0x1518290

etc tearing everything down, and never resuming again.
This is 100% reproducible for me in quick order, and so based on multiple runs I believe the
src/device.c:device_bonding_failed() status 14 line is the key prelude to failure.

Note: the 11:11:11:11:11:11 above was the last attempted-to-connect-to-via-GATT device, which included some characteristics that couldn't be read w/o auth (because I wasn't authed)

Calling gatt_read_char() with handle 55
Characteristic value/descriptor: iPhone
"GATTPRINT:CHAR_VALUE","random","11:11:11:11:11:11","0x0003","6950686f6e65"
Characteristic value/descriptor: @00 
"GATTPRINT:CHAR_VALUE","random","11:11:11:11:11:11","0x0005","4000"
Characteristic value/descriptor: Apple Inc.
"GATTPRINT:CHAR_VALUE","random","11:11:11:11:11:11","0x000c","4170706c6520496e632e"
Characteristic value/descriptor: iPhone15,3
"GATTPRINT:CHAR_VALUE","random","11:11:11:11:11:11","0x000e","6950686f6e6531352c33"
Characteristic value/descriptor read failed: Attribute requires authentication before read/write
Characteristic value/descriptor read failed: Attribute requires authentication before read/write
Characteristic value/descriptor read failed: Attribute requires authentication before read/write
Characteristic value/descriptor read failed: Attribute requires authentication before read/write
"GATTPRINT:DESCRIPTORS","random","11:11:11:11:11:11","0x0001","00002800-0000-1000-8000-00805f9b34fb"
"GATTPRINT:DESCRIPTORS","random","11:11:11:11:11:11","0x0002","00002803-0000-1000-8000-00805f9b34fb"
"GATTPRINT:DESCRIPTORS","random","11:11:11:11:11:11","0x0003","00002a00-0000-1000-8000-00805f9b34fb"

And the final btmon log looked like:

< ACL Data TX: Handle 64 flags 0x00 dlen 9                                                                                                                                                                                           #578 [hci0] 159.512757
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0033-0xffff
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                                                               #579 [hci0] 159.559690
        Num handles: 1
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 24                                                                                                                                                                                          #580 [hci0] 159.608995
      ATT: Find Information Response (0x05) len 19
        Format: UUID-128 (0x02)
        Handle: 0x0033
        UUID: Vendor specific (2f7cabce-808d-411f-9a0c-bb92ba96c102)
< ACL Data TX: Handle 64 flags 0x00 dlen 9                                                                                                                                                                                           #581 [hci0] 159.610745
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0034-0xffff
> ACL Data RX: Handle 64 flags 0x02 dlen 18                                                                                                                                                                                          #582 [hci0] 159.706115
      ATT: Find Information Response (0x05) len 13
        Format: UUID-16 (0x01)
        Handle: 0x0034
        UUID: Characteristic Extended Properties (0x2900)
        Handle: 0x0035
        UUID: Client Characteristic Configuration (0x2902)
        Handle: 0x0036
        UUID: Characteristic (0x2803)
< ACL Data TX: Handle 64 flags 0x00 dlen 9                                                                                                                                                                                           #583 [hci0] 159.709998
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0037-0xffff
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                                                               #584 [hci0] 159.789021
        Num handles: 1
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Count: 1
> ACL Data RX: Handle 64 flags 0x02 dlen 24                                                                                                                                                                                          #585 [hci0] 159.804035
      ATT: Find Information Response (0x05) len 19
        Format: UUID-128 (0x02)
        Handle: 0x0037
        UUID: Vendor specific (c6b2f38c-23ab-46d8-a6ab-a3a870bbd5d7)
< ACL Data TX: Handle 64 flags 0x00 dlen 9                                                                                                                                                                                           #586 [hci0] 159.804763
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0038-0xffff
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                                                               #587 [hci0] 159.852185
        Num handles: 1
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Count: 2
> ACL Data RX: Handle 64 flags 0x02 dlen 10                                                                                                                                                                                          #588 [hci0] 159.900874
      ATT: Find Information Response (0x05) len 5
        Format: UUID-16 (0x01)
        Handle: 0x0038
        UUID: Characteristic Extended Properties (0x2900)
< ACL Data TX: Handle 64 flags 0x00 dlen 9                                                                                                                                                                                           #589 [hci0] 159.901691
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0039-0xffff
> ACL Data RX: Handle 64 flags 0x02 dlen 9                                                                                                                                                                                           #590 [hci0] 159.998378
      ATT: Error Response (0x01) len 4
        Find Information Request (0x04)
        Handle: 0x0039
        Error: Attribute Not Found (0x0a)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                                                               #591 [hci0] 160.164016
        Num handles: 1
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Count: 1
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                                                                       #592 [hci0] 162.177312
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                                                            #593 [hci0] 162.178179
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                                                       #594 [hci0] 162.192554
        Status: Success (0x00)
        Handle: 64 Address: 11:11:11:11:11:11 (Resolvable)
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                                                {0x0001} [hci0] 162.192672
        LE Address: 11:11:11:11:11:11 (Resolvable)
        Reason: Connection terminated by local host (0x02)
@ RAW Open: btmon (privileged) version 2.22                                                                                                                                                                                             {0x0002} 267.095117
@ RAW Close: btmon

Note the "Device Disconnected" event.

What I'm seeing right now is that on the Raspberry Pi Zero W, bluetoothd seems to not handle failures gracefully at all. The first time it gets a device_bonding_failed(), it ends up just tearing everything down and breaking. In contrast, on a separate Intel based system, I can see these sorts of errors at all the same places (i.e. GATT connections gone awry), but bluetoothd and bluetoothctl keep working normally and discovering devices normally.

Is there some setting which perhaps controls whether bluetoothd handles failures gracefully or not? (Note: both the Raspberry Pi and Intel based system are running BlueZ 5.66 compiled from source and make installed

@jsmif
Copy link

jsmif commented Sep 4, 2023 •
edited

Can confirm this is 100% reproducible on Raspberry Pi Zero W w/ BlueZ 5.68 manually compiled and installed as well.

And I can confirm that per #510, rolling back to an older Raspbian Buster distribution which has a "5.10.103+" kernel allowed my system to scan continuously without error like was happening upon failed connections in the latest Bullseye 6.1.X kernel. (e.g. with the older 5.50 BlueZ). So it seems this is a kernel issue of some sort.

@jsmif jsmif mentioned this issue Sep 4, 2023
Closed
@Vudentz
Copy link
Contributor

Vudentz commented Sep 6, 2023

Looks like a duplicated of #510, try with the following change: bluez/bluetooth-next@52bf4fd

intel-lab-lkp pushed a commit to intel-lab-lkp/linux that referenced this issue Sep 14, 2023
@Vudentz @intel-lab-lkp
Bluetooth: hci_core: Remove le_restart_scan work
782b927 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
@tedd-an tedd-an mentioned this issue Sep 14, 2023
Closed
github-actions bot pushed a commit to tedd-an/bluetooth-next that referenced this issue Sep 14, 2023
@Vudentz @tedd-an
Bluetooth: hci_core: Remove le_restart_scan work
6292eae 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
@BluezTestBot BluezTestBot mentioned this issue Sep 14, 2023
Closed
github-actions bot pushed a commit to BluezTestBot/bluetooth-next that referenced this issue Sep 14, 2023
@Vudentz @tedd-an
Bluetooth: hci_core: Remove le_restart_scan work
3c759bb 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
@BluezTestBot BluezTestBot mentioned this issue Nov 22, 2023
Closed
github-actions bot pushed a commit to BluezTestBot/bluetooth-next that referenced this issue Nov 22, 2023
@Vudentz @tedd-an
Bluetooth: hci_core: Remove le_restart_scan work
f651577 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
@tedd-an tedd-an mentioned this issue Nov 22, 2023
Closed
github-actions bot pushed a commit to tedd-an/bluetooth-next that referenced this issue Nov 22, 2023
@Vudentz @tedd-an
Bluetooth: hci_core: Remove le_restart_scan work
c1dd49a 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
intel-lab-lkp pushed a commit to intel-lab-lkp/linux that referenced this issue Nov 23, 2023
@Vudentz @intel-lab-lkp
Bluetooth: hci_core: Remove le_restart_scan work
abe38c2 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
BluezTestBot pushed a commit to bluez/bluetooth-next that referenced this issue Nov 27, 2023
@Vudentz
Bluetooth: hci_core: Remove le_restart_scan work
a4230d1 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
srcres258 pushed a commit to srcres258/linux-doc that referenced this issue Dec 18, 2023
@Vudentz
Bluetooth: hci_core: Remove le_restart_scan work
eb75ebe 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
BluezTestBot pushed a commit to bluez/bluetooth-next that referenced this issue Dec 19, 2023
@Vudentz
Bluetooth: hci_core: Remove le_restart_scan work
382bfbc 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
BluezTestBot pushed a commit to bluez/bluetooth-next that referenced this issue Dec 22, 2023
@Vudentz
Bluetooth: hci_core: Remove le_restart_scan work
78db544 
This removes le_restart_scan work and instead just disables controller
duplicate filtering when discovery result_filtering is enabled and
HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

Link: bluez/bluez#573
Link: bluez/bluez#572
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
@asterwyx
Copy link

I've also met a similar problem. When I run bluetoothctl scan on and try to connect to one found device in other desktop clients. (For example, add Bluetooth device in plasma's settings, just start pairing but never pair them, waiting for the process to timeout.) All devices are removed according to bluetoothctl's log except for the connecting one. I can only see the connecting one in bluetoothctl devices.

bella485 pushed a commit to bella485/centos-stream-9 that referenced this issue May 1, 2024
@damarlin
Bluetooth: hci_core: Remove le_restart_scan work
1196eea 
JIRA: https://issues.redhat.com/browse/RHEL-30099

commit 78db544b5d276b70c6ea2c2909ffed96b10229a3
Author: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Date:   Wed Sep 6 14:13:35 2023 -0700

    Bluetooth: hci_core: Remove le_restart_scan work

    This removes le_restart_scan work and instead just disables controller
    duplicate filtering when discovery result_filtering is enabled and
    HCI_QUIRK_STRICT_DUPLICATE_FILTER is set.

    Link: bluez/bluez#573
    Link: bluez/bluez#572
    Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

Signed-off-by: David Marlin <dmarlin@redhat.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dezi @Vudentz @asterwyx @jsmif