Supervision timeout is not triggered in corner case

[Matej]

Hi guys,

We have noticed some unexpected behavior of supervision timeout in case of few fast sequential calls of connect and disconnect commands in nRF connect app with android phones. After some retries this can be quite easily triggered.

The problem is that smart device is disconnected, but nRF does not receive disconnect event from softdevice – probably also softdevice is not aware that device on other side was disconnected.

Issue was noticed and reproduced on nRF51822 with S130, SDK 12.3.0 and also on nRF52832, SDK nRF5_SDK_15.3.0_59ac345, with prebuild hex ble_app_gls_pca10040_s132.hex.

• On nRF51 and custom project we don’t receive disconnect event at all – even if we disable or restart smart device and after that we are still get success on sd_ble_gap_disconnect
• On nRF52 and ble_app_gls example we receive disconnect event but not at disconnection time on smart device, but after aprox 180 sec + 4 sec (just presuming :180sec for advertising duration and 4 sec for supervision). In attachment you can find logs from UART and nRF connect.

We also build ble_app_gls with gcc and check the value of m_conn_handle variable with J-scope and also this variable changes as mentioned above.

Is this expected/known behavior?

Best regards,

Matej

Fullscreen Log 2019-03-20 100340.txt Download

nRF Connect, 2019-03-20
Nordic_Glucose (C4:BA:50:F2:96:06)
V	10:02:53.325	Connecting to C4:BA:50:F2:96:06...
D	10:02:53.325	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:02:54.001	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:02:54.024	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:02:54.024	Connected to C4:BA:50:F2:96:06
D	10:02:54.033	wait(1600ms)
V	10:02:55.652	Discovering services...
D	10:02:55.652	gatt.discoverServices()
D	10:02:55.674	[Callback] Services discovered with status: 0
I	10:02:55.674	Services discovered
V	10:02:55.722	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)
Glucose (0x1808)
- Glucose Measurement [N] (0x2A18)
   Client Characteristic Configuration (0x2902)
- Glucose Feature [R] (0x2A51)
- Record Access Control Point [I W] (0x2A52)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Serial Number String [R] (0x2A25)
- System ID [R] (0x2A23)
D	10:02:55.722	gatt.setCharacteristicNotification(00002a18-0000-1000-8000-00805f9b34fb, true)
D	10:02:55.727	gatt.setCharacteristicNotification(00002a52-0000-1000-8000-00805f9b34fb, true)
D	10:02:55.732	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
V	10:02:59.269	Disconnecting...
D	10:02:59.269	gatt.disconnect()
D	10:02:59.285	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	10:02:59.285	Disconnected
D	10:03:00.362	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:03:01.020	gatt.close()
D	10:03:01.022	wait(200)
V	10:03:01.225	Connecting to C4:BA:50:F2:96:06...
D	10:03:01.225	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
V	10:03:01.519	Cancelling connection...
D	10:03:01.519	gatt.disconnect()
I	10:03:01.523	Disconnected
D	10:03:01.864	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:03:01.864	gatt.close()
D	10:03:01.876	wait(200)
V	10:03:02.082	Connecting to C4:BA:50:F2:96:06...
D	10:03:02.082	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:02.226	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:02.227	Error 133 (0x85): GATT ERROR
I	10:03:02.227	Disconnected
D	10:03:02.536	gatt.close()
D	10:03:02.538	wait(200)
V	10:03:02.742	Connecting to C4:BA:50:F2:96:06...
D	10:03:02.742	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:02.864	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:02.864	Error 133 (0x85): GATT ERROR
I	10:03:02.864	Disconnected
D	10:03:16.040	gatt.close()
D	10:03:16.043	wait(200)
V	10:03:16.246	Connecting to C4:BA:50:F2:96:06...
D	10:03:16.246	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:16.370	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:16.371	Error 133 (0x85): GATT ERROR
I	10:03:16.371	Disconnected

Fullscreen Log 2019-03-20 100649.txt Download

nRF Connect, 2019-03-20
Nordic_Glucose (C4:BA:50:F2:96:06)
V	10:02:53.325	Connecting to C4:BA:50:F2:96:06...
D	10:02:53.325	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:02:54.001	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:02:54.024	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:02:54.024	Connected to C4:BA:50:F2:96:06
D	10:02:54.033	wait(1600ms)
V	10:02:55.652	Discovering services...
D	10:02:55.652	gatt.discoverServices()
D	10:02:55.674	[Callback] Services discovered with status: 0
I	10:02:55.674	Services discovered
V	10:02:55.722	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)
Glucose (0x1808)
- Glucose Measurement [N] (0x2A18)
   Client Characteristic Configuration (0x2902)
- Glucose Feature [R] (0x2A51)
- Record Access Control Point [I W] (0x2A52)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Serial Number String [R] (0x2A25)
- System ID [R] (0x2A23)
D	10:02:55.722	gatt.setCharacteristicNotification(00002a18-0000-1000-8000-00805f9b34fb, true)
D	10:02:55.727	gatt.setCharacteristicNotification(00002a52-0000-1000-8000-00805f9b34fb, true)
D	10:02:55.732	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
V	10:02:59.269	Disconnecting...
D	10:02:59.269	gatt.disconnect()
D	10:02:59.285	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	10:02:59.285	Disconnected
D	10:03:00.362	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:03:01.020	gatt.close()
D	10:03:01.022	wait(200)
V	10:03:01.225	Connecting to C4:BA:50:F2:96:06...
D	10:03:01.225	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
V	10:03:01.519	Cancelling connection...
D	10:03:01.519	gatt.disconnect()
I	10:03:01.523	Disconnected
D	10:03:01.864	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:03:01.864	gatt.close()
D	10:03:01.876	wait(200)
V	10:03:02.082	Connecting to C4:BA:50:F2:96:06...
D	10:03:02.082	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:02.226	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:02.227	Error 133 (0x85): GATT ERROR
I	10:03:02.227	Disconnected
D	10:03:02.536	gatt.close()
D	10:03:02.538	wait(200)
V	10:03:02.742	Connecting to C4:BA:50:F2:96:06...
D	10:03:02.742	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:02.864	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:02.864	Error 133 (0x85): GATT ERROR
I	10:03:02.864	Disconnected
D	10:03:16.040	gatt.close()
D	10:03:16.043	wait(200)
V	10:03:16.246	Connecting to C4:BA:50:F2:96:06...
D	10:03:16.246	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:03:16.370	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	10:03:16.371	Error 133 (0x85): GATT ERROR
I	10:03:16.371	Disconnected
D	10:06:07.435	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:06:37.470	gatt.close()
D	10:06:37.473	wait(200)
V	10:06:37.675	Connecting to C4:BA:50:F2:96:06...
D	10:06:37.675	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:06:38.325	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:06:38.350	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:06:38.350	Connected to C4:BA:50:F2:96:06
D	10:06:38.354	wait(1600ms)
V	10:06:39.972	Discovering services...
D	10:06:39.972	gatt.discoverServices()
D	10:06:39.990	[Callback] Services discovered with status: 0
I	10:06:39.990	Services discovered
V	10:06:40.030	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)
Glucose (0x1808)
- Glucose Measurement [N] (0x2A18)
   Client Characteristic Configuration (0x2902)
- Glucose Feature [R] (0x2A51)
- Record Access Control Point [I W] (0x2A52)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Serial Number String [R] (0x2A25)
- System ID [R] (0x2A23)
D	10:06:40.030	gatt.setCharacteristicNotification(00002a18-0000-1000-8000-00805f9b34fb, true)
D	10:06:40.032	gatt.setCharacteristicNotification(00002a52-0000-1000-8000-00805f9b34fb, true)
D	10:06:40.036	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)

[Kenneth]

Hi,

According to the experts the connection may be kept alive if other apps are using the connection (including android settings). Usually Android disconnects 1sec after the disconnect is called and no other connection is open (no other app is still connected to this device)

Best regards,
Kenneth

[Matej]

Hi,

Actually mentioned behavior is triggered on Samsung devices (S5 android 6.0.1 [a bit harder to trigger] and S8 android 7.0 [easily triggered]) with android version < 8.0. We receive disconnect event after 180 sec even if we disable BLE. In case that we power off smart device we receive disconnect event within 30 sec.

Also tested with Xiaomi MI 6 android 8.0 and Apple iPad and things works as expected – it seems that this is some issue on Samsung with BLE stack.

Any ideas how to proceed… or prevent mobile app developers to trigger that? Except not calling connect sequential if first try of establishing connection from some reason won’t succeed.

Thank you!

BR,
Matej

[Kenneth]

You may check out this thread and the linked document in the thread:

https://devzone.nordicsemi.com/b/blog/posts/what-to-keep-in-mind-when-developing-your-ble-andr