Connect to a bonded peripheral via Android Smart Device

[Constantin]

This was already discussed in several threads but seems to be still unsolved completely. We have some android devices and ios devices. The peripheral is encrypted with LESC.

The SDK is 15.3 and the softdevice is S140. We developed first the iOS app and it is working fine without an issue. The device is paired and afterwards can be reconnected without an issue. If the pair is deleted a new pair can be created.

But the same peripheral has some strange behavior with several android devices:

With Samsung S7 Android 8 it works as expected although we are facing a timeout after 30 seconds. But reconnecting works as expected. But with some Samsung A6 tabs Same Android version it does not work. The sequence received is the following:

<info> peer_manager_smd: BLE_GAP_EVT_SEC_INFO_REQUEST
<debug> peer_manager_handler: Event PM_EVT_CONN_SEC_START
<debug> peer_manager_handler: Connection security procedure started: role: Peripheral, conn_handle: 0, procedure: Encryption
<info> BLE_CONN_HANDLER: Unknown event 0x14
<info> peer_manager_smd: BLE_GAP_EVT_CONN_SEC_UPDATE
<debug> peer_manager_handler: Event PM_EVT_CONN_SEC_SUCCEEDED
<info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption
<debug> peer_manager_handler: Event PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
<debug> peer_manager_handler: Peer data updated in flash: peer_id: 2, data_id: Peer rank, action: Update
<info> BLE_CONN_HANDLER: Connection secured: role: 1, conn_handle: 0x0, procedure: 0.
<info> BLE_CONN_HANDLER: Unknown event 0x1A
<debug> peer_manager_handler: Event PM_EVT_SERVICE_CHANGED_IND_CONFIRMED
<debug> peer_manager_handler: Service Changed indication confirmed.
<info> BLE_CONN_HANDLER: PM_EVT_SERVICE_CHANGED_IND_CONFIRMED
<info> BLE_CONN_HANDLER: Discovery timer stopped
<info> BLE_CONN_HANDLER: Unknown event 0x54
<info> FLASH_STORAGE: FDS Event Handler, 2
<info> FLASH_STORAGE: Update Successful
<debug> peer_manager_handler: Event PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
<debug> peer_manager_handler: Peer data updated: 2, data_id: Service changed pending flag, action: Update
<info> BLE_CONN_HANDLER: Unknown event 0x12
<info> BLE_CONN_HANDLER: Fast advertising.
<info> BLE_CONN_HANDLER: Disconnected.

This is the sequence during reconnection. I do not understand why it fails. Attached is a capture of wireshark sniffer one for iOS and one for Android. I've already checked with the nRF Connect App but the same happens. So it does not seem to be an issue with the Android App.

[Constantin]

Here is the log of the nrf_connect app:

nRF Connect, 2021-04-23
STIM2GO_f47a92 (F0:FC:C8:F4:7A:92)
V 16:08:04.241 Connecting to F0:FC:C8:F4:7A:92...
D 16:08:04.241 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:08:05.255 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:08:05.275 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:08:05.304 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
D 16:08:05.304 [Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_CONSENT (3)
I 16:08:05.304 Connected to F0:FC:C8:F4:7A:92
I 16:08:05.540 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I 16:08:05.853 Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I 16:08:08.198 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D 16:08:08.208 [Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_PIN (0)
D 16:08:14.034 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:08:14.035 Device bonded
D 16:08:14.087 wait(1600ms)
I 16:08:14.282 Connection parameters updated (interval: 75.0ms, latency: 0, timeout: 4000ms)
V 16:08:15.690 Discovering services...
D 16:08:15.690 gatt.discoverServices()
D 16:08:15.716 [Callback] Services discovered with status: 0
I 16:08:15.717 Services discovered
V 16:08:15.753 Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
D 16:08:15.754 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D 16:08:15.759 gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
D 16:08:23.626 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:08:23.626 Error 8 (0x8): GATT CONN TIMEOUT
I 16:08:23.626 Disconnected
D 16:08:23.725 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:08:38.803 gatt.close()
D 16:08:38.808 wait(200)
V 16:08:39.010 Connecting to F0:FC:C8:F4:7A:92...
D 16:08:39.010 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:08:39.220 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:08:39.220 Connected to F0:FC:C8:F4:7A:92
D 16:08:39.222 wait(1600ms)
D 16:08:39.222 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:08:39.632 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:08:39.675 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:08:39.675 Device bonded
I 16:08:39.873 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V 16:08:40.823 Discovering services...
D 16:08:40.823 gatt.discoverServices()
D 16:08:44.987 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:08:44.988 Error 8 (0x8): GATT CONN TIMEOUT
I 16:08:44.988 Disconnected
D 16:08:45.118 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:12:50.149 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:12:50.150 gatt.close()
D 16:12:50.179 wait(200)
V 16:12:50.381 Connecting to F0:FC:C8:F4:7A:92...
D 16:12:50.382 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:12:50.408 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:12:50.408 Connected to F0:FC:C8:F4:7A:92
D 16:12:50.411 wait(1600ms)
D 16:12:50.547 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:12:50.618 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:12:50.618 Device bonded
I 16:12:50.791 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I 16:12:51.106 Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V 16:12:52.013 Discovering services...
D 16:12:52.013 gatt.discoverServices()
D 16:12:52.029 [Callback] Services discovered with status: 0
I 16:12:52.029 Services discovered
V 16:12:52.030 No services found 
I 16:12:56.102 Connection parameters updated (interval: 75.0ms, latency: 0, timeout: 4000ms)
D 16:13:10.466 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:13:10.466 Error 8 (0x8): GATT CONN TIMEOUT
I 16:13:10.466 Disconnected
D 16:13:10.521 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:13:20.607 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:13:20.607 gatt.close()
D 16:13:20.628 wait(200)
V 16:13:20.830 Connecting to F0:FC:C8:F4:7A:92...
D 16:13:20.831 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:13:20.863 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:13:20.863 Connected to F0:FC:C8:F4:7A:92
D 16:13:20.865 wait(1600ms)
D 16:13:21.015 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:13:21.049 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:13:21.049 Device bonded
I 16:13:21.256 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V 16:13:22.467 Discovering services...
D 16:13:22.467 gatt.discoverServices()
D 16:13:26.375 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:13:26.375 Error 8 (0x8): GATT CONN TIMEOUT
I 16:13:26.375 Disconnected
D 16:13:26.414 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:13:40.450 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:13:40.451 gatt.close()
D 16:13:40.455 wait(200)
V 16:13:40.657 Connecting to F0:FC:C8:F4:7A:92...
D 16:13:40.657 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:13:40.684 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:13:40.684 Connected to F0:FC:C8:F4:7A:92
D 16:13:40.686 wait(1600ms)
D 16:13:40.856 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:13:40.895 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:13:40.896 Device bonded
I 16:13:41.102 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V 16:13:42.288 Discovering services...
D 16:13:42.288 gatt.discoverServices()
D 16:13:46.209 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:13:46.210 Error 8 (0x8): GATT CONN TIMEOUT
I 16:13:46.210 Disconnected
D 16:13:46.253 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:14:12.990 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:14:12.990 gatt.close()
D 16:14:13.024 wait(200)
V 16:14:13.226 Connecting to F0:FC:C8:F4:7A:92...
D 16:14:13.226 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:14:13.258 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:14:13.258 Connected to F0:FC:C8:F4:7A:92
D 16:14:13.261 wait(1600ms)
D 16:14:13.391 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:14:13.422 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:14:13.422 Device bonded
I 16:14:13.636 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V 16:14:14.862 Discovering services...
D 16:14:14.862 gatt.discoverServices()
D 16:14:18.110 [Callback] Services discovered with status: 0
I 16:14:18.110 Services discovered
V 16:14:18.110 No services found 
W 16:14:18.204 Connection parameters update failed with status 34 (interval: 45.0ms, latency: 0, timeout: 5000ms)
E 16:14:18.204 Error 34 (0x22): GATT CONN LMP TIMEOUT
D 16:14:18.219 [Callback] Connection state changed with status: 34 and new state: DISCONNECTED (0)
E 16:14:18.219 Error 34 (0x22): GATT CONN LMP TIMEOUT
I 16:14:18.220 Disconnected
D 16:14:18.264 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:16:01.946 gatt.close()
D 16:16:01.949 wait(200)
V 16:16:02.150 Connecting to F0:FC:C8:F4:7A:92...
D 16:16:02.150 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D 16:16:03.320 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 16:16:03.343 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:16:03.343 Connected to F0:FC:C8:F4:7A:92
D 16:16:03.347 wait(1600ms)
D 16:16:03.729 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:16:03.796 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I 16:16:03.797 Device bonded
I 16:16:03.975 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V 16:16:04.958 Discovering services...
D 16:16:04.958 gatt.discoverServices()
D 16:16:09.086 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:16:09.086 Error 8 (0x8): GATT CONN TIMEOUT
I 16:16:09.086 Disconnected
D 16:16:09.143 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

[Constantin]

Okay I can solve it by myself.

The issue was related to PM_HANDLER_SEC_DELAY_MS. The value was first at 0. But checking the reasing for BLE_GAP_EVT_DISCONNECTED reveals a BLE_HCI_DIFFERENT_TRANSACTION_COLLISION as the reason.

Googling for this issue gave that the PM_HANDLER_SEC_DELAY_MS might be the reason that the first request was not yet answered while a second request was already send. This produces a collision. Hence by introducing the PM_HANDLER_SEC_DELAY_MS of 100 worked in my case. The retest with iOS gave still the same performance.

Hence the issue can be closed.