blessed-android-coroutines
blessed-android-coroutines copied to clipboard
weliem
Write success after 2nd connect
Hello!
I am encountering a problem and am somewhat at odds as to how to solve it.
Scenario: We have a bluetooth device that has been tried and tested. This year I wrote a new android app to connect to the device. Since we were often plagued with 133 errors I decided to give this library a try.
My problem: If the Bluetoothdevice does a fresh boot and I try to write a characteristic then it does nothing. But it does not even throw an error. Even android's own BluetoothGatt write call returns status=0 ( whatever that is worth with writetype=NO_RESPONSE)...
Once I disconnect, rescan, reconnect to the device I can write without any problems until the bluetooth device gets bootet again.
I used the BluetoothHandler class from the examples. And since it is a singleton I really don't understand why it only works the second time around.
I tested this by added a writeCharacteristic to the handlePeripheral() method so that after a connection is made we can send some data and directly know if the device gets the data. And like I said, after the second connection the data always gets transmitted.
Anyone have a clue as to what is going on here? Or how I could try to further debug this situation?
Running this on a Samsung A20e phone
Greetings
Sure.
2022-08-01 11:01:44.720 27020-27020/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:01:44.720 27020-27020/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:01:44.721 27020-27020/com.myapp D/BluetoothLeScanner: Start Scan with callback
2022-08-01 11:01:44.724 27020-31927/com.myapp D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=8 mScannerId=0
2022-08-01 11:01:44.730 27020-27020/com.myapp I/BluetoothCentralManager: scan started
2022-08-01 11:01:44.877 27020-804/com.myapp I/BluetoothConnectionHandler$connectBySerialId: Found peripheral '00S0' with RSSI -54
2022-08-01 11:01:44.878 27020-804/com.myapp I/BluetoothConnectionHandler$connectBySerialId: connecting
2022-08-01 11:01:44.879 27020-804/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:01:44.879 27020-804/com.myapp D/BluetoothLeScanner: Stop Scan with callback
2022-08-01 11:01:44.885 27020-804/com.myapp I/BluetoothCentralManager: scan stopped
2022-08-01 11:01:44.887 27020-804/com.myapp I/BluetoothConnectionHandler$connectBySerialId: Connecting to peripheral
2022-08-01 11:01:44.893 27020-804/com.myapp D/BluetoothPeripheral: autoConnect to '000S0' (5C:F3:70:96:17:48) using TRANSPORT_LE
2022-08-01 11:01:44.897 27020-804/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:01:44.899 27020-804/com.myapp D/BluetoothGatt: connect() - device: 5C:F3:70:96:17:48, auto: true
2022-08-01 11:01:44.899 27020-804/com.myapp I/BluetoothAdapter: isSecureModeEnabled
2022-08-01 11:01:44.900 27020-804/com.myapp D/BluetoothGatt: registerApp()
2022-08-01 11:01:44.900 27020-804/com.myapp D/BluetoothGatt: registerApp() - UUID=171011c8-93a1-4418-931e-5f06d7fa3fbb
2022-08-01 11:01:44.904 27020-31927/com.myapp D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
2022-08-01 11:01:44.969 27020-31927/com.myapp D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=5C:F3:70:96:17:48
2022-08-01 11:01:44.978 27020-31927/com.myapp D/BluetoothPeripheral: connected to '000S0' (BONDED) in 0,1s
2022-08-01 11:01:44.981 27020-804/com.myapp D/BluetoothPeripheral: discovering services of '000S0'
2022-08-01 11:01:44.981 27020-804/com.myapp D/BluetoothGatt: discoverServices() - device: 5C:F3:70:96:17:48
2022-08-01 11:01:44.985 27020-31927/com.myapp D/BluetoothGatt: onSearchComplete() = Device=5C:F3:70:96:17:48 Status=0
2022-08-01 11:01:44.990 27020-31927/com.myapp D/BluetoothPeripheral: discovered 4 services for '000S0'
2022-08-01 11:01:44.993 27020-804/com.myapp I/BluetoothConnectionHandler$observeStates: Peripheral 000S0 com.welie.blessed.BluetoothPeripheral@6b38d1 has CONNECTED
2022-08-01 11:01:44.995 27020-27020/com.myapp D/BluetoothGatt: refresh() - device: 5C:F3:70:96:17:48
2022-08-01 11:01:45.098 27020-804/com.myapp D/BluetoothGatt: requestConnectionPriority() - params: 1
2022-08-01 11:01:45.099 27020-804/com.myapp D/BluetoothPeripheral: requesting connection priority HIGH
2022-08-01 11:01:45.813 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=6 latency=0 timeout=500 status=0
2022-08-01 11:01:45.814 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-08-01 11:01:46.113 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=12 latency=0 timeout=500 status=0
2022-08-01 11:01:46.217 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=6 latency=0 timeout=500 status=0
2022-08-01 11:01:46.218 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-08-01 11:01:46.444 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=12 latency=0 timeout=500 status=0
2022-08-01 11:01:46.445 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=15.0ms latency=0 timeout=5s
2022-08-01 11:01:48.204 27020-804/com.myapp D/BluetoothGatt: readRssi() - device: 5C:F3:70:96:17:48
2022-08-01 11:01:49.373 27020-804/com.myapp D/BluetoothPeripheral: writing <00000000fd3f743d> to characteristic <0afc896d-de39-46f3-8c98-d9df0d4036bb>
This last command writing to the device never goes through.
At some point I read out the RSSI values (right before the write attempt) which works. Writing to the device ( last line ) works only if I close the connection ( central.close() ), rescan and reconnect.
Just for the sake of completion this is the log output I get on a connection where the writing works. Just like all further connections until the target device is rebootet again:
2022-08-01 11:22:15.001 27020-27020/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:22:15.002 27020-27020/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:22:15.002 27020-27020/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:22:15.004 27020-27020/com.myapp D/BluetoothLeScanner: Start Scan with callback
2022-08-01 11:22:15.007 27020-31927/com.myapp D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
2022-08-01 11:22:15.013 27020-27020/com.myapp I/BluetoothCentralManager: scan started
2022-08-01 11:22:15.315 27020-803/com.myapp I/BluetoothConnectionHandler$connectBySerialId: Found peripheral '000S0' with RSSI -51
2022-08-01 11:22:15.317 27020-803/com.myapp I/BluetoothConnectionHandler$connectBySerialId: connecting
2022-08-01 11:22:15.317 27020-803/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:22:15.318 27020-803/com.myapp D/BluetoothLeScanner: Stop Scan with callback
2022-08-01 11:22:15.322 27020-803/com.myapp I/BluetoothCentralManager: scan stopped
2022-08-01 11:22:15.324 27020-803/com.myapp I/BluetoothConnectionHandler$connectBySerialId: Connecting to peripheral
2022-08-01 11:22:15.333 27020-803/com.myapp D/BluetoothPeripheral: autoConnect to '000S0' (5C:F3:70:96:17:48) using TRANSPORT_LE
2022-08-01 11:22:15.336 27020-803/com.myapp I/BluetoothAdapter: STATE_ON
2022-08-01 11:22:15.340 27020-803/com.myapp D/BluetoothGatt: connect() - device: 5C:F3:70:96:17:48, auto: true
2022-08-01 11:22:15.340 27020-803/com.myapp I/BluetoothAdapter: isSecureModeEnabled
2022-08-01 11:22:15.341 27020-803/com.myapp D/BluetoothGatt: registerApp()
2022-08-01 11:22:15.341 27020-803/com.myapp D/BluetoothGatt: registerApp() - UUID=84189c2f-3ed9-41e6-a352-2854436558cf
2022-08-01 11:22:15.345 27020-31927/com.myapp D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2022-08-01 11:22:15.452 27020-31927/com.myapp D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=5C:F3:70:96:17:48
2022-08-01 11:22:15.459 27020-31927/com.myapp D/BluetoothPeripheral: connected to '000S0' (BONDED) in 0,1s
2022-08-01 11:22:15.461 27020-803/com.myapp D/BluetoothPeripheral: discovering services of '000S0'
2022-08-01 11:22:15.461 27020-803/com.myapp D/BluetoothGatt: discoverServices() - device: 5C:F3:70:96:17:48
2022-08-01 11:22:15.468 27020-31927/com.myapp D/BluetoothGatt: onSearchComplete() = Device=5C:F3:70:96:17:48 Status=0
2022-08-01 11:22:15.471 27020-31927/com.myapp D/BluetoothPeripheral: discovered 4 services for '000S0'
2022-08-01 11:22:15.475 27020-803/com.myapp I/BluetoothConnectionHandler$observeStates: Peripheral 000S0 com.welie.blessed.BluetoothPeripheral@b5cd75d has CONNECTED
2022-08-01 11:22:15.476 27020-27020/com.myapp D/BluetoothGatt: refresh() - device: 5C:F3:70:96:17:48
2022-08-01 11:22:15.579 27020-803/com.myapp D/BluetoothGatt: requestConnectionPriority() - params: 1
2022-08-01 11:22:15.581 27020-803/com.myapp D/BluetoothPeripheral: requesting connection priority HIGH
2022-08-01 11:22:16.292 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=6 latency=0 timeout=500 status=0
2022-08-01 11:22:16.295 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-08-01 11:22:16.499 27020-27020/com.myapp D/BluetoothGatt: refresh() - device: 5C:F3:70:96:17:48
2022-08-01 11:22:16.577 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=12 latency=0 timeout=500 status=0
2022-08-01 11:22:16.578 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=15.0ms latency=0 timeout=5s
2022-08-01 11:22:16.682 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=6 latency=0 timeout=500 status=0
2022-08-01 11:22:16.683 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2022-08-01 11:22:17.006 27020-27020/com.myapp D/DecorView: semSetRoundedCorners: 5
2022-08-01 11:22:17.013 27020-31927/com.myapp D/BluetoothGatt: onConnectionUpdated() - Device=5C:F3:70:96:17:48 interval=12 latency=0 timeout=500 status=0
2022-08-01 11:22:17.014 27020-31927/com.myapp D/BluetoothPeripheral: connection parameters: interval=15.0ms latency=0 timeout=5s
2022-08-01 11:22:18.532 27020-803/com.myapp D/BluetoothPeripheral: writing <00000000ce0ea3bc> to characteristic <0afc896d-de39-46
``
I started observing successful writes to a freshly booted bluetooth device. These are random and not reproducible, so this could be some kind of timing problem.
I am not sure, but the 'refresh' you are doing might be the problem. It clears the gatt cache and hence you create a race condition for the write.
Anyway, try reducing you code to the basics. Don't do the refresh, don't do the connection settings etc....until only the write is left
I did get like a 40% success rate after trying to clear the cache 2-3 seconds after connection. Which is not great but a whole lot better than not being able to write at all. But I am not able to connect the dots here as to what could cause this.
I am not sure, but the 'refresh' you are doing might be the problem. It clears the gatt cache and hence you create a race condition for the write.
I agree, there is a lot happening at once. Reducing the code to the bare minimum but not seeing any positive effects.
Maybe I am overlooking something so I will copy&paste the code here:
fun connectBySerialId(serialId: String, lifecycle: LifecycleCoroutineScope, context: Context) {
Timber.d("Scanning for devices with name $serialId")
central = BluetoothCentralManager(context)
central.enableLogging()
observeStates(lifecycle)
central.scanForPeripheralsWithNames(arrayOf(serialId),
{ peripheral, scanResult ->
Timber.i("Found peripheral '${peripheral.name}' with RSSI ${scanResult.rssi}")
if (isConnecting) return@scanForPeripheralsWithNames // Avoid multiple connects
//Signal Connection is in progress and stop scan
isConnecting = true
central.stopScan()
// Check for bond state and bond
if (peripheral.bondState == BondState.NONE) {
Timber.i("Creating bond")
peripheral.createBond()
} else { // Connect to device
Timber.i("Connecting to peripheral")
central.autoConnectPeripheral(peripheral)
}
},
{ scanFailure -> Timber.e("scan failed: $scanFailure") }
)
}
suspend fun writeDataToRCUnit(payload : ByteArray) {
if(isConnected) {
try {
central.getConnectedPeripherals().forEach {
Timber.i("Writing Payload to device.")
it.writeCharacteristic(SERVICE_UUID, CHARACTERISTIC_UUID, payload, WriteType.WITHOUT_RESPONSE)
}
}catch (e: Exception) {
Timber.e("Could not write to device! ${e.message}")
e.printStackTrace()
}
}
}
suspend fun disconnectDevice() {
Timber.e("Disconnecting device: $currentDevice")
isConnecting = false
isConnected = false
try {
central.getConnectedPeripherals().forEach {
central.cancelConnection(it)
}
central.close()
}catch (e: Exception) {
e.printStackTrace()
}
}
Like I said, calling disconnectDevice followed by connectBySerialId always works. This is driving me nuts :crab:
what do you if you put breakpoints in the writeCharacteristic function? Where does it fail?
I cannot see the write call failing anywhere.
GattStatus is SUCCESS
Inside BluetoothPeripheral.kt:914
if (bluetoothGatt?.writeCharacteristic(characteristic) == true) {
This also returns TRUE.
Everything looks like the data should have been sent but the device does not log any received data.
I enabled Bluetooth HCI snoop log to get a lower level sense of what is failing...
There is a Warning about Invalid usage of this characteristic with this opcode when writing to the characteristic.
This is how it should look like on a successful write:
Not too sure about length too short but the warning about the handle seems to fit the picture as refreshing the service cache tends to sometimes fix the problem.
Inside the writeCharacteristic method of BluetoothPeriperal.kt I can see the correct Characteristic is being used:
In your first screenshot (with the error) witeshark thinks you are writing to the CCC descriptor (2902). I guess that is wrong? ...because in the second screenshot it doesn't say that. So it looks like there is something going wrong during the service discovery. But you are not doing the 'refresh' anymore, right?
Can you share another log? There shouldn't be any refresh anymore....
In your first screenshot (with the error) witeshark thinks you are writing to the CCC descriptor (2902). I guess that is wrong? ...because in the second screenshot it doesn't say that.
Yes, I have no clue where 0x2902 is coming from. But I can tell that I am getting this error every time I try to connect to the freshly booted bluetooth device. Subsequent connects work as expected.
So it looks like there is something going wrong during the service discovery.
Agreed. I tested on Motorola, Samsung and Huawei devices but they all behave the same. I tried out this BLE-Scanner App from the Playstore which lets you connect to a device and write to a characteristic that did not show this specific problem (writing was immediately possible).
But you are not doing the 'refresh' anymore, right?
Correct. But I did get better results with the refresh. I do understand how the refresh can screw things up.
BT HCI Log with 2 Connections for wireshark: bt_bug_huawei.log
First Connection is roughly at 14:50 Second Connection at 14:51
This time the write packets don't have this "apparent" error with 0x2902 but the outcome was the same.
I hacked something that works 99%....
BluetoothPeripheral.kt:successfullyConnected() clear the cache before services are searched:
Handler(Looper.getMainLooper()).postDelayed({
scope.launch {
clearServicesCache()
discoverServices()
}
}, 300)
Of course this is not a solution but it shows that something within the initial bluetoothGatt discoverServices call goes wrong.
BluetoothGatt.discoverServices() returns TRUE, throws no exception and even calls mServices.clear() beforehand.
I wonder if it has something to do with the way the bluetooth device does its advertising. I can tell by the logs that there are way more advertisements received during the first scan than during the second.
Sooo this shouldn't be a problem within the blessed lib I guess.
Ok, but why do you call clearServicesCache at all? I never use it. It is only needed when you do a firmware update where the services/characteristics change....
If you use it. You need to call it before connecting or just before disconnecting. It basically erases all discovered services and characteristics. What you do is almost correct but keep in mind that clearServicesCache and discoverServices are asynchronous....better to add a delay between them. ....but even better is to do it before connecting and let the existing code be....
Ok, but why do you call clearServicesCache at all?
I looked into my initial native android BLE implementation (based on nordic semiconductor) and found this call (probably due to a similar/same issue) so I tried it out. Since it yielded some kind of progress I probed it further. As you say it should only be called when characteristics change. But the Bluetooth device is rather static and has no incentive to change so it should not be necessary.
If you use it. You need to call it before connecting or just before disconnecting.
Good point. But clearServicesCache() relies on a connected bluetoothGatt so calling it before or after the connection (to the gatt) does not make sense to me.
suspend fun clearServicesCache(): Boolean {
if (bluetoothGatt == null) return false
var result = false
try {
val refreshMethod = bluetoothGatt?.javaClass?.getMethod("refresh")
if (refreshMethod != null) {
result = refreshMethod.invoke(bluetoothGatt) as Boolean
}
} catch (e: Exception) {
Logger.e(TAG, "could not invoke refresh method")
}
delay(100)
return result
}
I call it after the connection but before discovering services which seems to work. Kindly correct me if I got this wrong :)
Since 3rd party BLE apps could write directly, I assumed that this should work without the workaround, but maybe they also clear caches beforehand; who knows?
Anyways, I greatly appreciate the time & effort you put into this issue ❤️ . My bluetooth guy is available again next week and I will answer this topic once we figure out what is causing this.
Ah yes, you are right. You can only do clearServiceCache while being connected. So doing it before disconnecting would be the best place.
Nonetheless, I still think it should work without using clearServicesCache. It is a hidden Android API and it should not really be used. Perhaps your BLE guy has some thoughts....