search

capacitor-community / bluetooth-le

Capacitor plugin for Bluetooth Low Energy
MIT License
274 stars 80 forks source link

Sporadic 'Writing characteristic failed' on BleClient.write() #253

Closed ASHBAW closed 2 years ago

ASHBAW commented 2 years ago

Hello, thank you for the creation and support of this plugin.

I have a ionic cordova application I ported to capacitor. The app does continuous BleClient.write()s with the expected result to come from an indication.

What I am seeing with this plugin is sporadic 'Writing characteristic failed' from the BleClient.write(). The app might be able to do writes and get the associated indication back for say 5 minutes before this error occurs. The next time it might run for 10 seconds before the error occurs.

Below is what I have captured in Android Studio.

GOOD CASE
File: http://localhost/main.js - Line 2114 - Msg: WRITE
V/Capacitor/Plugin: To native (Capacitor plugin): callbackId: 63189254, pluginId: BluetoothLe, methodName: write
V/Capacitor: callback: 63189254, pluginId: BluetoothLe, methodName: write, methodData: {"deviceId":"CC:3B:3E:81:45:6B","service":"832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1","characteristic":"737bea54-d3c5-11e4-b9d6-1681e6b88ec1","value":"2b 01 01 0b 00 04 00 00 00 00"}
D/Device: resolve: write|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|737bea54-d3c5-11e4-b9d6-1681e6b88ec1 Characteristic successfully written.
I/Capacitor/Console: File: http://localhost/ - Line 204 - Msg: undefined
V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|93c7a770-ddff-11e4-b9d6-1681e6b88ec1
I/Capacitor/Console: File: http://localhost/main.js - Line 2191 - Msg: rx [0x2b,0x00,0x01,0x01,0x0b,0x00,0x04,0x00,0x00,0x00,0x00]
I/Capacitor/Console: File: http://localhost/main.js - Line 2191 - Msg: tx [0x2b,0x01,0x01,0x0b,0x00,0x04,0x00,0x00,0x00,0x00]
BAD CASE
File: http://localhost/main.js - Line 2114 - Msg:-WRITE
V/Capacitor/Plugin: To native (Capacitor plugin): callbackId: 63189255, pluginId: BluetoothLe, methodName: write
V/Capacitor: callback: 63189255, pluginId: BluetoothLe, methodName: write, methodData: {"deviceId":"CC:3B:3E:81:45:6B","service":"832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1","characteristic":"737bea54-d3c5-11e4-b9d6-1681e6b88ec1","value":"2b 01 01 0b 00 04 00 00 00 00"}
D/Device: reject: write|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|737bea54-d3c5-11e4-b9d6-1681e6b88ec1 Writing characteristic failed.
D/Capacitor: Sending plugin error: {"save":false,"callbackId":"63189255","pluginId":"BluetoothLe","methodName":"write","success":false,"error":{"message":"Writing characteristic failed."}}
D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=CC:3B:3E:81:45:6B
V/Capacitor/BluetoothLe: Notifying listeners for event disconnected|CC:3B:3E:81:45:6B
D/Capacitor/BluetoothLe: No listeners found for event disconnected|CC:3B:3E:81:45:6B
D/BluetoothGatt: close()
    unregisterApp() - mClientIf=9
D/Device: Disconnected from GATT server.
W/Device: Resolve callback not registered for key: disconnect

For whatever reason I do not see this issue with the cordova plugin.

What are some potential causes behind 'Writing characteristic failed.'? Is there anything I can check or look into?

Thanks for any insight.

ASHBAW commented 2 years ago

Just a little more information. I have been running my app within Xcode on an iPhone for about an hour and have not seen the issue. So what I am seeing seems to be only on Android.

ASHBAW commented 2 years ago

Here is another capture. 

GOOD CASE
2021-12-02 07:33:49.694 13659-13659/com.test I/Capacitor/Console: File: http://localhost/ - Line 204 - Msg: undefined
2021-12-02 07:33:49.762 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|c73f5580-91eb-11e5-8994-feff819cdc9f
2021-12-02 07:33:50.295 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|93c7a770-ddff-11e4-b9d6-1681e6b88ec1
2021-12-02 07:33:50.301 13659-13659/com.test I/Capacitor/Console: File: http://localhost/main.js - Line 2194 - Msg: rx [0x2b,0x00,0x01,0x01,0x0b,0x00,0x04,0x00,0x00,0x00,0x00]
2021-12-02 07:33:50.780 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|c73f5580-91eb-11e5-8994-feff819cdc9f
2021-12-02 07:33:51.797 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|c73f5580-91eb-11e5-8994-feff819cdc9f
2021-12-02 07:33:52.335 13659-13659/com.test I/Capacitor/Console: File: http://localhost/main.js - Line 2194 - Msg: tx [0x2b,0x01,0x01,0x0b,0x00,0x04,0x00,0x00,0x00,0x00]
2021-12-02 07:33:52.338 13659-13779/com.test V/Capacitor/Plugin: To native (Capacitor plugin): callbackId: 63381312, pluginId: BluetoothLe, methodName: write
2021-12-02 07:33:52.338 13659-13779/com.test V/Capacitor: callback: 63381312, pluginId: BluetoothLe, methodName: write, methodData: {"deviceId":"CC:3B:3E:81:45:6B","service":"832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1","characteristic":"737bea54-d3c5-11e4-b9d6-1681e6b88ec1","value":"2b 01 01 0b 00 04 00 00 00 00"}
2021-12-02 07:33:52.777 13659-13773/com.test D/Device: resolve: write|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|737bea54-d3c5-11e4-b9d6-1681e6b88ec1 Characteristic successfully written.

BAD CASE
2021-12-02 07:33:52.783 13659-13659/com.test I/Capacitor/Console: File: http://localhost/ - Line 204 - Msg: undefined
2021-12-02 07:33:52.827 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|c73f5580-91eb-11e5-8994-feff819cdc9f
2021-12-02 07:33:53.589 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event notification|CC:3B:3E:81:45:6B|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|93c7a770-ddff-11e4-b9d6-1681e6b88ec1
2021-12-02 07:33:53.593 13659-13659/com.test I/Capacitor/Console: File: http://localhost/main.js - Line 2194 - Msg: rx [0x2b,0x00,0x01,0x01,0x0b,0x00,0x04,0x00,0x00,0x00,0x00]
2021-12-02 07:33:54.758 13659-13659/com.test I/Capacitor/Console: File: http://localhost/main.js - Line 2194 - Msg: tx [0x2b,0x01,0x01,0x03,0x00,0x04,0x00,0x00,0x00,0x00]
2021-12-02 07:33:54.761 13659-13779/com.test V/Capacitor/Plugin: To native (Capacitor plugin): callbackId: 63381313, pluginId: BluetoothLe, methodName: write
2021-12-02 07:33:54.762 13659-13779/com.test V/Capacitor: callback: 63381313, pluginId: BluetoothLe, methodName: write, methodData: {"deviceId":"CC:3B:3E:81:45:6B","service":"832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1","characteristic":"737bea54-d3c5-11e4-b9d6-1681e6b88ec1","value":"2b 01 01 03 00 04 00 00 00 00"}
2021-12-02 07:33:59.697 2335-3074/? W/bt_stack: [WARNING:btif_bqr.cc(390)] Appro LSTO , Handle: 0x0008, NULL, Central, PwLv: 9, RSSI: -81, SNR: 0, UnusedCh: 61, UnidealCh: 4, ReTx: 0, NoRX: 0, NAK: 0, FlowOff: 0, OverFlow: 0, UndFlow: 0
2021-12-02 07:33:59.698 2335-3074/? I/bt_stack: [INFO:btsnoop.cc(338)] clear_l2cap_allowlist: Clearing acceptlist from l2cap channel. conn_handle=8 cid=4:4
2021-12-02 07:33:59.699 2335-3074/? I/bt_stack: [INFO:gatt_attr.cc(338)] gatt_connect_cback: remove untrusted client status, bda=cc:3b:3e:81:45:6b
2021-12-02 07:33:59.699 2335-3074/? I/bluetooth: system/bt/stack/gap/gap_ble.cc:298 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:45:6b callback:Disconnected
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? 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_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? I/bt_bta_gattc: system/bt/bta/gatt/bta_gattc_act.cc:1115 bta_gattc_conn_cback: Disconnected att_id:9 transport:le reason:GATT_CONN_TIMEOUT
2021-12-02 07:33:59.699 2335-3074/? W/bt_btm_sec: system/bt/stack/btm/btm_sec.cc:3685 btm_sec_disconnected: Got uncommon disconnection reason:Connection Timeout handle:0x0008
2021-12-02 07:33:59.700 2335-3074/? I/btif_av: system/bt/btif/src/btif_av.cc:3352 btif_av_acl_disconnected: btif_av_acl_disconnected: Peer cc:3b:3e:81:45:6b : ACL Disconnected
2021-12-02 07:33:59.700 2335-3074/? I/btif_av: system/bt/btif/src/btif_av.cc:1078 FindOrCreatePeer: BtifAvPeer *BtifAvSource::FindOrCreatePeer(const RawAddress &, tBTA_AV_HNDL): Create peer: peer_address=cc:3b:3e:81:45:6b bta_handle=0x41 peer_id=0
2021-12-02 07:33:59.700 2335-3074/? I/btif_av: system/bt/btif/src/btif_av.cc:3279 btif_av_get_peer_sep: No active sink or source peer found
2021-12-02 07:33:59.700 2335-3074/? I/bt_btif_a2dp_source: system/bt/btif/src/btif_a2dp_source.cc:691 btif_a2dp_source_on_idle: btif_a2dp_source_on_idle: state=STATE_OFF
2021-12-02 07:33:59.700 2335-3074/? I/btif_av: system/bt/btif/src/btif_av.cc:3279 btif_av_get_peer_sep: No active sink or source peer found
2021-12-02 07:33:59.700 2335-3074/? I/bt_btif_a2dp_source: system/bt/btif/src/btif_a2dp_source.cc:691 btif_a2dp_source_on_idle: btif_a2dp_source_on_idle: state=STATE_OFF
2021-12-02 07:33:59.700 2335-3074/? I/btif_av: system/bt/btif/src/btif_av.cc:1123 DeleteIdlePeers: DeleteIdlePeers: Deleting idle peer: cc:3b:3e:81:45:6b bta_handle=0x41
2021-12-02 07:33:59.703 13659-13773/com.test D/Device: reject: write|832ae7fe-d3c5-11e4-b9d6-1681e6b88ec1|737bea54-d3c5-11e4-b9d6-1681e6b88ec1 Writing characteristic failed.
2021-12-02 07:33:59.703 13659-13773/com.test D/Capacitor: Sending plugin error: {"save":false,"callbackId":"63381313","pluginId":"BluetoothLe","methodName":"write","success":false,"error":{"message":"Writing characteristic failed."}}
2021-12-02 07:33:59.705 13659-13773/com.test D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=CC:3B:3E:81:45:6B
2021-12-02 07:33:59.705 13659-13773/com.test V/Capacitor/BluetoothLe: Notifying listeners for event disconnected|CC:3B:3E:81:45:6B
2021-12-02 07:33:59.706 13659-13773/com.test D/Capacitor/BluetoothLe: No listeners found for event disconnected|CC:3B:3E:81:45:6B
2021-12-02 07:33:59.706 13659-13773/com.test D/BluetoothGatt: close()
2021-12-02 07:33:59.706 13659-13773/com.test D/BluetoothGatt: unregisterApp() - mClientIf=9
2021-12-02 07:33:59.707 1716-1716/? D/CompanionDeviceManagerService: CC:3B:3E:81:45:6B disconnected w/ reason: (1104) Timeout
2021-12-02 07:33:59.707 1716-1716/? D/CompanionDeviceManagerService: onDeviceDisconnected(address = CC:3B:3E:81:45:6B)
2021-12-02 07:33:59.709 13659-13773/com.test D/Device: Disconnected from GATT server.
2021-12-02 07:33:59.710 2335-3074/? I/bt_stack: [INFO:gatt_api.cc(1042)] GATT_Deregister gatt_if=9
2021-12-02 07:33:59.710 13659-13773/com.test W/Device: Resolve callback not registered for key: disconnect
2021-12-02 07:33:59.717 3638-3638/? I/Morris.CarModeRcvr: #onReceive #Intent;action=android.bluetooth.device.action.ACL_DISCONNECTED;launchFlags=0x5000010;end
2021-12-02 07:33:59.717 2351-2434/? W/BluetoothEventManager: AclStateChangedHandler: activeDevice is null
2021-12-02 07:33:59.723 3638-3638/? I/AmbBrdcstRcvrServClient: handleRefreshAction(): not handling android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.726 3638-4217/? I/BrdcstRcvrMsgr: sendMessage(): received broadcast id:21 with action:android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.734 3916-3916/? I/A: Creating pss binder().
2021-12-02 07:33:59.737 3916-4406/? I/A: Calling beginBinderSession().
2021-12-02 07:33:59.738 3916-4406/? I/A: beginBinderSession(): calling binder
2021-12-02 07:33:59.739 3638-4197/? I/BrdcstRcvrMsgr: SvcConn: messenger connected
2021-12-02 07:33:59.741 3916-4093/? I/BrdcstRcvrBProvider: handleMessage(): id:21 action:android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.742 3916-4093/? I/AmbBrdcstRcvrBProvider: receive(): android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.743 3916-4093/? I/A: handleIntent(): action:android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.746 3916-4270/? I/BrdcstRcvrBProvider: handleMessage(): DONE id:21
2021-12-02 07:33:59.747 3638-4193/? I/BrdcstRcvrMsgr: handleMessage(): id:21, DEC to 0
2021-12-02 07:33:59.748 3638-4193/? I/BrdcstRcvrMsgr: disconnect()
2021-12-02 07:33:59.749 3916-4273/? I/BistoWorker: bluetoothConnectionStateChanged. Action: android.bluetooth.device.action.ACL_DISCONNECTED
2021-12-02 07:33:59.759 2916-2916/? I/NearbyDiscovery: onAclChange: state=DISCONNECTED, device=XX:XX:XX:XX:45:6B [CONTEXT service_id=49 ]
2021-12-02 07:33:59.761 3916-4230/? E/BistoWorker: Failed to get bistoDeviceInfo
    com.google.android.apps.gsa.shared.bisto.a.cl
        at com.google.android.apps.gsa.shared.bisto.a.o.a(PG:1)
        at com.google.android.apps.gsa.shared.bisto.a.p.run(PG:2)
        at com.google.android.libraries.gsa.k.a.m.call(PG:2)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at com.google.android.libraries.i.ac.run(PG:1)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at com.google.android.libraries.i.e.run(PG:2)
        at com.google.android.libraries.i.o.run(PG:4)
        at java.lang.Thread.run(Thread.java:920)
2021-12-02 07:33:59.771 3916-4230/? I/DeviceDetector: Not bonded or not refresh cache.
2021-12-02 07:33:59.789 13659-13659/com.test I/Capacitor/Console: File: http://localhost/main.js - Line 2118 - Msg: Error: Writing characteristic failed.
2021-12-02 07:33:59.792 13659-13779/com.test V/Capacitor/Plugin: To native (Capacitor plugin): callbackId: 63381314, pluginId: BluetoothLe, methodName: removeListener
2021-12-02 07:33:59.792 13659-13659/com.test E/Capacitor/Console: File: http://localhost/main.js - Line 8096 - Msg: Error: Writing characteristic failed.
pwespi commented 2 years ago

Thanks for using this plugin.

From your logs it looks like the device disconnected shortly before the write in both cases. Could it be that the connection is unstable? (Large distance, obstacles...) So it might have nothing to do with the write itself?

You can be notified of disconnection events by providing a onDisconnect callback to the connect call, see connect.

ASHBAW commented 2 years ago

My phone is actually fairly close to our device - maybe 5 feet away direct line of sight. So I don't think that is the issue.

Why would the following be happening prior to disconnect? 

2021-12-02 07:33:59.698 2335-3074/? I/bt_stack: [INFO:btsnoop.cc(338)] clear_l2cap_allowlist: Clearing acceptlist from l2cap channel. conn_handle=8 cid=4:4
2021-12-02 07:33:59.699 2335-3074/? I/bt_stack: [INFO:gatt_attr.cc(338)] gatt_connect_cback: remove untrusted client status, bda=cc:3b:3e:81:45:6b

I have did not seen the issue with iOS. but I am going to do some more testing on iOS today.

Will adding the onDisconnect callback provide any information as to why it disconnected?

I will also try another Android device. I am currently using a Pixel 4 with API 31 (Android 12).

With our app/device we have one indication (heartbeat) and one notification. Notification occurs on write response. It is a fairly mature app and device (5 years old). The Cordova version of our app does not have this issue for whatever reason.

Any other thoughts on what debug I might be able to add to get more information?

Thanks!

pwespi commented 2 years ago

Hmm I have no idea why this Clearing acceptlist from l2cap channel and remove untrusted client status happens.

Were you able to reproduce this behavior with other devices? I'm not able to reproduce this behavior, so it's really hard to tell what's going on.

No, the onDisconnect callback will not provide any information on why it disconnected.

The logs from Android Studio are probably the best place to look for information that might help for debugging.

pwespi commented 2 years ago

Let me know if you find anything. I am unfortunately still not able to reproduce this.

ASHBAW commented 2 years ago

Thank for looking at this.

I was actually in the process of responding. I am thinking there was something up with my development environment. The plugin seems to be working well.

You can close this issue.

Thanks for your time supporting this plugin.