Immediate disconnect from bonded device with reason 42

[emb_dev]

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.

[Kenneth]

An on-air sniffer log would be useful:
https://www.nordicsemi.com/Software-and-tools/Development-Tools/nRF-Sniffer-for-Bluetooth-LE

Without a sniffer log it would be difficult to guess, you may try comment out the following api calls (if those are used in your application):
//pm_handler_disconnect_on_sec_failure() // comment out if used
//pm_handler_secure_on_connection() // comment out if used
//pm_handler_secure_on_error() // comment out if used
//pm_handler_disconnect_on_insufficient_sec // comment out if used

For the above change to have any effect, you would need to make a new bond with the above changes in place.

Best regards,
Kenneth

[emb_dev]

Hi Kenneth,

Thank you for your response. We do not currently use any of those calls in our application.
I spent some time getting the sniffer set up and recording useful logs, however it seems that no matter what I do, the logger cannot break the encryption of the packets after the bond is made. I do not expect this to happen with our current bonding parameters, shown below:

#define MAX_BONDED_PEERS                    5

#define SEC_PARAM_BOND                      1                                       /**< Perform bonding. */
#define SEC_PARAM_MITM                      0                                       /**< Man In The Middle protection not required. */
#define SEC_PARAM_LESC                      0                                       /**< LE Secure Connections enabled. */
#define SEC_PARAM_KEYPRESS                  0                                       /**< Keypress notifications not enabled. */
#define SEC_PARAM_IO_CAPABILITIES           BLE_GAP_IO_CAPS_NONE                    /**< No I/O capabilities. */
#define SEC_PARAM_OOB                       0                                       /**< Out Of Band data not available. */
#define SEC_PARAM_MIN_KEY_SIZE              7                                       /**< Minimum encryption key size. */
#define SEC_PARAM_MAX_KEY_SIZE              16                                      /**< Maximum encryption key size. */

Regardless, for both logs, I would power on the device and see that it was advertising, then start the wireshark log. I would then connect the phone to the device, pause a bit and then start the bonding process from the phone. The bonding process would succeed, I would pause, and then disconnect. After a few seconds of advertising, I would attempt to reconnect again. On the "failed" log, the connection is not successful, on the "passed" log the connection is successful and I disconnected after a few moments.

The sniffer logs are attached below:
bondingTestPassed1.pcapng
bondingTestFailed1.pcapng

[Kenneth]

Hi,

Can  you just search through your project for pm_handler_secure_on_connection()?

It could explain your problem, because I can see from the sniffer log that the peripheral is sending a SMP security request after connection, and I have seen this may trigger an issue on android phones. So trying to find out where this request is comming from is what I recommend:

Kenneth

[emb_dev]

Hi Kenneth,

We just checked and the function is not called anywhere in our code. However, just to make sure, we deleted the definition and declaration in peer_manager_handler.c and peer_manager_handler.h, rebuilt the application and tested with the same results. Do you have any thoughts on where else the SMP request could be coming from so we can check, or is it time to submit the code for a private review?

*Edit: we also see the same SMP request on the phone where the reconnect-after-bond is successful (from the bondingTestPassed1 logs) and it does not seem to cause any issues - is this a difference in how the bl version / android versions handle this request?

[Kenneth]

emb_dev said:

*Edit: we also see the same SMP request on the phone where the reconnect-after-bond is successful (from the bondingTestPassed1 logs) and it does not seem to cause any issues - is this a difference in how the bl version / android versions handle this request?

Yes.

I might have linked the wrong api call, try to comment out: pm_handler_on_pm_evt().

Kenneth

[emb_dev]

Hi Kenneth,

Thank you for your help - removing the pm_handler_on_pm_evt() call from the pm_event_handler() function seems to have resolved our issue and we no-longer see the reason 42 disconnects after bonding. Is there a more detailed explanation for why certain versions do not play nicely with the SMP request?