startNotifying sometimes makes BLE device disconnect

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.

https://github.com/nativescript-community/ble/blob/a81ffcffdb6121559aaa3ad0cb5046845635410c/src/bluetooth.android.ts#L2328

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

Start in src/bluetooth.android.ts around line 2328, then compare the successful and failing adb logcat sequences for onCharacteristicChanged and onDescriptorWrite. Reproduce startNotifying around a characteristic write and determine whether the callback ordering correlates with the disconnect; done means the intermittent disconnect is addressed and the notification sequence is verified.