We have a design that uses a simple custom board with an NRF52832 chip, button, accelerometer and onboard battery. For many phones, the operation is quite stable - we connect, bond, and subscribe to notifications and don't see any unusual behavior. However with certain phones (so far only bl4.2), we connect, bond, disconnect, and then on any consecutive attempts to connect we are immediately disconnected after the device's first attempt to negotiate connection parameters. Some more information is included below:
Connection settings:
#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 92 #define NRF_SDH_BLE_GAP_DATA_LENGTH 32 #define NRF_SDH_BLE_GAP_EVENT_LENGTH 10
#define MIN_CONN_INTERVAL MSEC_TO_UNITS(45, UNIT_1_25_MS) #define MAX_CONN_INTERVAL MSEC_TO_UNITS(60, UNIT_1_25_MS) #define SLAVE_LATENCY 15 #define CONN_SUP_TIMEOUT MSEC_TO_UNITS(6000, UNIT_10_MS) #define FIRST_CONN_PARAMS_UPDATE_DELAY APP_TIMER_TICKS(5000) #define NEXT_CONN_PARAMS_UPDATE_DELAY APP_TIMER_TICKS(1000) #define MAX_CONN_PARAMS_UPDATE_COUNT 3
This is what a normal connection sequence to a bonded device (using the NRF Connect App on Android) looks like from the device side:
[00:01:45.000,000] <debug> nrf_sdh_ble: BLE event: 0x10. [00:01:45.000,000] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change [00:01:45.000,000] <info> app: Connected with Bond Info [00:01:45.000,000] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 92 bytes on connection 0x0. [00:01:45.000,000] <debug> nrf_ble_gatt: Updating data length to 32 on connection 0x0. [00:01:45.000,000] <info> app: Connected. [00:01:45.000,000] <info> app: Stopped iBeacon advertising [00:01:45.000,000] <info> app: Initialized ADC [00:01:45.000,000] <debug> nrf_sdh_ble: BLE event: 0x24. [00:01:45.000,000] <debug> nrf_ble_gatt: Data length updated to 32 on connection 0x0. [00:01:45.000,000] <debug> nrf_ble_gatt: max_rx_octets: 32 [00:01:45.000,000] <debug> nrf_ble_gatt: max_tx_octets: 32 [00:01:45.000,000] <debug> nrf_ble_gatt: max_rx_time: 1096 [00:01:45.000,000] <debug> nrf_ble_gatt: max_tx_time: 1096 [00:01:45.000,000] <debug> nrf_sdh_ble: BLE event: 0x14. [00:01:45.000,000] <info> app: Battery: 3008mV TempAdj: 20mV, 100% [00:01:45.000,000] <debug> app: Value write: 3028 [00:01:45.000,000] <info> app: Writing file: 0xA010, key: 0xA008, len: 1 words, 4 bytes [00:01:45.000,000] <info> app: Update Record ID: 0x01E0 File ID: 0xA010 Record key: 0xA008 [00:01:45.000,000] <debug> nrf_sdh_ble: BLE event: 0x1A. [00:01:45.000,000] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption [00:01:45.000,000] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change [00:01:45.000,000] <debug> nrf_sdh_ble: BLE event: 0x3A. [00:01:45.000,000] <debug> nrf_ble_gatt: ATT MTU updated to 92 bytes on connection 0x0 (response). [00:01:46.000,000] <debug> nrf_sdh_ble: BLE event: 0x12. [00:01:46.000,000] <debug> nrf_sdh_ble: BLE event: 0x23. [00:01:46.000,000] <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 123 bytes. [00:01:46.000,000] <debug> nrf_ble_gatt: Updating data length to 32 on connection 0x0. [00:01:46.000,000] <debug> nrf_sdh_ble: BLE event: 0x24. [00:01:46.000,000] <debug> nrf_ble_gatt: Data length updated to 32 on connection 0x0. [00:01:46.000,000] <debug> nrf_ble_gatt: max_rx_octets: 32 [00:01:46.000,000] <debug> nrf_ble_gatt: max_tx_octets: 32 [00:01:46.000,000] <debug> nrf_ble_gatt: max_rx_time: 1096 [00:01:46.000,000] <debug> nrf_ble_gatt: max_tx_time: 1096 [00:01:46.000,000] <debug> nrf_sdh_ble: BLE event: 0x12. [00:01:47.000,000] <debug> nrf_sdh_ble: BLE event: 0x12. [00:01:47.000,000] <debug> app: iBeacon Radio Session End [00:01:47.000,000] <debug> app: iBeacon Radio Session Closed [00:02:14.000,000] <debug> nrf_sdh_ble: BLE event: 0x11. [00:02:14.000,000] <debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist [00:02:14.000,000] <info> app: Fast advertising with whitelist. [00:02:14.000,000] <info> app: Disconnected, reason 19.
And here is what the logs look like from the app side:
Safety_Tag-DC40342AB7A1 (DC:40:34:2A:B7:A1) V 17:17:35.542 Connecting to DC:40:34:2A:B7:A1... D 17:17:35.542 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M) D 17:17:35.601 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2) I 17:17:35.601 Connected to DC:40:34:2A:B7:A1 V 17:17:35.641 Discovering services... D 17:17:35.641 gatt.discoverServices() D 17:17:35.655 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED I 17:17:36.276 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms) D 17:17:36.548 [Callback] Services discovered with status: 0 I 17:17:36.548 Services discovered V 17:17:36.562 Generic Access (0x1800) ... D 17:17:36.562 gatt.setCharacteristicNotification(3c961041-b9dd-4885-52f6-ed6699edb9e7, true) D 17:17:36.564 gatt.setCharacteristicNotification(3c961042-b9dd-4885-52f6-ed6699edb9e7, true) D 17:17:36.565 gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true) I 17:17:36.632 Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms) I 17:17:41.741 Connection parameters updated (interval: 45.0ms, latency: 15, timeout: 6000ms)
We have several phones that have problems and do not have this connection pattern after a bond has been established. The details of one such phone are included below:
Compare the successful connection sequence to the logs we get when we use a "troublesome" phone and the devices (same app, also bonded):
[00:02:15.000,000] <debug> nrf_sdh_ble: BLE event: 0x10. [00:02:15.000,000] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change [00:02:15.000,000] <info> app: Connected with Bond Info [00:02:15.000,000] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 92 bytes on connection 0x0. [00:02:15.000,000] <debug> nrf_ble_gatt: Updating data length to 32 on connection 0x0. [00:02:15.000,000] <info> app: Connected. [00:02:15.000,000] <info> app: Stopped iBeacon advertising [00:02:15.000,000] <info> app: Initialized ADC [00:02:15.000,000] <debug> nrf_sdh_ble: BLE event: 0x14. [00:02:15.000,000] <info> app: Battery: 3007mV TempAdj: 20mV, 100% [00:02:15.000,000] <debug> app: Value write: 3027 [00:02:15.000,000] <info> app: Writing file: 0xA010, key: 0xA008, len: 1 words, 4 bytes [00:02:15.000,000] <info> app: Update Record ID: 0x01E1 File ID: 0xA010 Record key: 0xA008 [00:02:15.000,000] <debug> nrf_sdh_ble: BLE event: 0x1A. [00:02:15.000,000] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption [00:02:15.000,000] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change [00:02:15.000,000] <debug> nrf_sdh_ble: BLE event: 0x3A. [00:02:15.000,000] <debug> nrf_ble_gatt: ATT MTU updated to 92 bytes on connection 0x0 (response). [00:02:16.000,000] <debug> nrf_sdh_ble: BLE event: 0x12. [00:02:16.000,000] <debug> nrf_sdh_ble: BLE event: 0x11. [00:02:16.000,000] <debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist [00:02:16.000,000] <info> app: Fast advertising with whitelist. [00:02:16.000,000] <info> app: Disconnected, reason 42.
And this is what the NRF Connect logs look like:
nRF Connect, 2021-03-23 Safety_Tag-DC40342AB7A1 (DC:40:34:2A:B7:A1) D 16:02:54.460 gatt.close() D 16:02:54.461 wait(200) V 16:02:54.663 Connecting to DC:40:34:2A:B7:A1... D 16:02:54.663 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M) D 16:02:54.815 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED D 16:02:54.831 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2) I 16:02:54.831 Connected to DC:40:34:2A:B7:A1 D 16:02:54.833 wait(1600ms) D 16:02:55.220 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11) D 16:02:55.238 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12) I 16:02:55.238 Device bonded I 16:02:55.620 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms) V 16:02:56.435 Discovering services... D 16:02:56.435 gatt.discoverServices() D 16:03:00.725 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0) E 16:03:00.725 Error 8 (0x8): GATT CONN TIMEOUT I 16:03:00.725 Disconnected D 16:03:00.831 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
At this point I am not sure what is happening and what to check next - The device says the phone is disconnecting, but the Phone says the connection times out... I do not see any errors or other things in the device logs that would suggest a time out, and the issue only happens with certain phones and not others. Other posts suggest that maybe the connection parameters or MTU size might be to blame, however even the "trouble" phones are able to connect and bond once, which would not be the case if the connection settings were not compatible. Any hints would be appreciated.
