Bluetooth Disconnections while connecting the device with IPhone SE

[karnram]

We are facing issues whenever a Bluetooth connection is made between our device (Amazon Locker using nrf52840) and IPhone SE Model.The connection is made successfully but within a few seconds, disconnection is triggered by the device without any clear reason in the logs.

We are observing the following series of events:

1. Connection is made successfully.

2. Connection params are exchanged between the device and the app.

3. Within a few seconds, disconnection is triggered without any clear reason in the logs.

Sample logs from the device:

[17:20:05.104] <info>: Received BLE GAP event: 16
[17:20:05.104] <info>: Peer address: 62:26:7C:8F:C8:A1.
[17:20:05.104] <info>: Received Connection Params: MIN_CI: 24, MAX_CI: 24, SL: 0, ST: 72
[17:20:05.104] <info>: Successfully disabled local slave latency
[17:20:05.104] <info>: [elf::communication::ble(BLE)] 226 87944 BLE connection status changed [conn_id: 0, connected: 1]
[17:20:05.105] <info>: [elf::metric::worker(NORMAL_METRIC_)] 158 87920 process metric 83
[17:20:05.107] <info>: [elf::communication::security::authenticated(BLE)] 226 87944 New connection event for connection id: 0
[17:20:05.211] <info>: Received BLE GAP event: 58
[17:20:05.211] <info>: [elf::communication::ble(BLE)] 226 87736 BLE MTU changed to 185
[17:20:05.241] <info>: Received BLE GAP event: 36
[17:20:05.661] <info>: Received BLE GAP event: 80
[17:20:05.930] <info>: Received BLE GAP event: 81
[17:20:06.081] <info>: Received BLE GAP event: 80
[17:20:06.141] <info>: Received BLE GAP event: 80
[17:20:06.141] <info>: [elf::communication::ble::rx_data_ctlr(BLE)] 226 87696 Message bytes length: 31
[17:20:06.142] <info>: Current Time: 1615310406, Sender Time: 1615310407, Message Flight Time: 1
[17:20:06.142] <info>: Signing received random nonce in Asn1 format ...
[17:20:06.199] <info>: Sending challenge response message to mobile...
[17:20:06.291] <info>: Received BLE GAP event: 83
[17:20:06.296] <info>: Received BLE GAP event: 80
[17:20:06.321] <info>: Received BLE GAP event: 18
[17:20:06.321] <info>: Received Connection Params: MIN_CI: 27, MAX_CI: 27, SL: 10, ST: 400
[17:20:06.321] <info>: Successfully disabled local slave latency
[17:20:06.421] <info>: Received BLE GAP event: 80
[17:20:06.485] <info>: Received BLE GAP event: 80
[17:20:06.485] <info>: [elf::communication::ble::rx_data_ctlr(BLE)] 226 87240 Message bytes length: 400
[17:20:06.486] <info>: Current Time: 1615310406, Sender Time: 1615310408, Message Flight Time: 2
[17:20:06.487] <info>: Processing create session request...
[17:20:06.701] <info>: Persisting session keys with cloud session id: 87344831-1840-4d4c-8e18-485e498b5d25 and expiry: 1615396473
[17:20:06.755] <info>: Received BLE GAP event: 83
[17:20:08.951] <info>: Received BLE GAP event: 80
[17:20:08.951] <info>: [elf::communication::ble::rx_data_ctlr(BLE)] 226 87424 Message bytes length: 100
[17:20:08.951] <info>: Current Time: 1615310408, Sender Time: 1615310410, Message Flight Time: 2
[17:20:08.952] <warning>: Failed to find byte-array attribute: q during deserialization
[17:20:08.952] <info>: Sending challenge request for the mobile...
[17:20:09.015] <info>: Received BLE GAP event: 83
[17:20:09.017] <info>: Received BLE GAP event: 80
[17:20:09.017] <info>: [elf::communication::ble::rx_data_ctlr(BLE)] 226 87304 Message bytes length: 61
[17:20:09.018] <info>: Current Time: 1615310409, Sender Time: 1615310410, Message Flight Time: 1
[17:20:09.018] <info>: Handling challenge response message from mobile...
[17:20:09.019] <info>: Forwarding decrypted user message to application...
[17:20:09.019] <info>: [elf::communication::command(SEC_MGR_WORKER)] 51 Received command for request: 0, T: 8, V: 1
[17:20:09.020] <warning>: [elf::communication::command(CMD_WORKER_LOW)] 996 87504 No processor mapped for T: 8
[17:20:09.421] <info>: Received BLE GAP event: 18
[17:20:09.421] <info>: Received Connection Params: MIN_CI: 27, MAX_CI: 27, SL: 10, ST: 400
[17:20:09.421] <info>: Successfully disabled local slave latency
[17:20:12.525] <info>: Received BLE GAP event: 18
[17:20:12.525] <info>: Received Connection Params: MIN_CI: 27, MAX_CI: 27, SL: 10, ST: 400
[17:20:12.525] <info>: Successfully disabled local slave latency
[17:20:15.596] <info>: Received BLE GAP event: 17
[17:20:15.596] <info>: [elf::communication::ble(BLE)] 226 87528 Successfully changed BLE advertisement status (start-1, stop-0): 0
[17:20:15.597] <info>: [elf::communication::ble(BLE)] 226 87528 Successfully changed BLE advertisement status (start-1, stop-0): 1
[17:20:15.597] <info>: [elf::communication::ble(BLE)] 226 87528 BLE connection status changed [conn_id: 0, connected: 0]
[17:20:15.597] <info>: [elf::communication::ble::connection(BLE)] 226 87528 connection_info removed with id : 0
[17:20:15.599] <info>: [elf::communication::security::authenticated(BLE)] 226 87528 Cleaning up resources for connection id: 0
[17:20:15.600] <info>: Cleaning up the auth session...
[17:20:15.600] <info>: [elf::communication::command(BLE)] 226 87840 Cleaning up worker tasks resources...
[17:20:15.600] <info>: [elf::communication::ble(BLE)] 226 87928 Received BLE Disconnection Reason: 22

[Einar Thorsrud]

Hi,

I see the disconnect reason is 22 = 0x16 = BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION so it seems like it is the nRF that is disconnecting. I do not see from the log why the nRF disconnects, but I notice that there are a lot of connection parameter updates before it. Could it be that you disconnect when connection parameters are not acceptable to you? (in that case you would typically use BLE_HCI_CONN_INTERVAL_UNACCEPTABLE  but there is nothing preventing you from using BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION). There could also be other reasons for the nRF disconnecting, though I am not able to explain that from the log. Is it possible to check the code and see in which situation the nRF would disconnect? And perhaps add some logging around there to show what happens why?

Einar