search

weliem / blessed-android

BLESSED, a Bluetooth Low Energy (BLE) library for Android
MIT License
557 stars 119 forks source link

onCharacteristicUpdate not called after disconnect and successful reconnect #134

Closed be-bert closed 2 years ago

be-bert commented 2 years ago

Hello Weliem,

We are experiencing difficulty getting a BLE Device to resume characteristic updates after a HciStatus.CONNECTION_TIMEOUT and successful reconnect using autoConnectPeripheral.

Everything seems to get fired correctly upon reconnect. When the BLE Device is within range again, onConnectedPeripheral, followed by onServicesDiscovered is called where we set peripheral.setNotify. We just don't get calls to onCharacteristicUpdate again.

In order to get data to stream again, we typically have to disconnect, toggle bluetooth on the phone and connect again.

Everything works as intended with the BLE Device with iOS.

Any ideas on what we could try or could be causing issues? Thanks!

weliem commented 2 years ago

Difficult to say what it could be. If the device really sends a notification, there is not much that can go wrong as long as the callback is registered. This library is basically 'passthrough' in this respect.

Can you share a log? Maybe that contains some clues.

be-bert commented 2 years ago

Hi Weliem,

Thanks for your help.

Here are the logs. Nothing seems off, but I don't know.

This happens when I unplug the peripheral. I assume it's the same when walking out of range since the same behavior happens, but I haven't captured those logs.

Is there a way to tell if the peripheral really sends a notification? Im not sure why it would work on iOS.

I can see that the peripheral is connected by an indicator on the peripheral itself, and it does not show up when I scan from another phone.

2022-02-10 09:11:36.530 7748-7748/com.app.app W/systems.myvolt: Verification of void com.welie.blessed.BluetoothPeripheral.<init>(android.content.Context, android.bluetooth.BluetoothDevice, com.welie.blessed.BluetoothPeripheral$InternalCallback, com.welie.blessed.BluetoothPeripheralCallback, android.os.Handler, com.welie.blessed.Transport) took 146.967ms (932.18 bytecodes/s) (5664B approximate peak alloc)
2022-02-10 09:11:36.784 7748-7748/com.app.app W/systems.myvolt: Verification of void com.welie.blessed.BluetoothPeripheral.handleBondStateChange(int, int) took 188.013ms (1212.68 bytecodes/s) (6408B approximate peak alloc)
2022-02-10 09:11:37.757 7748-7748/com.app.app D/BluetoothCentralManager: peripheral with address '04:91:62:65:A1:55' not in Bluetooth cache, autoconnecting by scanning
2022-02-10 09:11:37.780 7748-7748/com.app.app D/BluetoothCentralManager: started scanning to autoconnect peripherals (1)
2022-02-10 09:11:38.605 7748-7748/com.app.app D/BluetoothCentralManager: peripheral with address '04:91:62:65:A1:55' found
2022-02-10 09:11:38.611 7748-7748/com.app.app I/BluetoothCentralManager: autoscan stopped
2022-02-10 09:11:38.767 7748-7748/com.app.app I/BluetoothPeripheral: connect to 'VPS-A155' (04:91:62:65:A1:55) using transport LE
2022-02-10 09:11:38.830 7748-7748/com.app.app I/BluetoothPeripheral: peripheral '04:91:62:65:A1:55' is connecting
2022-02-10 09:11:38.834 7748-7748/com.app.app D/BluetoothGatt: connect() - device: 04:91:62:65:A1:55, auto: false
2022-02-10 09:11:38.834 7748-7748/com.app.app D/BluetoothGatt: registerApp()
2022-02-10 09:11:38.835 7748-7748/com.app.app D/BluetoothGatt: registerApp() - UUID=247ee4e5-a858-4bbe-a3a2-4357e5ae590b
2022-02-10 09:11:38.840 7748-7767/com.app.app D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
2022-02-10 09:11:38.948 7748-7767/com.app.app D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=04:91:62:65:A1:55
2022-02-10 09:11:38.959 7748-7767/com.app.app I/BluetoothPeripheral: connected to 'VPS-A155' (NONE) in 0.2s
2022-02-10 09:11:38.968 7748-7748/com.app.app D/BluetoothPeripheral: discovering services of 'VPS-A155' with delay of 0 ms
2022-02-10 09:11:38.968 7748-7748/com.app.app D/BluetoothGatt: discoverServices() - device: 04:91:62:65:A1:55
2022-02-10 09:11:39.395 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=6 latency=0 timeout=500 status=0
2022-02-10 09:11:39.418 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-02-10 09:11:39.650 7748-7767/com.app.app D/BluetoothGatt: onSearchComplete() = Device=04:91:62:65:A1:55 Status=0
2022-02-10 09:11:39.658 7748-7767/com.app.app I/BluetoothPeripheral: discovered 4 services for 'VPS-A155'
2022-02-10 09:11:39.663 7748-7748/com.app.app D/BluetoothHandler$centralManagerCallback: onConnectedPeripheral -- peripheral: com.welie.blessed.BluetoothPeripheral@fa325d6
2022-02-10 09:11:43.220 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=36 latency=0 timeout=500 status=0
2022-02-10 09:11:43.243 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=45.0ms latency=0 timeout=5s
2022-02-10 09:11:45.662 7748-7748/com.app.app D/BluetoothGatt: requestConnectionPriority() - params: 2
2022-02-10 09:11:45.665 7748-7748/com.app.app D/BluetoothPeripheral: requesting connection priority LOW_POWER
2022-02-10 09:11:46.178 7748-7748/com.app.app D/BluetoothPeripheral: reading characteristic <00002a00-0000-1000-8000-00805f9b34fb>
2022-02-10 09:11:46.292 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=96 latency=2 timeout=500 status=0
2022-02-10 09:11:46.302 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=120.0ms latency=2 timeout=5s
2022-02-10 09:11:46.426 7748-7748/com.app.app D/BluetoothGatt: setCharacteristicNotification() - uuid: 00035b03-58e6-07dd-021a-08123a000301 enable: true
2022-02-10 09:11:46.613 7748-7748/com.app.app D/BluetoothHandler$peripheralCallback: onNotificationStateUpdate -- peripheral: VPS-A155 haracteristic: android.bluetooth.BluetoothGattCharacteristic@703c962, status: SUCCESS
2022-02-10 09:11:46.630 7748-7748/com.app.app D/BluetoothPeripheral: reading characteristic <00002a25-0000-1000-8000-00805f9b34fb>
2022-02-10 09:11:46.640 7748-7748/com.app.app D/BluetoothHandler: connectedPeripheral: com.welie.blessed.BluetoothPeripheral@fa325d6
2022-02-10 09:11:46.646 7748-7748/com.app.app D/BluetoothHandler: connectedPeripheral: com.welie.blessed.BluetoothPeripheral@fa325d6
2022-02-10 09:11:46.778 7748-7748/com.app.app D/BluetoothGatt: requestConnectionPriority() - params: 2
2022-02-10 09:11:46.782 7748-7748/com.app.app D/BluetoothPeripheral: requesting connection priority LOW_POWER
2022-02-10 09:11:47.306 7748-7748/com.app.app D/BluetoothPeripheral: writing <555502fe0404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:11:47.494 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@fa325d6, value: [0x55, 0x55, 0x02, 0xFE, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@703c962, status: SUCCESS
2022-02-10 09:11:47.502 7748-7748/com.app.app D/BluetoothPeripheral: writing <555503fd0404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:11:47.781 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@fa325d6, value: [0x55, 0x55, 0x03, 0xFD, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@703c962, status: SUCCESS
2022-02-10 09:11:47.787 7748-7748/com.app.app D/BluetoothPeripheral: writing <55550601f90404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:11:48.032 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@fa325d6, value: [0x55, 0x55, 0x06, 0x01, 0xF9, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@703c962, status: SUCCESS
2022-02-10 09:11:48.440 7748-7845/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=96 latency=2 timeout=500 status=0
2022-02-10 09:11:48.443 7748-7845/com.app.app D/BluetoothPeripheral: connection parameters: interval=120.0ms latency=2 timeout=5s
2022-02-10 09:12:01.148 7748-7767/com.app.app D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=9 device=04:91:62:65:A1:55
2022-02-10 09:12:01.156 7748-7767/com.app.app I/BluetoothPeripheral: peripheral 'VPS-A155' disconnected with status 'CONNECTION_TIMEOUT' (8)
2022-02-10 09:12:01.156 7748-7767/com.app.app D/BluetoothGatt: close()
2022-02-10 09:12:01.156 7748-7767/com.app.app D/BluetoothGatt: unregisterApp() - mClientIf=9
2022-02-10 09:12:01.184 7748-7748/com.app.app D/BluetoothHandler$centralManagerCallback: onDisconnectedPeripheral -- peripheral: com.welie.blessed.BluetoothPeripheral@fa325d6, status: CONNECTION_TIMEOUT
2022-02-10 09:12:01.207 7748-7748/com.app.app I/BluetoothPeripheral: autoConnect to 'VPS-A155' (04:91:62:65:A1:55) using transport LE
2022-02-10 09:12:01.217 7748-7748/com.app.app D/BluetoothGatt: connect() - device: 04:91:62:65:A1:55, auto: true
2022-02-10 09:12:01.217 7748-7748/com.app.app D/BluetoothGatt: registerApp()
2022-02-10 09:12:01.218 7748-7748/com.app.app D/BluetoothGatt: registerApp() - UUID=da24cd9f-d75a-4b92-98aa-7a445194d058
2022-02-10 09:12:01.220 7748-7767/com.app.app D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
2022-02-10 09:12:01.220 7748-7748/com.app.app I/BluetoothPeripheral: peripheral '04:91:62:65:A1:55' is connecting
2022-02-10 09:12:18.062 7748-7767/com.app.app D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=04:91:62:65:A1:55
2022-02-10 09:12:18.072 7748-7767/com.app.app I/BluetoothPeripheral: connected to 'VPS-A155' (NONE) in 16.9s
2022-02-10 09:12:18.077 7748-7748/com.app.app D/BluetoothPeripheral: discovering services of 'VPS-A155' with delay of 0 ms
2022-02-10 09:12:18.078 7748-7748/com.app.app D/BluetoothGatt: discoverServices() - device: 04:91:62:65:A1:55
2022-02-10 09:12:18.554 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=6 latency=0 timeout=500 status=0
2022-02-10 09:12:18.559 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-02-10 09:12:18.801 7748-7767/com.app.app D/BluetoothGatt: onSearchComplete() = Device=04:91:62:65:A1:55 Status=0
2022-02-10 09:12:18.808 7748-7767/com.app.app I/BluetoothPeripheral: discovered 4 services for 'VPS-A155'
2022-02-10 09:12:18.812 7748-7748/com.app.app D/BluetoothHandler$centralManagerCallback: onConnectedPeripheral -- peripheral: com.welie.blessed.BluetoothPeripheral@a595dd2
2022-02-10 09:12:18.830 7748-7748/com.app.app D/BluetoothGatt: requestConnectionPriority() - params: 2
2022-02-10 09:12:18.834 7748-7748/com.app.app D/BluetoothPeripheral: requesting connection priority LOW_POWER
2022-02-10 09:12:18.861 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=36 latency=0 timeout=500 status=0
2022-02-10 09:12:18.865 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=45.0ms latency=0 timeout=5s
2022-02-10 09:12:19.343 7748-7748/com.app.app D/BluetoothPeripheral: reading characteristic <00002a00-0000-1000-8000-00805f9b34fb>
2022-02-10 09:12:19.403 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=96 latency=2 timeout=500 status=0
2022-02-10 09:12:19.407 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=120.0ms latency=2 timeout=5s
2022-02-10 09:12:19.656 7748-7748/com.app.app D/BluetoothGatt: setCharacteristicNotification() - uuid: 00035b03-58e6-07dd-021a-08123a000301 enable: true
2022-02-10 09:12:19.907 7748-7748/com.app.app D/BluetoothHandler$peripheralCallback: onNotificationStateUpdate -- peripheral: VPS-A155 haracteristic: android.bluetooth.BluetoothGattCharacteristic@8a3b559, status: SUCCESS
2022-02-10 09:12:19.913 7748-7748/com.app.app D/BluetoothPeripheral: reading characteristic <00002a25-0000-1000-8000-00805f9b34fb>
2022-02-10 09:12:19.916 7748-7748/com.app.app D/BluetoothHandler: connectedPeripheral: com.welie.blessed.BluetoothPeripheral@a595dd2
2022-02-10 09:12:19.922 7748-7748/com.app.app D/BluetoothHandler: connectedPeripheral: com.welie.blessed.BluetoothPeripheral@a595dd2
2022-02-10 09:12:20.139 7748-7748/com.app.app D/BluetoothGatt: requestConnectionPriority() - params: 2
2022-02-10 09:12:20.142 7748-7748/com.app.app D/BluetoothPeripheral: requesting connection priority LOW_POWER
2022-02-10 09:12:20.650 7748-7748/com.app.app D/BluetoothPeripheral: writing <555502fe0404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:12:20.850 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@a595dd2, value: [0x55, 0x55, 0x02, 0xFE, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@8a3b559, status: SUCCESS
2022-02-10 09:12:20.853 7748-7748/com.app.app D/BluetoothPeripheral: writing <555503fd0404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:12:21.093 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@a595dd2, value: [0x55, 0x55, 0x03, 0xFD, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@8a3b559, status: SUCCESS
2022-02-10 09:12:21.097 7748-7748/com.app.app D/BluetoothPeripheral: writing <55550601f90404> to characteristic <00035b03-58e6-07dd-021a-08123a000301>
2022-02-10 09:12:21.335 7748-7748/com.app.app V/BluetoothHandler$peripheralCallback: onCharacteristicWrite -- peripheral: #com.welie.blessed.BluetoothPeripheral@a595dd2, value: [0x55, 0x55, 0x06, 0x01, 0xF9, 0x04, 0x04], characteristic: android.bluetooth.BluetoothGattCharacteristic@8a3b559, status: SUCCESS
2022-02-10 09:12:21.811 7748-7767/com.app.app D/BluetoothGatt: onConnectionUpdated() - Device=04:91:62:65:A1:55 interval=96 latency=2 timeout=500 status=0
2022-02-10 09:12:21.816 7748-7767/com.app.app D/BluetoothPeripheral: connection parameters: interval=120.0ms latency=2 timeout=5s
weliem commented 2 years ago

Yeah, that all looks totally fine.

You could try to capture a HCI snoop log to see if a notification was really received.

But if it was received by Android, you should have received it. This library does do anything regarding notifications once they are enabled.

Does it occasionally happen or every time?

be-bert commented 2 years ago

Yeah it happens every time.

How would I capture a HCI snoop log?

be-bert commented 2 years ago

Once it connects again, we send some data to the device to reboot it. Once it reboots, we auto connect again and then data resumes streaming.

Another strange thing is on a Samsung S9 with Android 10, we get the callback for onConnectedPeripheral but the peripheral doesn't show up as connected at all. This again requires a bluetooth toggle and sometimes a bluetooth module power cycle.

weliem commented 2 years ago

I see you immediately issue an autoconnect when the disconnect happens. Can you try waiting 10 seconds when the disconnect happens, before issueing the autoconnect? I always do that in my apps.

I have seen before that on some phones, it takes time for the phone to process the disconnection. Especially on Samsung phones....

be-bert commented 2 years ago

So far no luck with the 10 second wait. I don't know. Perhaps it has something to do with the bluetooth module itself.

weliem commented 2 years ago

...it could indeed be an issue with the peripheral. I don't see this behaviour with the peripherals I use daily.

If possible, try to talk to the firmware engineer.

be-bert commented 2 years ago

Thanks for all your help Weliem! I appreciate it. I'll close this as it doesn't seem to be an issue with the library.