bluez / bluez

Main BlueZ tree
https://bluez.github.io/bluez/
GNU General Public License v2.0
711 stars 267 forks source link

No GATT services for concurrent connections #195

Open ArneJoris opened 3 years ago

ArneJoris commented 3 years ago

When the central connects to a single peripheral, GATT services are resolved after a few seconds.

Found 1 peripherals: C2:5C:77:29:83:FE. Connected to device C2:5C:77:29:83:FE. Device C2:5C:77:29:83:FE GATT resolved: False Device C2:5C:77:29:83:FE GATT resolved: True Device C2:5C:77:29:83:FE GATT resolved: True Device C2:5C:77:29:83:FE GATT resolved: True Device C2:5C:77:29:83:FE GATT resolved: True

When the central connects to two peripherals, the GATT services of the most recently connected peripheral are resolved for just a few seconds.:

Found 2 peripherals: EE:EF:2A:24:D6:A1,E1:FC:EC:71:0C:9A. Connected to device EE:EF:2A:24:D6:A1. Connected to device E1:FC:EC:71:0C:9A. Device EE:EF:2A:24:D6:A1 GATT resolved: False Device E1:FC:EC:71:0C:9A GATT resolved: True Device EE:EF:2A:24:D6:A1 GATT resolved: False Device E1:FC:EC:71:0C:9A GATT resolved: False Device EE:EF:2A:24:D6:A1 GATT resolved: False Device E1:FC:EC:71:0C:9A GATT resolved: False

This has been repeated on bluez-5.58, bluez-5.60, bluez-5.61 and bluez-5.51. Cache = always, or Cache = no seems to make no difference.

Bluetoothd -nEd output:

bluetoothd[9284]: src/adapter.c:connected_callback() hci0 device EE:EF:2A:24:D6:A1 connected eir_len 0
bluetoothd[9284]: attrib/gattrib.c:g_attrib_ref() 0x228668: g_attrib_ref=1
bluetoothd[9284]: src/device.c:load_gatt_db() Restoring EE:EF:2A:24:D6:A1 gatt database from file
bluetoothd[9284]: No cache for EE:EF:2A:24:D6:A1
bluetoothd[9284]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
bluetoothd[9284]: src/device.c:btd_device_set_temporary() temporary 0
bluetoothd[9284]: src/device.c:device_connect_le() Connection attempt to: E1:FC:EC:71:0C:9A
bluetoothd[9284]: src/adapter.c:connected_callback() hci0 device E1:FC:EC:71:0C:9A connected eir_len 0
bluetoothd[9284]: attrib/gattrib.c:g_attrib_ref() 0x222250: g_attrib_ref=1
bluetoothd[9284]: src/device.c:load_gatt_db() Restoring E1:FC:EC:71:0C:9A gatt database from file
bluetoothd[9284]: No cache for E1:FC:EC:71:0C:9A
bluetoothd[9284]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
bluetoothd[9284]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 100
bluetoothd[9284]: src/device.c:gatt_debug() MTU Exchange failed. ATT ECODE: 0x00
bluetoothd[9284]: src/device.c:gatt_client_ready_cb() status: failed, error: 0
bluetoothd[9284]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_E1_FC_EC_71_0C_9A err -5
bluetoothd[9284]: src/device.c:att_disconnected_cb()
bluetoothd[9284]: src/device.c:att_disconnected_cb() Success (0)
bluetoothd[9284]: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up.

Btmon output on the central when connecting to two peripherals:

< HCI Command: LE Extended Create Connection (0x08|0x0043) plen 26                                                                                                                                     #97 [hci0] 2021-08-26 16:46:30.151169
        Filter policy: White list is not used (0x00)
        Own address type: Random (0x01)
        Peer address type: Random (0x01)
        Peer address: EE:EF:2A:24:D6:A1 (Static)
        Initiating PHYs: 0x04
        Entry 0: LE Coded
          Scan interval: 60.000 msec (0x0060)
          Scan window: 60.000 msec (0x0060)
          Min connection interval: 30.00 msec (0x0018)
          Max connection interval: 50.00 msec (0x0028)
          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                                                                                                                                                              #98 [hci0] 2021-08-26 16:46:30.153098
      LE Extended Create Connection (0x08|0x0043) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                                                                                                                                                              #99 [hci0] 2021-08-26 16:46:30.492085
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: EE:EF:2A:24:D6:A1 (Static)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x05
@ MGMT Event: Device Connected (0x000b) plen 13                                                                                                                                                   {0x0001} [hci0] 2021-08-26 16:46:30.492150
        LE Address: EE:EF:2A:24:D6:A1 (Static)
        Flags: 0x00000000
        Data length: 0
@ MGMT Event: Device Connected (0x000b) plen 13                                                                                                                                                   {0x0002} [hci0] 2021-08-26 16:46:30.492150
        LE Address: EE:EF:2A:24:D6:A1 (Static)
        Flags: 0x00000000
        Data length: 0
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                                                                                                                                      #100 [hci0] 2021-08-26 16:46:30.492407
        Handle: 0
> HCI Event: LE Meta Event (0x3e) plen 4                                                                                                                                                              #101 [hci0] 2021-08-26 16:46:30.493087
      LE Channel Selection Algorithm (0x14)
        Handle: 0
        Algorithm: #2 (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                             #102 [hci0] 2021-08-26 16:46:[120/2394]      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12                                                                                                                                                             #103 [hci0] 2021-08-26 16:46:30.596111
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 0
        Features: 0xbf 0x58 0x01 0x00 0x00 0x00 0x00 0x00
          LE Encryption
          Connection Parameter Request Procedure
          Extended Reject Indication
          Slave-initiated Features Exchange
          LE Ping
          LE Data Packet Length Extension
          Extended Scanner Filter Policies
          LE Coded PHY
          LE Extended Advertising
          Channel Selection Algorithm #2
          Minimum Number of Used Channels Procedure
= bluetoothd: No cache for EE:EF:2A:24:D6:A1                                                                                                                                                                      2021-08-26 16:46:30.600352
< ACL Data TX: Handle 0 flags 0x00 dlen 7                                                                                                                                                             #104 [hci0] 2021-08-26 16:46:30.597915
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
< HCI Command: LE Set Extended Scan Parameters (0x08|0x0041) plen 8                                                                                                                                   #105 [hci0] 2021-08-26 16:46:30.612805
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement (0x00)
        PHYs: 0x04
        Entry 0: LE Coded
          Type: Passive (0x00)
          Interval: 60.000 msec (0x0060)
          Window: 60.000 msec (0x0060)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                           #106 [hci0] 2021-08-26 16:46:30.614082
      LE Set Extended Scan Parameters (0x08|0x0041) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6                                                                                                                                       #107 [hci0] 2021-08-26 16:46:30.614188
        Extended scan: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
        Duration: 0 msec (0x0000)
        Period: 0.00 sec (0x0000)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                           #108 [hci0] 2021-08-26 16:46:30.615111
      LE Set Extended Scan Enable (0x08|0x0042) ncmd 1
        Status: Success (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                                #109 [hci0] 2021-08-26 16:46:30.746076
        Num handles: 1
        Handle: 0
        Count: 1
> ACL Data RX: Handle 0 flags 0x02 dlen 7                                                                                                                                                             #110 [hci0] 2021-08-26 16:46:30.747062
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 100
> HCI Event: LE Meta Event (0x3e) plen 86                                                                                                                                                             #111 [hci0] 2021-08-26 16:46:30.802069
      LE Extended Advertising Report (0x0d)
        Num reports: 1
        Entry 0
          Event type: 0x0001
            Props: 0x0001
              Connectable
            Data status: Complete
          Address type: Random (0x01)
          Address: E1:FC:EC:71:0C:9A (Static)
          Primary PHY: LE Coded
          Secondary PHY: LE Coded
          SID: 0x0a
          TX power: 127 dBm
          RSSI: -57 dBm (0xc7)
          Periodic advertising invteral: 0.00 msec (0x0000)
          Direct address type: Public (0x00)
          Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
          Data length: 0x3c
        02 01 06 07 03 0a 18 0f 18 10 30 11 07 94 9a 42  ..........0....B
        5a 03 cf 21 ae 82 4b 6b eb 01 30 70 b4 0f ff 99  Z..!..Kk..0p....
        99 31 31 31 31 31 31 31 31 31 31 31 31 0e 09 46  .111111111111..F
        32 32 32 33 33 33 34 34 34 35 35 35              222333444555
< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6                                                                                                                                       #112 [hci0] 2021-08-26 16:46:30.802184
        Extended scan: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
        Duration: 0 msec (0x0000)
        Period: 0.00 sec (0x0000)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                           #113 [hci0] 2021-08-26 16:46:30.803074
      LE Set Extended Scan Enable (0x08|0x0042) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Extended Create Connection (0x08|0x0043) plen 26                                                                                                                                    #114 [hci0] 2021-08-26 16:46:30.803162
        Filter policy: White list is not used (0x00)
        Own address type: Random (0x01)
        Peer address type: Random (0x01)
        Peer address: E1:FC:EC:71:0C:9A (Static)
        Initiating PHYs: 0x04
        Entry 0: LE Coded
          Scan interval: 60.000 msec (0x0060)
          Scan window: 60.000 msec (0x0060)
          Min connection interval: 30.00 msec (0x0018)
          Max connection interval: 50.00 msec (0x0028)
          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                                                                                                                                                             #115 [hci0] 2021-08-26 16:46:30.805075
      LE Extended Create Connection (0x08|0x0043) ncmd 1
        Status: Success (0x00)
> ACL Data RX: Handle 0 flags 0x02 dlen 7                                                                                                                                                             #116 [hci0] 2021-08-26 16:46:30.845211
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 100
> HCI Event: LE Meta Event (0x3e) plen 19                                                                                                                                                             #117 [hci0] 2021-08-26 16:46:30.975075
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 1
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: E1:FC:EC:71:0C:9A (Static)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x05
@ MGMT Event: Device Connected (0x000b) plen 13                                                                                                                                                   {0x0001} [hci0] 2021-08-26 16:46:30.975142
        LE Address: E1:FC:EC:71:0C:9A (Static)
        Flags: 0x00000000
        Data length: 0
@ MGMT Event: Device Connected (0x000b) plen 13                                                                                                                                                   {0x0002} [hci0] 2021-08-26 16:46:30.975142
        LE Address: E1:FC:EC:71:0C:9A (Static)
        Flags: 0x00000000
        Data length: 0
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                                                                                                                                      #118 [hci0] 2021-08-26 16:46:30.975384
        Handle: 1
> HCI Event: LE Meta Event (0x3e) plen 4                                                                                                                                                              #119 [hci0] 2021-08-26 16:46:30.976077
      LE Channel Selection Algorithm (0x14)
        Handle: 1
        Algorithm: #2 (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                             #120 [hci0] 2021-08-26 16:46:30.977075
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12                                                                                                                                                             #121 [hci0] 2021-08-26 16:46:31.067076
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 1
        Features: 0xbf 0x58 0x01 0x00 0x00 0x00 0x00 0x00
          LE Encryption
          Connection Parameter Request Procedure
          Extended Reject Indication
          Slave-initiated Features Exchange
          LE Ping
          LE Data Packet Length Extension
          Extended Scanner Filter Policies
          LE Coded PHY
          LE Extended Advertising
          Channel Selection Algorithm #2
          Minimum Number of Used Channels Procedure
= bluetoothd: No cache for E1:FC:EC:71:0C:9A                                                                                                                                                                      2021-08-26 16:46:31.070092
> ACL Data RX: Handle 1 flags 0x02 dlen 7                                                                                                                                                             #122 [hci0] 2021-08-26 16:46:31.165553
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 100
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                                        #123 [hci0] 2021-08-26 16:46:33.128819
        Handle: 1
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                             #124 [hci0] 2021-08-26 16:46:33.130043
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                        #125 [hci0] 2021-08-26 16:46:33.166075
        Status: Success (0x00)
        Handle: 1
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                 {0x0001} [hci0] 2021-08-26 16:46:33.166136
        LE Address: E1:FC:EC:71:0C:9A (Static)
        Reason: Connection terminated by local host (0x02)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                 {0x0002} [hci0] 2021-08-26 16:46:33.166136
        LE Address: E1:FC:EC:71:0C:9A (Static)
        Reason: Connection terminated by local host (0x02)
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                                        #126 [hci0] 2021-08-26 16:47:02.648831
        Handle: 0
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                             #127 [hci0] 2021-08-26 16:47:02.650620
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                        #128 [hci0] 2021-08-26 16:47:02.693650
        Status: Success (0x00)
        Handle: 0
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                 {0x0001} [hci0] 2021-08-26 16:47:02.693714
        LE Address: EE:EF:2A:24:D6:A1 (Static)
        Reason: Connection terminated by local host (0x02)
@ MGMT Event: Device Disconnected (0x000c) plen 8                                                                                                                                                 {0x0002} [hci0] 2021-08-26 16:47:02.693714
        LE Address: EE:EF:2A:24:D6:A1 (Static)
        Reason: Connection terminated by local host (0x02)
ArneJoris commented 3 years ago

Python script for central to repeat this:

from bluezero import device, GATT, adapter
import time

dongle = list(adapter.Adapter.available())[0]
dongle.powered = False
dongle.powered = True

peripherals = []

def deviceFound(dev):
    if dev.address not in peripherals:
        peripherals.append(dev.address)

dongle.on_device_found = deviceFound
dongle.nearby_discovery(timeout=5)

adapterAddress=dongle.address

def connect(deviceAddress):
    d = device.Device(adapterAddress, deviceAddress)
    d.connect(timeout=30)
    print("Connected to device %s." %deviceAddress)

def disconnect(deviceAddress):
    d = device.Device(adapterAddress, deviceAddress)
    d.disconnect()
    print("Disconnected from device %s." %deviceAddress)

def gattResolved(deviceAddress):
    c = GATT.Characteristic(adapterAddress, deviceAddress, "b4703001-eb6b-4b82-ae21-cf035a429a94", "b4703002-eb6b-4b82-ae21-cf035a429a94")
    return c.resolve_gatt()

while True:
    print("Found %d perihperals: %s." %(len(peripherals), ",".join(peripherals)))
    for p in peripherals:
        connect(p)

    for i in range(0,5):
        for address in peripherals:
            print("Device %s GATT resolved: %s" %(address, gattResolved(address)))
        time.sleep(5)

    for p in peripherals:
        disconnect(p)

    for i in range(0,2):
        for address in peripherals:
            print("Device %s GATT resolved: %s" %(address, gattResolved(address)))
        time.sleep(5)
ArneJoris commented 3 years ago

Seems like there is a timing hole; if I wait 3 seconds between connecting to the 2 devices, everything works fine:

Found 2 peripherals: E1:FC:EC:71:0C:9A,EE:EF:2A:24:D6:A1. Connected to device E1:FC:EC:71:0C:9A. Connected to device EE:EF:2A:24:D6:A1. Device E1:FC:EC:71:0C:9A GATT resolved: True Device EE:EF:2A:24:D6:A1 GATT resolved: True Device E1:FC:EC:71:0C:9A GATT resolved: True Device EE:EF:2A:24:D6:A1 GATT resolved: True Device E1:FC:EC:71:0C:9A GATT resolved: True Device EE:EF:2A:24:D6:A1 GATT resolved: True Device E1:FC:EC:71:0C:9A GATT resolved: True Device EE:EF:2A:24:D6:A1 GATT resolved: True

Vudentz commented 3 years ago

Yep, I suspect following line is the problem:

https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/tree/net/bluetooth/hci_event.c#n5234

It doesn't actually check what device has connected instead it attempts to lookup the first one pending so which in case there are multiple can cause the wrong object to be used. If you do serialize that should work though, but we will need to fix this in the long term, so we either block or lookup by peer address.

ArneJoris commented 3 years ago

Thanks @Vudentz , le_conn_complete_evt() not using its bdaddr argument to find the pending connection but instead taking the first pending connection on the controller does explain this problem.

I've got several async threads all creating connections. To work around this, I should probably centralize the connection establishment and only initiate one connection at a time and wait for it to succeed (or fail) before making the next connection.

Vudentz commented 3 years ago

@ArneJoris I will attempt to fix this in the kernel but if you don't control it you might as well have to do the work around anyway otherwise it would work with newer kernels were this issue was fixed.