startNotifying sometimes makes BLE device disconnect

[sebj54]

Hi!

I have a long running issue which happens approximately 1 in 10 times. It seems to happen more on Android than on iOS. I investigated this problem deeper on Android actually and I identified one thing which, I think, is responsible of the problem.

I started my debug by enabling Trace for this module:

import { Trace } from '@nativescript/core'
import { BleTraceCategory } from '@nativescript-community/ble'

Trace.enable()
Trace.setCategories(BleTraceCategory)

What I do in my app is the following:

1. Connect to a BLE device
2. Write something on a characteristic
3. Receive a notification on another characteristic

The problem occurs between step 2 and step 3.

Here is a sample of the involved code:

console.log('BT DEBUG:  BLE start notification')
bluetooth.startNotifying({
    peripheralUUID,
    serviceUUID: myService,
    characteristicUUID: myCharacteristic,
    onNotify: () => {
        console.log('BT DEBUG:  BLE notification success')
    },
}

Here is a sample of adb logcat for a successful notification (only the startNotifying part):

02-03 14:46:34.614 31483 31483 I JS      : BT DEBUG:  BLE start notification
02-03 14:46:34.726 31483 31483 I JS      : NativescriptBle: startNotifying {"peripheralUUID":"00:16:A4:0F:C5:71","serviceUUID":"a88b1101-e5b2-42b3-b33b-bac0899b391a","characteristicUUID":"a88b3001-e5b2-42b3-b33b-bac0899b391a"}
02-03 14:46:34.731 31483 31483 I JS      : NativescriptBle: startNotifying ---- peripheralUUID:00:16:A4:0F:C5:71 serviceUUID:a88b1101-e5b2-42b3-b33b-bac0899b391a characteristicUUID:a88b3001-e5b2-42b3-b33b-bac0899b391a
02-03 14:46:34.732 31483 31483 D BluetoothGatt: setCharacteristicNotification() - uuid: a88b3001-e5b2-42b3-b33b-bac0899b391a enable: true
02-03 14:46:34.825 31483 31483 I JS      : NativescriptBle: TNS_BluetoothGattCallback.onDescriptorWrite ---- gatt: android.bluetooth.BluetoothGatt@49bf26e, descriptor: android.bluetooth.BluetoothGattDescriptor@e7b9b8, status: 0
02-03 14:46:34.841 31483 31483 I JS      : NativescriptBle: TNS_BluetoothGattCallback.onCharacteristicChanged ---- gatt: android.bluetooth.BluetoothGatt@49bf26e, characteristic: android.bluetooth.BluetoothGattCharacteristic@17c1b15, device: 00:16:A4:0F:C5:71
02-03 14:46:34.844 31483 31483 I JS      : BT DEBUG:  BLE notification success

And here is a sample of adb logcat for a failing notification:

02-03 14:46:50.768 31483 31483 I JS      : BT DEBUG:  BLE start notification
02-03 14:46:50.873 31483 31483 I JS      : NativescriptBle: startNotifying {"peripheralUUID":"00:16:A4:0F:C5:71","serviceUUID":"a88b1101-e5b2-42b3-b33b-bac0899b391a","characteristicUUID":"a88b3001-e5b2-42b3-b33b-bac0899b391a"}
02-03 14:46:50.876 31483 31483 I JS      : NativescriptBle: startNotifying ---- peripheralUUID:00:16:A4:0F:C5:71 serviceUUID:a88b1101-e5b2-42b3-b33b-bac0899b391a characteristicUUID:a88b3001-e5b2-42b3-b33b-bac0899b391a
02-03 14:46:50.877 31483 31483 D BluetoothGatt: setCharacteristicNotification() - uuid: a88b3001-e5b2-42b3-b33b-bac0899b391a enable: true
02-03 14:46:51.104 31483 31483 I JS      : NativescriptBle: TNS_BluetoothGattCallback.onCharacteristicChanged ---- gatt: android.bluetooth.BluetoothGatt@8698f62, characteristic: android.bluetooth.BluetoothGattCharacteristic@5cd3151, device: 00:16:A4:0F:C5:71
02-03 14:46:51.108 31483 31483 I JS      : NativescriptBle: TNS_BluetoothGattCallback.onDescriptorWrite ---- gatt: android.bluetooth.BluetoothGatt@8698f62, descriptor: android.bluetooth.BluetoothGattDescriptor@5dc8224, status: 0
02-03 14:46:55.051  1888  2387 I bt_stack: [INFO:hearing_aid.cc(1796)] GetDeviceCount: Not initialized yet
02-03 14:46:55.393 31483 31502 D BluetoothGatt: onConnectionUpdated() - Device=00:16:A4:0F:C5:71 interval=48 latency=0 timeout=600 status=0
[...]
02-03 14:47:04.106  1888  2387 I bt_stack: [INFO:btsnoop.cc(338)] clear_l2cap_allowlist: Clearing acceptlist from l2cap channel. conn_handle=17 cid=4:4
02-03 14:47:04.106  1888  2387 I bt_stack: [INFO:gatt_attr.cc(338)] gatt_connect_cback: remove untrusted client status, bda=00:16:a4:0f:c5:71
02-03 14:47:04.107  1888  2387 I bluetooth: system/bt/stack/gap/gap_ble.cc:298 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:c5:71 callback:Disconnected
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:3 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:4 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:5 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:6 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:7 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:8 transport:le reason:GATT_CONN_TERMINATE_PEER_USER
02-03 14:47:04.107  1888  2387 I btif_av : system/bt/btif/src/btif_av.cc:3352 btif_av_acl_disconnected: btif_av_acl_disconnected: Peer 00:16:a4:0f:c5:71 : ACL Disconnected

To make it short, the problem in the failing notification seems to be that BluetoothGattCallback.onCharacteristicChanged is called before BluetoothGattCallback.onDescriptorWrite (see diff).

I tried to debug it in bluetooth.android.js directly in node_modules but I didn't find anything different when it fails. I thought that setCharacteristicNotification should be called after bluetoothGattDescriptor instanciation but it does not change anything.

ble/src/bluetooth.android.ts

Line 2328 in a81ffcf

if (!gatt.setCharacteristicNotification(characteristic, true)) {

If you have any idea, let me know, I'll probably debug it more last week.

[farfromrefug]

first what s your version of the plugin? second what s your ble device ?
it could be an error on the device firmware closing thw connection

[sebj54]

Plugin's version is the last one (3.1.5).

You're right, this error can happen because of the BLE device. But the different callbacks order when failing makes me think this is the root cause. Do you think the device can trigger the callbacks in a different order randomly?

I was also wondering if callbacks are all registered in the startNotifying function.

In the failing logs I provided, onDescriptorWrite is logged only 40ms after onCharacteristicChanged. Something may delay the first callback internally. I know also that GATT is extremely synchronous so JS asynchronous behavior can introduce issues like this one.

[farfromrefug]

@sebj54 First the order is correct. setCharacteristicNotification is called before setValue so onCharacteristicChanged shoudl happen before.
now the fact that you see that both on iOS and Android let me to believe it is on the device side. The implementation are completely different on both platforms.
finally i know it does not say it all but i use startNotifying in multiple apps in productions. I use it also daily on tens of devices and i never had any such issue.
I would bet on either the device crashing or the device not liking the order you do things. Maybe to fast after connection?

[sebj54]

Thank you for the adivce, I'm going to test it further today with extras setTimeout and see if the BLE communication is more stable with our device. Actually we also have an app in production with the plugin and it has worked fine for months, except this little bug which happens sometimes and forces users to connect again with the BLE device.

About the order, you're saying:

setCharacteristicNotification is called before setValue so onCharacteristicChanged should happen before.

I noticed the opposite, it is working only if onCharacteristicChanged is called after onDescriptorWrite. That's what made me think there was a problem on the phone's side. The idea was to know if it is possible to make sure onCharacteristicChanged is called only after the descriptor has been written.

I'll let you know if I find anything and I'll close the issue if I can work around the problem without altering the plugin. Tahnks again for your help!