esp-nimble-cpp icon indicating copy to clipboard operation
esp-nimble-cpp copied to clipboard

onRead Callback not called

Open arjanmels opened this issue 2 years ago • 27 comments

The onRead callbacks are never trigger. I traced it down to the packet header length always being 8 in line: https://github.com/h2zero/esp-nimble-cpp/blob/a36655c105444f26d1ef7dd0893b189ab26f23ce/src/NimBLECharacteristic.cpp#L278

So apparently the filter for first and follow up reads is not working properly.

For the time being I just commented out this check

arjanmels avatar May 21 '22 08:05 arjanmels

It's working fine for me for both simple and long reads, what IDF / NimBLE version are you using?

h2zero avatar May 21 '22 15:05 h2zero

ESP-IDF 4.4.0. Not sure where to find the NimBLE version. (I use the default version from ESP-IDF 4.4.0.) I am up to date with the master branch of esp-nimble-cpp.

The attributes I use happen to be 4 or 8 bytes long. Perhaps that makes a difference?

arjanmels avatar May 21 '22 17:05 arjanmels

Strange for sure. With that small amount of data it should not be a long read issue so that's not a problem. What is the client device that is reading the data?

h2zero avatar May 21 '22 22:05 h2zero

Android 12 (Pixel 5). I confirm (via wireshark sniffing) it's is a single read transaction. Is there any more info (e.g. from wireshark) that could be useful?

(I don't understand the exact purpose of the packet header length field and how it is related to the over the air protocol.)

arjanmels avatar May 22 '22 05:05 arjanmels

I've attempted to reproduce this issue and still have not been able to. The packet header length check is a bit of a hack to workaround NimBLE spamming the callback when a long read is requested, which will call it on each subsequent data request, however it also works for a normal read as per my testing. Is this a custom app?, can you test with nRFconnect and let me know if you still have this issue?

h2zero avatar May 29 '22 00:05 h2zero

I have the same issue. Using an iPhone 13 with (my very own) app https://apps.apple.com/gb/app/ble-labor-pro/id1436021089, which is using plain CoreBluetooth read statements.

mickeyl avatar Jun 01 '22 13:06 mickeyl

Thanks, I'll see what I can do about this.

h2zero avatar Jun 01 '22 13:06 h2zero

Unfortunately I am still unable to reproduce this locally, I suspect I would need to use your apps for this. I did come up with a potential workaround, it's not ideal but it should work.

Here is a patch for it, let me know if you try it. callback_patch.txt

h2zero avatar Jun 05 '22 00:06 h2zero

@h2zero Same issue here. As long as I removed the if(ctxt->om->om_pkthdr_len > 8) { it solves the problem. I've also tried your patch, it works for me.

Here's my project: https://github.com/huming2207/SoulInspector

You may be interested in these files:

  • main/protocol/uart_handler.cpp which is the BLE characteristic callback handler
  • main/protocol/ble_manager.cpp which is the BLE manager that controls the GATT services etc.

huming2207 avatar Jun 22 '22 12:06 huming2207

@huming2207, Thanks for confirming the patch. I'll merge that soon. Are you also getting this issue when using a custom phone app?

h2zero avatar Jun 22 '22 15:06 h2zero

Are you also getting this issue when using a custom phone app?

I haven't tried that yet as my app isn't ready at the moment. I was using nRF Connect for now. I've tried negotiating different MTUs as well and it all worked fine for me.

huming2207 avatar Jun 22 '22 21:06 huming2207

Hi @h2zero , I've just got my own app working. It's a Flutter app with flutter_reactive_ble library. I can confirm the write is working.

huming2207 avatar Jun 29 '22 12:06 huming2207

Awesome, thanks for the update!

h2zero avatar Jun 30 '22 04:06 h2zero

I'm also having this problem, even though I have the latest version of this repo, which already has the patch that was discussed in this thread. Client device is a Redmi phone running Android 11, and problem appears with at least two generic BLE apps ("BLE Scanner" and "Lightblue"). So, onRead() does not fire unless I remove the check for ctxt->om->om_pkthdr_len > 8. Characteristic has 8 bytes of data. I'll report later if the behavior is different with my custom app.

tientuk3 avatar Jul 23 '22 13:07 tientuk3

Interesting, the patch should be working for this as it also checks if the data size is less than the MTU, perhaps the MTU is not set somehow...

h2zero avatar Jul 23 '22 15:07 h2zero

Hello everyone!

I'm also witnessing this issue, or at least a similar one. Our peripheral has a long readable characteristic (~200 bytes), and the callback only gets triggered on the first read, not on any subsequent reads. Commenting out the aforementioned length/MTU check in NimBLECharacteristic.cpp causes the callback to be executed on every read (10 times, of course). I've witnessed this behaviour after testing with both v1.4.1 and the latest master.

It's also worth noting that I've only encountered this problem after migrating to esp-nimble-cpp from NimBLE-Arduino, with which our system correctly executes the callback once per read.

We're using ESP-IDF v4.4.6 and Arduino-ESP32 v2.0.14 (as IDF component).

AnnoyingMoose avatar Feb 26 '24 14:02 AnnoyingMoose

@AnnoyingMoose That is the intended function, the callback should only be called on the first read which provides an opportunity to change the value before the client reads it. After that the stack will bypass the callback until all the data is read.

h2zero avatar Feb 26 '24 15:02 h2zero

@AnnoyingMoose That is the intended function, the callback should only be called on the first read which provides an opportunity to change the value before the client reads it. After that the stack will bypass the callback until all the data is read.

Apologies, I wasn't clear. When I said "read" I meant of the whole characteristic value, not a single LL packet.

To reiterate the behaviour I've observed: When the client reads the characteristic for the first time, the callback (which updates the characteristic value) is called. However, when the client reads the same characteristic again at a later time, long after the first read completed, the callback is not called again.

Again, this problem showed its head after migrating our project away from NimBLE-Arduino, which did not seem to have this problem.

AnnoyingMoose avatar Feb 26 '24 15:02 AnnoyingMoose

Sorry, I understand now. This is odd behavior for sure, I think it may have something to do with the stack code difference from the Arduino stack.

Could you try adding a debug log message to that section of the code and print the value of ctxt->om->om_pkthdr_len? If that is different now then I guess an alternative is needed to deal with the callbacks.

h2zero avatar Feb 26 '24 20:02 h2zero

// Read \#1

D (49215) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49216) NimBLECharacteristic: Read: CHandle 1; Value length 0; Header length 8; MTU 23
D (49221) NimBLECharacteristic: >> setValue: length=217, data=888cb9284c0100000000b8bb0000243c0058813f0400903d020037bef8ffda3d67663640343365c2347307438ab67f3f347ec23b583ad03bbe943e3df61b323fa69d363fddd2aac052eddf3bb4c70bbb807a2e3c00000000ad04ad04ae04ac04ad04af04, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
D (49249) NimBLECharacteristic: << setValue
D (49253) NimBLECharacteristicCallbacks: onRead: default
D (49305) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49306) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49395) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49396) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49455) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49456) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49515) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49516) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49575) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49576) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49635) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49636) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49695) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49696) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49755) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49756) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (49815) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (49816) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23

// Read \#2

D (93074) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93075) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93165) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93166) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93224) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93225) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93284) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93285) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93344) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93345) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93404) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93405) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93464) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93465) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93554) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93555) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93614) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93615) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23
D (93765) NimBLECharacteristic: Characteristic beb5483e-36e1-4688-b7f5-ea07361b26a8 Read event
D (93766) NimBLECharacteristic: Read: CHandle 1; Value length 217; Header length 8; MTU 23

Looks like the first read is only triggering the callback because the initial length of the attval is 0 (which is less than 20), rather than 217. (Reiteration: my callback sets the attval before returning). Also, all the header lengths - initial and otherwise - are 8. I'm not entirely familiar with the Bluetooth stack yet, but I gather that the first header should be longer?

I haven't tried doing the same logs yet with the Arduino library; I wonder if we'll see different header lengths.

AnnoyingMoose avatar Feb 26 '24 21:02 AnnoyingMoose

Thanks, very interesting! I'd be curious to see the Arduino comparison as well.

h2zero avatar Feb 27 '24 00:02 h2zero

I just did the same test with NimBLE-Arduino. The header for the initial read event is 10 bytes, and all subsequent reads for the same high-level read have header length 8 bytes. The precompiled ESP-IDF that's packaged with ESP32 Arduino claims to have the same version, so maybe this discrepancy is a config thing?

Do you happen to know which part of the Bluetooth Core Specification concerns the structure of this header? If not, I can just search for it.

AnnoyingMoose avatar Feb 27 '24 14:02 AnnoyingMoose

NimBLE-Arduino comes with NimBLE since the esp32 core does not have that code. I'm curious as to what may be happening here.

h2zero avatar Feb 27 '24 15:02 h2zero

NimBLE-Arduino comes with NimBLE since the esp32 core does not have that code.

I didn't realize that. It looks the version of NimBLE that comes with ESP-IDF v4.4.6 is v1.3, as opposed to the v1.4 that's packaged with NimBLE-Arduino. Since the latest stable Arduino-ESP framework (v2.0.14) doesn't support integration with ESP-IDF 5.x (which presumably has a more up-to-date version of NimBLE), I suspect this issue may be specific to ESP-IDF with Arduino-as-component workloads. I may try seeing what happens if I switch to the 3.0 alpha of Arduino-ESP, or somehow inject a different version of NimBLE.

AnnoyingMoose avatar Feb 27 '24 18:02 AnnoyingMoose

You can also use NimBLE-Arduino with IDF, you'll just need to disable nimble in menuconfig.

h2zero avatar Feb 27 '24 19:02 h2zero

You can also use NimBLE-Arduino with IDF, you'll just need to disable nimble in menuconfig.

That... makes things much easier. And it works! Thank you!

AnnoyingMoose avatar Feb 27 '24 20:02 AnnoyingMoose

You're welcome 😄, I still would like to know what the difference is though. The nimble version used with Arduino originally was 1.3 and this method worked fine at that time too.

h2zero avatar Feb 27 '24 20:02 h2zero