Disable notifications ACK not received, trying to enable notifications throws Status -3 #48
Comments
ghost
changed the title
|
Yes, the atomic queue will complete no matter of the inner requests result. You may call As to the erro3 "Write Not Permitted", I would say it's a reply from your device? |
|
What do you mean from "Write not permitted"? The status = -3? From my debugging, FailCallback.REASON_NULL_ATTRIBUTE is thrown when a gatt operation returns false My guesses were I'll really appreciate if you have other guess/thought. I've been fighting against this for too long now, I was hoping for a library bug that explained the behavior 😢 I'll close the ticket if you don't think this is a library issue |
|
Oh, -3, not 3 :) |
|
Hi @maragues-kolibree, It should not be possible to start any request before the previous operation is completed. If you indeed managed to do this, that's a bug in the library. |
|
Here are some more logs. For reference, this is a method I call writeAndNotify /**
* Blocking call that writes to a characteristic and waits until the response is emitted in a
* characteristic notification.
*
* If the command doesn't receive a response in OPERATION_TIMEOUT_MS it throws a FailureReason
* If the response to the command is not successful, it throws a CommandFailedException
*/
@Throws(FailureReason::class)
fun writeAndNotifyOperation(
gattCharacteristicWrite: BluetoothGattCharacteristic?,
payload: ByteArray
): ByteArray {
if (gattCharacteristicWrite == null) throw FailureReason("Can't write on a null characteristic")
val responseCharacteristic = mapToResponseCharacteristic(gattCharacteristicWrite)
try {
val responseContainer = object : ProfileReadResponse() {}
Timber.d("writeAndNotifyOperation command id ${payload.first().toHex()}")
waitForNotification(responseCharacteristic)
.trigger(writeCharacteristic(gattCharacteristicWrite, payload))
.timeout(OPERATION_TIMEOUT_MS)
.awaitValid(responseContainer)
val response = responseContainer.rawData.value ?: byteArrayOf()
throwIfNonSuccessResponse(response, payload)
return response
} catch (exception: Exception) {
...
}
}What usually happens is
If a sensor emits multiple states, I might call this sequence multiple times. Logs for a successful invocation Two logs for failure invocations. Both writeAndNotify fail to show the
It's not happening all the time, maybe 1 out of 10. Furthermore, I wasn't able to reproduce the issue when I commented out the invocation to writeAndNotify, so something's going on in there.
Let me know if I can provide any more details. Thanks for your time! |
|
Let's start with the easy: To make your How do you wait fo the sensor to emit new state? What do you do then? Do you have the source on github, or somewhere I could have a look? |
|
Ok, I've created a override fun onDataReceived(device: BluetoothDevice, data: Data) {
super.onDataReceived(device, data)
if (!validateActionCommandResponse()) {
onInvalidDataReceived(device, data)
}
}I don't think this changes anything on this issue tho, I just reproduced it and the On the how do I wait for the sensor, it's quite convoluted and I'm afraid I'm not allowed to share the code. I'll try to summarize it
BleManagerGattCallback {
...
override fun initialize() {
super.initialize()
klEnableNotificationsRequest(...).enqueue()
}
}
fun klEnableNotificationsRequest(gattCharacteristic: BluetoothGattCharacteristic?): WriteRequest {
if (gattCharacteristic == null) throw FailureReason("Can't write on a null characteristic")
return enableNotifications(gattCharacteristic)
.before {
setNotificationCallback(gattCharacteristic)
.with { _, data ->
onCharacteristicDataReceived(gattCharacteristic, data)
}
}
} I wonder if there's a better way to do this
internal interface KLManagerCallbacks : BleManagerCallbacks {
fun onNotify(uuid: String, value: ByteArray?)
}
fun onCharacteristicDataReceived(
gattCharacteristic: BluetoothGattCharacteristic,
data: Data
) {
mCallbacks.onNotify(gattCharacteristic.uuid.toString(), data.value)
}
@Override
public void onNotify(@NonNull String uuid, @Nullable byte[] value) {
if (value == null) {
return;
}
if (MY_CHAR.equals(uuid)) {
final PayloadReader payload = new PayloadReader(value);
//detect the appropriate listener
switch (...) {
case ...:
boolean isEnabled = ...;
//call that triggers the sequence mentioned in my previous comment
listener.onSensorStateChanged(isEnabled);
break;
default:
break;
}
} else {
...
}
//notify other subscribers
bleNotificationDataRelay.accept(BleNotificationData.create(UUID.fromString(uuid), value));
}I know it's risky to invoke alien methods, but in my checks I've haven't seen onNotify blocked recently, but it's definitely a possibility that something's wrong there. It's legacy code (>4 years) and complex to refactor Maybe it'd be wiser to move this onNotify code to the main thread or to a single executor
Thanks! |
|
Could you check from where is |
|
You mean which thread? It's always the invoker thread Log for simple sequence failure, snippet of writeAndNotify I guess you already know this but just for clarification, 1173 is the main thread, and the one next to the hyphen is the thread where the log line is written. In this case, pre and post logs are written on thread 1498. |
|
No, if you put a breakpoint therein |
|
Also, the initialization could be changed to: BleManagerGattCallback {
...
override fun initialize() {
super.initialize()
setNotificationCallback(gattCharacteristic)
.with { _, data ->
onCharacteristicDataReceived(gattCharacteristic, data)
}
klEnableNotificationsRequest(...).enqueue()
}
}
fun klEnableNotificationsRequest(gattCharacteristic: BluetoothGattCharacteristic?): WriteRequest {
if (gattCharacteristic == null) throw FailureReason("Can't write on a null characteristic")
return enableNotifications(gattCharacteristic);
} No need to initialize the callback more than once, unless you need it. But that's also not important for the issue, and should work as well as you have it. |
|
Hmm.. the notification callback gets removed when you disable notifications, true. So your code is ok :) Sorry! |
|
Yeah, I had to scratch my head to get that working. I'm not getting any done/fail/invalid callback invocation on the trigger operation in writeAndNotify, I guess because of the awaitValid waitForNotification(responseCharacteristic)
.trigger(writeCharacteristic(gattCharacteristicWrite, payload)
.invalid { Timber.d("writeAndNotifyOperation invalid id ${payload.first().toHex()}") }
.done { Timber.d("writeAndNotifyOperation done id ${payload.first().toHex()}") }
.fail { _, status -> Timber.d("writeAndNotifyOperation fail id ${payload.first().toHex()} with status $status") }
)
.timeout(OPERATION_TIMEOUT_MS)
.awaitValid(response)If I add a breakpoint after awaitValid, the invoker is my code. I'll keep on debugging and keep you posted |
|
After reproducing the issue while debugging The WriteRequest has notifyFail invoked with status = -3, but both failCallback and internalFailCallback are null. It's invoked from BleManager#3391 I've normally seen this happening when BluetoothGatt#writeCharacteristic returns false |
|
One more thing, where was this nextRequest(..) called from? |
|
Whenever a WriteCharacteristic doesn't log a
Also, I'm sometimes seeing ...
.awaitValid(response)
173 return response.responseThrowIfNotValid()53 fun response(): ByteArray? = rawData.value
fun responseThrowIfNotValid(): ByteArray {
if (!isValid) {
throw CommandFailedException(...)
}
77 return response()!!
} |
|
The same -3 status happened with a different set of commands, but the sequence is very similar
|
|
I think I've identified
writeCharacteristic(deviceParametersCharacteristic, payload)
.fail { _, status ->
Timber.e("writeCharacteristic sensors failed with status %s",status)
}
.enqueue()
waitForNotification(deviceParametersCharacteristic!!)
.trigger(writeCharacteristic(deviceParametersCharacteristic, payload)
.fail { _, status ->
Timber.e("writeCharacteristic sensors failed with status %s",status)
}
)
.timeout(OPERATION_TIMEOUT_MS)
.enqueue()Sorry to spam the thread, but this is biting us and we need to fix it 😢 |
|
Are you receiving the new sensor state events on the same characteristic that you then use for waitAndNofity, or a different one? |
|
To me the issue is indeed related to the |
|
Really happy to hear to you were able to reproduce the issue!
Turns out I was wrong, it's happening in all devices. |
|
Regarding your characteristic notification question
It's even a different service, if that makes any difference |
|
The way I reproduced the issue was by playing with nRF Blinky. I've added: waitForNotification(mButtonCharacteristic)
.before(device -> Log.i("AAAA", "Before wait for"))
.trigger(
writeCharacteristic(mLedCharacteristic, BlinkyLED.turnOn())
.before(device -> Log.i("AAAA", "Before trigger"))
.fail((device, status) -> Log.w("AAAA", "Trigger failed: " + status))
.with((device, data) -> Log.i("AAAA", "Data sent: " + data))
.done(device -> Log.i("AAAA", "Trigger done"))
)
.fail((device, status) -> {
Log.w("AAAA", "Wait for failed: " + status);
})
.done(device -> {
Log.i("AAAA", "Wait for done");
})
.with((device, data) -> Log.i("AAAA", "Notification received: " + data))
.timeout(10000)
.enqueue();
waitForNotification(mButtonCharacteristic)
.before(device -> Log.i("AAAA", "Before wait for 2"))
.trigger(
writeCharacteristic(mLedCharacteristic, BlinkyLED.turnOff())
.before(device -> Log.i("AAAA", "Before trigger 2"))
.fail((device, status) -> Log.w("AAAA", "Trigger 2 failed: " + status))
.with((device, data) -> Log.i("AAAA", "Data sent 2: " + data))
.done(device -> Log.i("AAAA", "Trigger 2 done"))
)
.fail((device, status) -> {
Log.w("AAAA", "Wait for 2 failed: " + status);
})
.done(device -> {
Log.i("AAAA", "Wait for 2 done");
})
.with((device, data) -> Log.i("AAAA", "Notification 2 received: " + data))
.timeout(10000)
.enqueue();to I pushed a change to develop branch with a fix (I hope). I'm not sure if it really fixes your issue, could you try it before I publish the version? |
|
I'm getting a timeout waitForNotification(responseCharacteristic)
.trigger(writeCharacteristic(gattCharacteristicWrite, payload))
.timeout(4000)
.awaitValid(response)Notifications were enabled previously |
|
If you think it can help, I'm open to a pair programming session |
|
Are you sure you are getting the notification before the timeout after the 33-12-0B-... was sent? We can work on it tomorrow. I was quite busy with some other tasks today, sorry. |
|
You are right, I was filtering out the notification log line. This is the full log More important, this is only happening in one of our devices, the other works fine, so maybe we unveiled a firmware bug. |
|
The notification on characteristic 02000004 does arrive, but before the Data written to 02000004. On the device that works fine, the order is as I'd expect, first the write, then the notification change Failure writeAndNotify Successful writeAndNotify PS. Nevermind my previous comment |
|
Yep. Order is wrong, but that may happen (if Android handles it incorrectly). I'll add a fix for this tomorrow. A notification received after the trigger was executed (but not completed) will work, but the lib will still wait for the write callback before going forward. |
|
Btw, if your device if flooding with notifications, than you shouldn't use the trigger. My intention was to use this for command-responses use cases, where it is the command that triggers notification that would not be sent otherwise. In your case it looks like the notification was received before the trigger was sent, so in fact the lib should ignore it and wait for a next one. |
|
The notification flood was on a different characteristic. Does it still affect the WaitForValueChangedRequest? It can happen that the characteristic emits a notification change that's not a direct answer to our command. For example, if the user presses a button and the device starts vibrating, the "is vibrating" sensor will emit a notification changed on the same characteristic we are trying to write on. Will that cause issues? In our case, the response's first byte matches the command we sent. I don't know if it'd be possible to pass some kind of filter to WaitForValueChangedRequest, but I guess that belongs in a separate feature request. Failure log, where we can see that the notification received was indeed a response to the command we sent |
No, other characteristics are safe.
The notification given as a parameter to
Yes, let's leave it for the future. If your notification was indeed a response for the request, that means that it may come even before the |
|
Hi, could you try with the latest update? The manager will now wait until a notification is received after the trigger request was at least started. When it comes before the trigger was finished, it will also wait until the trigger's request is received. |
|
That seems to fix the issues, thank you so much!! |
|
I'll release 2.0.1 soon. |
ghost
mentioned this issue
|
Released in 2.0.1. |
|
Hi @philips77, Thanks for this great library! I'm wondering if I'm facing an issue similar to what is described above. I use the library to connect to a (Nordic) device and subscribe to notifications from one specific characteristic. To communicate in both ways, I (the Android app) receive notifications from the characteristic and when I need to send a message, I write to that characteristic and the device replies with the same exact data. Multiple issues were fixed from 2.0.1 & 2.0.3 releases. However, I'm still facing something weird. I sometimes receive a notification from the Nordic device and then, I can see in logs that the exact same data is automatically written to the device, without no link with my own code, meaning I'm not sending any write request for that specific message. Unfortunately, this issue breaks the communication protocol between our Nordic device and the Android app as we rely on a specific sequence order. Do you have any idea why this could happen? I will try to add logs asap when facing the issue again as it is not systematically reproducible. Thanks |
|
Here are the logs: All values have been changed , but the issue is visible with the I receive a notification with this value on line 8, and that same frame is automatically sent back to the device, visible on line 11, but I didn't chose to send this message from my code. |
|
Hi, could you please create a new issue with both your last posts? This seams to be related, but in fact, I'm afraid, isn't, and actually can't be fixed easily. I'll explain why in the other issue. Thank you! |
|
Hi @philips77, thanks for your quick reply. Here is the issue: #60 |
One of the operations I perform often is an atomic enable/disable notifications and write characteristic
A standard execution when passing "false" logs something like this
Some times, if there are consecutive calls with enable set to false and then true, it tries to enable notifications before the disable is complete. Apparently, the "disable notifications" request never confirms that the notifications are disabled but still completes
If you compare it with the previous log, it's missing the "disable notifications" ACK
Does it sound like a bug in the library?
We develop our own firmware so there might as well be a bug there, but I don't have a sniffer to check the packets.
The text was updated successfully, but these errors were encountered: