hci_usb, zephyr and bluez

[john23094]

Hi, 

There seems to be an issue somewhere between the hci_usb sample, zephyr, and bluez on linux. It's really easy to recreate the issue for me:

• Flash an nrf52840 dongle with the hci_usb sample
• flash any nordic board with a ble sample like I have peripheral hr
• connect dongle to linux host, using bluetoothctl scan and connect to the nordic board
• Using btmon to log the initial connection, when there is NO cache (the linux host has NEVER connected to this board before), I can see it gets to the MTU negotiation and then times out, and disconnects

On second attempt the connection always succeeds, and then further connection attemps always do succeed,  but if I delete the bluetooth cache from /var/lib/bluetooth/ and reconnect, the same issue occurs on the first connection attempt. I'm not sure where exactly the issue lays but with those exact steps I'm able to recreate it constantly. Here is the btmon log when I connect to the device:

< HCI Command: LE Set Random Address (0x08|0x0005) plen 6                                                                                                   #174 [hci0] 13.870590
        Address: E2:25:60:FB:F0:A7 (Static)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                 #175 [hci0] 13.877470
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Add Device To Accept List (0x08|0x0011) plen 7                                                                                            #176 [hci0] 13.878615
        Address type: Random (0x01)
        Address: E4:05:AA:E4:7B:4E (Static)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                 #177 [hci0] 13.880710
      LE Add Device To Accept List (0x08|0x0011) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7                                                                                                  #178 [hci0] 13.881419
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 60.000 msec (0x0060)
        Own address type: Random (0x01)
        Filter policy: Ignore not in accept list (0x01)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                 #179 [hci0] 13.883711
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2                                                                                                      #180 [hci0] 13.883755
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                 #181 [hci0] 13.885864
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 23                                                                                                                   #182 [hci0] 13.945714
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: E4:05:AA:E4:7B:4E (Static)
        Data length: 11
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 3 entries
          Heart Rate (0x180d)
          Battery Service (0x180f)
          Device Information (0x180a)
        RSSI: -51 dBm (0xcd)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2                                                                                                      #183 [hci0] 13.945976
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                 #184 [hci0] 13.948713
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25                                                                                                   #185 [hci0] 13.948957
        Scan interval: 60.000 msec (0x0060)
        Scan window: 60.000 msec (0x0060)
        Filter policy: Accept list is not used (0x00)
        Peer address type: Random (0x01)
        Peer address: E4:05:AA:E4:7B:4E (Static)
        Own address type: Random (0x01)
        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                                                                                                                   #186 [hci0] 13.952002
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 31                                                                                                                   #187 [hci0] 14.062627
      LE Enhanced Connection Complete (0x0a)
        Status: Success (0x00)
        Handle: 0
        Role: Central (0x00)
        Peer address type: Random (0x01)
        Peer address: E4:05:AA:E4:7B:4E (Static)
        Local resolvable private address: 00:00:00:00:00:00 (Non-Resolvable)
        Peer resolvable private address: 00:00:00:00:00:00 (Non-Resolvable)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Central clock accuracy: 0x00
@ MGMT Event: Device Connected (0x000b) plen 24                                                                                                         {0x0001} [hci0] 14.062729
        LE Address: E4:05:AA:E4:7B:4E (Static)
        Flags: 0x00000008
          Connection Locally Initiated
        Data length: 11
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 3 entries
          Heart Rate (0x180d)
          Battery Service (0x180f)
          Device Information (0x180a)
> HCI Event: LE Meta Event (0x3e) plen 4                                                                                                                    #188 [hci0] 14.064959
      LE Channel Selection Algorithm (0x14)
        Handle: 0
        Algorithm: #2 (0x01)
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                                                                                            #189 [hci0] 14.081529
        Handle: 0
> HCI Event: Command Status (0x0f) plen 4                                                                                                                   #190 [hci0] 14.085101
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 11                                                                                                                   #191 [hci0] 14.280425
      LE Data Length Change (0x07)
        Handle: 0
        Max TX octets: 27
        Max TX time: 2120
        Max RX octets: 27
        Max RX time: 2120
> HCI Event: LE Meta Event (0x3e) plen 12                                                                                                                   #192 [hci0] 14.334617
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 0
        Features: 0x2d 0x41 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
          Extended Reject Indication
          Peripheral-initiated Features Exchange
          LE Data Packet Length Extension
          LE 2M PHY
          Channel Selection Algorithm #2
= bluetoothd: src/device.c:load_gatt_db() No cache for E4:05:AA:E4:7B:4E                                                                                                14.336637
< ACL Data TX: Handle 0 flags 0x00 dlen 7                                                                                                                   #193 [hci0] 14.337850
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                      #194 [hci0] 14.388916
        Num handles: 1
        Handle: 0
        Count: 1

On the sniffer, we see basically the same thing, after that last message, there is just EMPTY PDU's until the connection times out

Edit: For comparison, here is me connecting to the same nrf52 peripheral from my galaxy S23 and connection succeeds first time:

[Kenneth]

Can you share the actual logs? Also it would be good to look at the second connection that works, to compare if there is any difference between the first and second in regards to the sequence up until it stops.

Kenneth

[john23094]

Sure, you mean the wireshark logs? here they are for both scenarios, linux host and bluez vs galaxy S23

sucessful connect with s23.pcapng

failed conect bluez.pcapng

[Kenneth]

Thank you for this, but you write that the second time you connect with bluez it works, so I would like to get the sniffer log for that one also. I want to understand the difference between first and second attempt.

Kenneth

[john23094]

Ah sorry - I see what you mean, here is the logs from when bluez connects and succeeds on the 2nd attempt. From what I can see it looks the same, but just continues immediately to read the GATT table, at least from what I understand.

I'm still completely unsure why this is the case, it seems like some kind of state machine issue, but I'm struggling to find the culprit, is it zephyr, bluez or the hci_usb dongle

successful connect bluez on 2nd attempt.pcapng

[Kenneth]

The only difference is the sequence of the two first packets, ref:

Out of curiosity, if you on the peripheral side disable the auto length update procedure, does this make any difference?

E.g. try CONFIG_BT_AUTO_DATA_LEN_UPDATE=n on the peripheral. This test may narrow down a bit the issue.

Kenneth