google / bumble

Apache License 2.0
255 stars 73 forks source link

Bumble stops working on Android when having (too?) many characteristics #202

Closed eliaslecomte closed 1 year ago

eliaslecomte commented 1 year ago

Hi,

We are using this great project with a Nordic nRF52840 dongle. However we notice that when having many characteristics, it stops working for (some) Android devices.

I have added about 170 (notifiable) characteristics and while I initially have no errors when starting the python code, bonding is never triggered and bluetooth connection times out.

Any idea what is going on, and if I could solve this?

barbibulle commented 1 year ago

Hi. I which direction is the connection? (Phone to dongle or dongle to phone?). Do you observe a disconnection after the timeout, or are things just stuck? If you can post a log of the HCI packet exchange (setting BUMBLE_LOGLEVEL=DEBUG) that may tell us what’s going on.

eliaslecomte commented 1 year ago

Hi there, thanks for the quick reply and help offered!

The smartphone connects to the nrf stick. The services and characteristics simulate an IoT device.

This is my log on startup:

Descriptor(handle=0x0217, type=UUID-16:2902 (Client Characteristic Configuration), value=)
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_RESET_COMMAND
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_RESET_COMMAND
  return_parameters:       HCI_SUCCESS

<< removed some logs here>>

DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_LE_SET_ADVERTISING_DATA_COMMAND
  return_parameters:       HCI_SUCCESS
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_LE_SET_SCAN_RESPONSE_DATA_COMMAND:
  scan_response_data: 
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_LE_SET_SCAN_RESPONSE_DATA_COMMAND
  return_parameters:       HCI_SUCCESS
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_LE_SET_ADVERTISING_PARAMETERS_COMMAND:
  advertising_interval_min:  100
  advertising_interval_max:  100
  advertising_type:          ADV_IND
  own_address_type:          RANDOM
  peer_address_type:         PUBLIC_DEVICE_ADDRESS
  peer_address:              00:00:00:00:00:00
  advertising_channel_map:   7
  advertising_filter_policy: 0
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_LE_SET_ADVERTISING_PARAMETERS_COMMAND
  return_parameters:       HCI_SUCCESS
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_LE_SET_ADVERTISING_ENABLE_COMMAND:
  advertising_enable: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_LE_SET_ADVERTISING_ENABLE_COMMAND
  return_parameters:       HCI_SUCCESS

On the Android smartphone I get an unexpected error during connect (so even before bonding):

[useBluetoothConnect] error during connect() {"aborted": false, "error": [BleError: Device F1:F2:F2:F3:F5:F9 was disconnected]}

And most often I see no logs in my python terminal 😢.

eliaslecomte commented 1 year ago

When connecting an iOS device, it does work but as I have added so many characteristics, the log is quite long 🙈:

DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_LE_ENHANCED_CONNECTION_COMPLETE_EVENT:
  status:                           HCI_SUCCESS
  connection_handle:                0
  role:                             PERIPHERAL
  peer_address_type:                RANDOM_DEVICE_ADDRESS
  peer_address:                     7B:DA:54:C9:70:03
  local_resolvable_private_address: 00:00:00:00:00:00/P
  peer_resolvable_private_address:  00:00:00:00:00:00/P
  connection_interval:              24
  peripheral_latency:               0
  supervision_timeout:              72
  central_clock_accuracy:           1
DEBUG:bumble.host:### LE CONNECTION: [0x0000] 7B:DA:54:C9:70:03 as PERIPHERAL
DEBUG:bumble.device:*** Connection: [0x0000] 7B:DA:54:C9:70:03 PERIPHERAL
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_LE_READ_PHY_COMMAND:
  connection_handle: 0
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 1
  command_opcode:          HCI_LE_READ_PHY_COMMAND
  return_parameters:       
    status:            HCI_SUCCESS
    connection_handle: 0
    tx_phy:            LE 1M
    rx_phy:            LE 1M
=== Connected to Connection(handle=0x0000, role=PERIPHERAL, address=7B:DA:54:C9:70:03)
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_LE_PHY_UPDATE_COMPLETE_EVENT:
  status:            HCI_SUCCESS
  connection_handle: 0
  tx_phy:            LE 2M
  rx_phy:            LE 2M
DEBUG:bumble.device:*** Connection PHY Update: [0x0000] 7B:DA:54:C9:70:03 as PERIPHERAL, ConnectionPHY(tx_phy=2, rx_phy=2)
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_LE_DATA_LENGTH_CHANGE_EVENT:
  connection_handle: 0
  max_tx_octets:     251
  max_tx_time:       328
  max_rx_octets:     27
  max_rx_time:       328
DEBUG:bumble.device:*** Connection Data Length Change: [0x0000] 7B:DA:54:C9:70:03 as PERIPHERAL
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=7, data=03000400027601
DEBUG:bumble.hci:<<< ACL PDU: 03000400027601
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_EXCHANGE_MTU_REQUEST:
  client_rx_mtu: 374
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_EXCHANGE_MTU_RESPONSE:
  server_rx_mtu: 517
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=7, data=03000400030502
DEBUG:bumble.device:*** Connection ATT MTU Update: [0x0000] 7B:DA:54:C9:70:03 as PERIPHERAL, 374
--- Logging error ---
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=07000400100100ffff0028
DEBUG:bumble.hci:<<< ACL PDU: 07000400100100ffff0028
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_BY_GROUP_TYPE_REQUEST:
  starting_handle:      0x0001
  ending_handle:        0xFFFF
  attribute_group_type: UUID-16:2800 (Primary Service)
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_READ_BY_GROUP_TYPE_RESPONSE:
  length:     6
  attributes: 0x0001-0x0005:0018

<< removed some logs here >>

  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=050004000411021102
DEBUG:bumble.hci:<<< ACL PDU: 050004000411021102
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_FIND_INFORMATION_REQUEST:
  starting_handle: 0x0211
  ending_handle:   0x0211
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_FIND_INFORMATION_RESPONSE:
  format:      1
  information: 0x0211:0229
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=10, data=06000400050111020229
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=7, data=030004000a0d02
DEBUG:bumble.hci:<<< ACL PDU: 030004000a0d02
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_REQUEST:
  attribute_handle: 0x020D
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_READ_REQUEST
  attribute_handle_in_error: 0x020D
  error_code:                ATT_INSUFFICIENT_ENCRYPTION_ERROR
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=9, data=05000400010a0d020f
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=070006000104002d100b0b
DEBUG:bumble.hci:<<< ACL PDU: 070006000104002d100b0b
DEBUG:bumble.smp:<<< Received SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_REQUEST_COMMAND:
  io_capability:               SMP_KEYBOARD_DISPLAY_IO_CAPABILITY
  oob_data_flag:               0
  auth_req:                    bonding_flags=1, MITM=1, sc=1, keypress=0, ct2=1
  maximum_encryption_key_size: 16
  initiator_key_distribution:  ENC,ID,LINK
  responder_key_distribution:  ENC,ID,LINK
DEBUG:bumble.smp:pairing method: NUMERIC_COMPARISON
DEBUG:bumble.smp:expecting distributions: ['SMP_Identity_Information_Command', 'SMP_Identity_Address_Information_Command']
***-----------------------------------
*** Pairing starting
***-----------------------------------
DEBUG:bumble.smp:>>> Sending SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_RESPONSE_COMMAND:
  io_capability:               SMP_KEYBOARD_DISPLAY_IO_CAPABILITY
  oob_data_flag:               0
  auth_req:                    bonding_flags=1, MITM=1, sc=1, keypress=0, ct2=0
  maximum_encryption_key_size: 16
  initiator_key_distribution:  ENC,ID
  responder_key_distribution:  ENC,ID
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=0, bc=0, data_total_length=11, data=070006000204000d100303
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=27, data=410006000c732605355d9dd8b7402244815ac0be966e7f36ddbea0
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=1, bc=0, data_total_length=27, data=8cfb30e17e6f5e52bd0f9e6e82ee35bc43641d7e3673395aa30319
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=1, bc=0, data_total_length=15, data=241d93f55b8bfca2c300f148ad0cd4
DEBUG:bumble.hci:<<< ACL PDU: 410006000c732605355d9dd8b7402244815ac0be966e7f36ddbea08cfb30e17e6f5e52bd0f9e6e82ee35bc43641d7e3673395aa30319241d93f55b8bfca2c300f148ad0cd4
DEBUG:bumble.smp:<<< Received SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_PUBLIC_KEY_COMMAND:
  public_key_x: 732605355d9dd8b7402244815ac0be966e7f36ddbea08cfb30e17e6f5e52bd0f
  public_key_y: 9e6e82ee35bc43641d7e3673395aa30319241d93f55b8bfca2c300f148ad0cd4
DEBUG:bumble.smp:DH key: 72262b74fe186ea044eb60d48469fe4e8e82d7937d74fc478f3325b1e1442ca0
DEBUG:bumble.smp:>>> Sending SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_PUBLIC_KEY_COMMAND:
  public_key_x: 815fb3ebccc9286e0b15d152875895b4c34e9a381a46c44a9757dea0fea02c94
  public_key_y: 3033f5fd5f92a5f1b5e9a99ac6c128e420bab57f530f54ae840f06e3c7087284
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=0, bc=0, data_total_length=27, data=410006000c815fb3ebccc9286e0b15d152875895b4c34e9a381a46
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=1, bc=0, data_total_length=27, data=c44a9757dea0fea02c943033f5fd5f92a5f1b5e9a99ac6c128e420
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=1, bc=0, data_total_length=15, data=bab57f530f54ae840f06e3c7087284
DEBUG:bumble.smp:generated random: 81afd5193c8e88336e3f78cb9e0f6bcd
DEBUG:bumble.smp:>>> Sending SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_CONFIRM_COMMAND:
  confirm_value: e6d31f8484089c3f6c48f801bc414ccc
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=0, bc=0, data_total_length=21, data=1100060003e6d31f8484089c3f6c48f801bc414ccc
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=21, data=110006000476a6e87ca5b9b4b46e5c05d7cfbea310
DEBUG:bumble.hci:<<< ACL PDU: 110006000476a6e87ca5b9b4b46e5c05d7cfbea310
DEBUG:bumble.smp:<<< Received SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_RANDOM_COMMAND:
  random_value: 76a6e87ca5b9b4b46e5c05d7cfbea310
DEBUG:bumble.smp:>>> Sending SMP Command on connection [0x0000] 7B:DA:54:C9:70:03: SMP_PAIRING_RANDOM_COMMAND:
  random_value: 81afd5193c8e88336e3f78cb9e0f6bcd
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=6) ACL: handle=0x0000pb=0, bc=0, data_total_length=21, data=110006000481afd5193c8e88336e3f78cb9e0f6bcd
DEBUG:bumble.smp:verification code: 702666
DEBUG:bumble.gatt_client:GATT Request from client: [0x0000] ATT_FIND_BY_TYPE_VALUE_REQUEST:
  starting_handle: 0x0001
  ending_handle:   0xFFFF
  attribute_type:  UUID-16:2800 (Primary Service)
  attribute_value: 0018
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=13, data=09000400060100ffff00280018
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=050004000701000500
DEBUG:bumble.hci:<<< ACL PDU: 050004000701000500
DEBUG:bumble.gatt_client:GATT Response to client: [0x0000] ATT_FIND_BY_TYPE_VALUE_RESPONSE:
  handles_information: 0x0001-0x0005
DEBUG:bumble.gatt_client:GATT Request from client: [0x0000] ATT_FIND_BY_TYPE_VALUE_REQUEST:
  starting_handle: 0x0006
  ending_handle:   0xFFFF
  attribute_type:  UUID-16:2800 (Primary Service)
  attribute_value: 0018
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=13, data=09000400060600ffff00280018
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=05000400010606000a
DEBUG:bumble.hci:<<< ACL PDU: 05000400010606000a
DEBUG:bumble.gatt_client:GATT Response to client: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_FIND_BY_TYPE_VALUE_REQUEST
  attribute_handle_in_error: 0x0006
  error_code:                ATT_ATTRIBUTE_NOT_FOUND_ERROR
DEBUG:bumble.gatt_client:GATT Request from client: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0001
  ending_handle:   0x0005
  attribute_type:  UUID-16:2A00 (Device Name)
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=11, data=070004000801000500002a
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=14, data=0a000400090803006950686f6e65
DEBUG:bumble.hci:<<< ACL PDU: 0a000400090803006950686f6e65
DEBUG:bumble.gatt_client:GATT Response to client: [0x0000] ATT_READ_BY_TYPE_RESPONSE:
  length:     8
  attributes: 0x0003:6950686f6e65
DEBUG:bumble.gatt_client:GATT Request from client: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0004
  ending_handle:   0x0005
  attribute_type:  UUID-16:2A00 (Device Name)
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=11, data=070004000804000500002a
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=05000400010805000a
DEBUG:bumble.hci:<<< ACL PDU: 05000400010805000a
DEBUG:bumble.gatt_client:GATT Response to client: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_READ_BY_TYPE_REQUEST
  attribute_handle_in_error: 0x0005
  error_code:                ATT_ATTRIBUTE_NOT_FOUND_ERROR
###-----------------------------------
### Pairing with iPhone [7B:DA:54:C9:70:03]
###-----------------------------------
>>> Does the other device display 702666? Type `yes`, `y` or nothing and hit enter to accept.
barbibulle commented 1 year ago

The first log, with Android, shows that the virtual device with the Nordic dongle is advertising, waiting for a connection. But there is no connection from the phone at all. On the phone side, can you tell if the phone even finds the device an attempts to connect to it, or does it timeout looking for the device's advertisements?

eliaslecomte commented 1 year ago

It does find it and when I try to connect it times out. Afterwards I even need to turn bluetooth on/off to make it able to connect with other devices again 😢.

Hard to tell what's going on in Android Logcat: This is the error I get when I trying to discover all services & characteristics, after about 35 seconds: BleError: Operation timed out

eliaslecomte commented 1 year ago

So far this is what I have figured out.

The log while disvering is very long, here are the last few entries:

DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_FIND_INFORMATION_RESPONSE:
  format:      1
  information: 0x020E:0229
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=10, data=0600040005010e020229
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=050004000411021102
DEBUG:bumble.hci:<<< ACL PDU: 050004000411021102
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_FIND_INFORMATION_REQUEST:
  starting_handle: 0x0211
  ending_handle:   0x0211
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_FIND_INFORMATION_RESPONSE:
  format:      1
  information: 0x0211:0229
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=10, data=06000400050111020229
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=0700040008140217020228
DEBUG:bumble.hci:<<< ACL PDU: 0700040008140217020228
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0214
  ending_handle:   0x0217
  attribute_type:  UUID-16:2802 (Include)
DEBUG:root:not found ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0214
  ending_handle:   0x0217
  attribute_type:  UUID-16:2802 (Include)
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_READ_BY_TYPE_REQUEST
  attribute_handle_in_error: 0x0214
  error_code:                ATT_ATTRIBUTE_NOT_FOUND_ERROR
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=9, data=05000400010814020a
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=0700040008140217020328
DEBUG:bumble.hci:<<< ACL PDU: 0700040008140217020328
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0214
  ending_handle:   0x0217
  attribute_type:  UUID-16:2803 (Characteristic)
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_READ_BY_TYPE_RESPONSE:
  length:     7
  attributes: 0x0215:201602052a
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=13, data=0900040009071502201602052a
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=0700040008160217020328
DEBUG:bumble.hci:<<< ACL PDU: 0700040008160217020328
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0216
  ending_handle:   0x0217
  attribute_type:  UUID-16:2803 (Characteristic)
DEBUG:root:not found ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x0216
  ending_handle:   0x0217
  attribute_type:  UUID-16:2803 (Characteristic)
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_READ_BY_TYPE_REQUEST
  attribute_handle_in_error: 0x0216
  error_code:                ATT_ATTRIBUTE_NOT_FOUND_ERROR
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=9, data=05000400010816020a
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=9, data=050004000417021702
DEBUG:bumble.hci:<<< ACL PDU: 050004000417021702
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_FIND_INFORMATION_REQUEST:
  starting_handle: 0x0217
  ending_handle:   0x0217
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_FIND_INFORMATION_RESPONSE:
  format:      1
  information: 0x0217:0229
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=10, data=06000400050117020229
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1

What could I do to debug this better?

I am using https://github.com/dotintent/react-native-ble-plx.

barbibulle commented 1 year ago

I will try to replicate this on a few Android phones to see if I can make it fail in the same way. Regarding the case described earlier where the phone would not even connect, does that happen after a connection where it fails to fully discover all characteristics? Or is that a different issue?

eliaslecomte commented 1 year ago

Indeed, if the discovery of services & characteristic failed, on a next attempt, it looks like it doesn't even try it again. Thanks for taking the time!

eliaslecomte commented 1 year ago

I just started to notice I have a few of these logs at the very end of the discover services:

DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:         1
  connection_handle[0]:     0
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0000pb=2, bc=0, data_total_length=11, data=07000400080b0213020228
DEBUG:bumble.hci:<<< ACL PDU: 07000400080b0213020228
DEBUG:bumble.gatt_server:GATT Request to server: [0x0000] ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x020B
  ending_handle:   0x0213
  attribute_type:  UUID-16:2802 (Include)
DEBUG:root:not found ATT_READ_BY_TYPE_REQUEST:
  starting_handle: 0x020B
  ending_handle:   0x0213
  attribute_type:  UUID-16:2802 (Include)
DEBUG:bumble.gatt_server:GATT Response from server: [0x0000] ATT_ERROR_RESPONSE:
  request_opcode_in_error:   ATT_READ_BY_TYPE_REQUEST
  attribute_handle_in_error: 0x020B
  error_code:                ATT_ATTRIBUTE_NOT_FOUND_ERROR
--- Logging error ---
DEBUG:bumble.host:### HOST -> CONTROLLER: (CID=4) ACL: handle=0x0000pb=0, bc=0, data_total_length=9, data=0500040001080b020a
--- Logging error ---
barbibulle commented 1 year ago

GATT errors like ATT_ATTRIBUTE_NOT_FOUND_ERROR are normal and expected when performing a service/attribute discovery. The client keeps asking for things until it gets that error, indicating that it has reached the end of what it was asking for.

barbibulle commented 1 year ago

I have tried with a Pixel 3a running Android 12, and a simple GATT server with 256 readable/writeable/notifiable characteristics (in one service), and that seems to work fine. I'll try to find other Android phones to test with.

barbibulle commented 1 year ago

Update: I'm able to reproduce the issue with a Pixel 6. I can now investigate what's going on. It might take a couple weeks before I can get to it, but I will follow up. Also, I checked with a different BT controller, I can reproduce the same issue, so it doesn't seem related to the specifics of the nrf52840 USB dongle.

barbibulle commented 1 year ago

The Android Bluetooth stack has a compiled-in limit for the maximum number of characteristic registrations (see https://cs.android.com/android/platform/superproject/main/+/main:packages/modules/Bluetooth/system/bta/gatt/bta_gattc_int.h;l=238;bpv=1;bpt=1 ). It used to be 15 a while back, more recent versions have it at 64, and some phone manufacturers may have they own customization. I don't think there's an way way to check from your app code what that limit is, unfortunately.