BLERead event handler called twice?

[kk7ds]

I'm using an Arduino Nano RP2040 Connect with the NINA module. I've got a service that exposes some string characteristics that I want to feed a different value to each time they're read. I've set an eventhandler for BLERead, which is called. However, it seems to always be called twice on each read. I thought maybe this was a problem with the mobile app I'm writing, but I tried a BLE test/scanner app and each time I read the characteristic, the event handler is called twice.

Surely this is not intentional right? Am I doing something wrong that causes me to be called twice? I've looked through the AndroidBLE code a bit and I don't see any indication that I should be called twice. Even if I don't change the value, the handler is called twice.

Here's roughly what I'm doing:

void iter_temp_log(BLEDevice *central, BLECharacteristic c) {
    Serial.println("CALLED!");
}

void setup() {
    BLE.setLocalName("Remote Level");
    BLE.setAdvertisedService(levelservice);
    levelservice.addCharacteristic(templog);
    BLE.addService(levelservice);
    BLE.advertise();
    templog.setEventHandler(BLERead, iter_temp_log);
}

[kk7ds]

@per1234 Does the imperfection label mean "yes, that's a thing"? I've been bashing my head in the last 24 hours trying to figure out why I'm missing log records, so I'm happy to have realized the problem. If it's a library thing I'll hack around it and be happy, I just want to make sure I'm not doing something wrong.

[per1234]

No. It means "the reporter perceives this to be a defect in some component of the project". This is purely a classification of the type of the report, used to organize the issue tracker.

We classify reports into "imperfection" (essentially bug reports, but we avoid the term "bug" because that is specific to code, while a defect might also be in other components such as documentation or infrastructure), and "enhancement" (feature request).

At some time in the future a developer will investigate this report to determine whether it is "a thing".

If you need help with your project now, please post over on the Arduino forum:

https://forum.arduino.cc/

[kk7ds]

Okay, for normal characteristics that return the "current" value always, it wouldn't be a big deal. So I figured maybe "imperfection" was acknowledgement that this is not critical, but superficial.

I guess I can ask in the forum, but I figured the developers here would be the ones to know whether or not the behavior is expected.

Thanks!

[paulvha]

Could it be that the String length is longer than the MTU size and as such 2 reads are necessary (and thus 2 x call back ?)

[kk7ds]

My string length is a fixed and constant 26 chars. I dunno what the MTU for BLE is, but I would have assumed I was safely below it... Even if that is the issue, it's very inconvenient to be called twice for one logical read, because any side effects will be duplicated.

[paulvha]

Default MTU is 23 bytes ( 3 bytes are used for overhead (handle etc) as such 20 bytes is max. A debug : Try a short String to see whether that works.

[kk7ds]

Eesh, okay. Now that you mention it, I have one other string characteristic which just happens to be 20 chars and I don't think I see it read twice in the logs. That one has no side effect so it doesn't matter if it is read more than once. I'll go confirm for sure.

Is there something in the BLE stack that can be used to avoid calling the handler for the subsequent reads? If not, I guess some documentation so at least it's visible as an issue.

[paulvha]

Think I have a fix/ bypass.

I added a bool (_Enable_BLEread_Callback) that is set during Writevalue(). In Readvalue () it is checked and if set it will look for a BLEread callback. If so that will be performed and _Enable_BLEread_Callback will be reset. Hence you get a callback only once after each WriteValue(). I can not test it that quickly.

In the attached zip 2 files.

• Close down ArduinoIDE
• goto the folder in ArduinoBLE/src/local
• Make a safety copy first if you want of BLELocalCharacteristic.CPP and BLELocalCharacteristic.h
• copy the attached files from the zip to this folder

restart ArduinoIDE and recompile. Look forward to whether that works.

BLELocalCharacteristic.zip

[kk7ds]

I'm using platformio, FYI. But, it seems like with this in place, my handlers only ever get called once after uploading the sketch. Not even a reset will cause them to be called again, which seems strange. And, it seems like they're still getting called twice on the initial round.

[paulvha]

I have made a change now. Instead of reacting on the first readValue(), it should now be calling the callback when ALL data that was written before has been read. It might have caused your issue.

BLELocalCharacteristic.zip

[kk7ds]

Hmm, nope, still getting a successful call post-flash and then never again on the long-string characteristics.

Reading from the long-string characteristic fires the handler on the first read, and then never again on subsequent reads. With the updated code, it only calls the handler once instead of twice for that initial read, but never again. The short-string characteristic also seems to be only ever called once, until a write is performed (it is BLERead | BLEWrite), after which it will be read once only (until the next write).

I've only got one BT-enabled device to do this testing with and it's already integrated into a working project, so I probably need to get another one where I can write a much simpler sketch to test with and avoid disturbing my actual workload.

[paulvha]

pfffff.. different try. in the previous version, I did a reset to _Enable_BLEread_Callback = false AFTER the callback. This might be undoing the writeValue() setting to true. Now changed that to do an _Enable_BLEread_Callback = false; JUST before the call back.. BLELocalCharacteristic.zip

[kk7ds]

This version restored the short string characteristic so it reads every time again. The long one still only reads once and then the callback is never called again.

Are you reproducing this locally and are these changes working for you?

I really have to put this back into service, so I can't test any more until I get another device I can debug things with.

Thanks for your help, hopefully this can get resolved. My workaround to skip every other call at least lets my project continue, and now that I know it's related to the length of the string, I can also change my format to sneak in under the length limit, at least until a real fix is available.

[paulvha]

Too bad..sorry I can't make it to work as I can't check locally at this moment. I will try tomorrow at my (day) time. As you say we at least know the root cause which is normally 50% of the solution. In previous sketches/solutions, I broke down the data to send in blocks of max 20 bytes. In the first block of the new message, data[0] was a magicnumber (0xcf), the data[1] being the length. So the central/client would know to synchronize and how much data to expect. To make sure I can repo your situation locally the long string is 26 bytes and the short one is 20 or less?

[kk7ds]

Yeah, what I'm doing is sending a string that is ISOTIME + " %05.1f", effectively a timestamp, a space, and a float. I'm reading a ringbuffer of samples, so I just read from the peripheral until I get a duplicate timestamp and then I know I've got the whole ring, instead of needing to do anything more complicated with an index or two-way synchronization. I chose the string timestamp and string float representation for easy debug-ability early on, but now that I've got both sides built and I know what the problem is, I can just send eight bytes (32-bit timestamp and 32-bit float) and be well under the MTU, and faster anyway. As you say, knowing the actual problem is (at least) half the battle :)

Yes, the long string is 26 bytes and the short one is 20. I write 25 bytes (plus a NULL) into the long one, and 19 (plus a NULL) into the short one.

Thanks!

[paulvha]

I have tested it today and the latest version I did send earlier works perfectly. In the attached zip a sketch that I used as well as the BLELocalCharacteristic.h and cpp that I used.

In the top of the sketch you find test setup, an explanation of the test results. I have even tried it with a string of 86 characters, which worked as expected.

BLERead_callback.zip

Warning : in the original version the BLERead_callback is not only done often (twice in your case) BUT also BEFORE any pending data has been copied. If you perform a new writeValue() in your callback, it will overwrite any data that has not been copied out yet.

[kk7ds]

Okay, and you can read those long characteristics more than once and the handler fires each time? The read would work, but I'd get the same value and the handler wasn't called after the first time.

As I said, I'm tweaking a complex system, so I'll try a simpler example later today (perhaps the provided one) and report back.

[paulvha]

yep.. that worked for me. you can find it in the top the sketch, Maybe your files are copied to the wrong place. Attached an updated version. In the top of the sketch I point out which changes I made, but forgot to include one change in the overview. BLE_BLERead_up.zip

[kk7ds]

Okay, I'll test. It's definitely a struggle to insert those two files, so perhaps something got out of sync. Any chance you could just push up a branch we could work from?

[paulvha]

I have made more changes to ArduionoBLE to solve a number of (known) bugs and some changes for my local tests. Don't want to start mixing versions. Let's try this first (it are only 4 easy changes for this)

[kk7ds]

Okay, so, I did test last night and I think I've got a lead on why the latest version is not working for me. With your newest code, I only two callbacks after reset. That seems to be because right after reset, I have only one record to return. So I get called, I writeValue() that into the char. Then the next read I get called, I don't update the char, and then never get called again. If I writeValue() every time, then I keep getting called. Your example works, but because it calls writeValue() every time the handler is called.

I also notice that my handler is called, but the old value is returned for the read. I've always had to write some initial value into the char in order for my handler to be called at all. Is the handler supposed to generate the "current value" to be read (my expectation) or the "next value"? If the latter, then I guess I have to writeValue() into the char each time the handler is called so that the stack thinks the value has changed and calls me each time? However, the former behavior is what I want, which is "call this function always to generate the value to return". But debugging this, I'm guessing that's not possible?

[paulvha]

HI Instead of using Github, send me your BLELocalCharacteristic.cpp and h files directly (paulvha@hotmail.com) Maybe we a shorter link so I am able to provide more/ faster help and debug. regards, Paul

[paulvha]

To add to previous message:

I am a bit puzzled with what you try to achieve.

I got the impression that with every valid BLERead_callback, where all the previous data that was written with writeValue() to the characteristic before and now also send to the central/client, you wanted to write new updated data to writeValue().

In adjusted setup (by me) if you don't write anything new with writeValue()from BLERead_callback it will NOT re-trigger, as the boolean _Enable_BLEread_Callback will not have been set to true (done in writeValue()).

But when you do not write anything new: everytime before readValue() is called from remote, it will check that there is a valuesize to read from the characteristic. That valuesize is still indicating a pre-written and hence "old" written valuesize and "old" value is still valid. It does not count down. That is why you see the "old value" when remote reads.

What scenario you are looking for?

regards. Paul

---

Van: Dan Smith @.> Verzonden: dinsdag 8 november 2022 19:05 Aan: arduino-libraries/ArduinoBLE @.> CC: paulvha @.>; Comment @.> Onderwerp: Re: [arduino-libraries/ArduinoBLE] BLERead event handler called twice? (Issue #272)

Okay, so, I did test last night and I think I've got a lead on why the latest version is not working for me. With your newest code, I only two callbacks after reset. That seems to be because right after reset, I have only one record to return. So I get called, I writeValue() that into the char. Then the next read I get called, I don't update the char, and then never get called again. If I writeValue() every time, then I keep getting called. Your example works, but because it calls writeValue() every time the handler is called.

I also notice that my handler is called, but the old value is returned for the read. I've always had to write some initial value into the char in order for my handler to be called at all. Is the handler supposed to generate the "current value" to be read (my expectation) or the "next value"? If the latter, then I guess I have to writeValue() into the char each time the handler is called so that the stack thinks the value has changed and calls me each time? However, the former behavior is what I want, which is "call this function always to generate the value to return". But debugging this, I'm guessing that's not possible?

— Reply to this email directly, view it on GitHubhttps://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Farduino-libraries%2FArduinoBLE%2Fissues%2F272%23issuecomment-1307626280&data=05%7C01%7C%7C4d7da225bd6042889eab08dac1b3cae5%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C638035275189547946%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=sWVPc8Fly06kvzMFWscey73NLCEk9V83QBM6TiAn1qU%3D&reserved=0, or unsubscribehttps://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAD2GBPASWGKWWOK67H22LYLWHKI53ANCNFSM6AAAAAARQTEPWE&data=05%7C01%7C%7C4d7da225bd6042889eab08dac1b3cae5%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C638035275189547946%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=8uwtKXDPoNTFiBMlwOSXIUyxhFbx6Xtt9%2BXHpqO%2FZwM%3D&reserved=0. You are receiving this because you commented.Message ID: @.***>

[kk7ds]

Just to be clear, I haven't changed your BLELocalCharacteristic.{cpp,h} files, so no need for me to send them :)

What I am trying to achieve is that any time the central reads a characteristic from the peripheral, the handler is called to generate the value that is to be returned to the central for that read. In other words, to make the characteristic fully dynamic, i.e. "what is the value right now, which might involve doing reading from another device to determine."

However, the actual behavior seems to be that when the central reads the value, the last-known value is returned to the central, and the event handler is called to "update" the value for the next read. This is the undesirable behavior (if it is avoidable) because I effectively have to be constantly writing the current value into the characteristic "in case" the central reads it, so it doesn't read an old/stale value. Since this is a ring buffer, I can't update the values when the central isn't going to read the next one, and if the central hasn't read in a while, all the data has aged out of the ring buffer, but the first read will be very stale.

Anyway, I can work around the quirks of what is in the tree now, and will be better off with what you have proposed in your latest zip file, so that's cool. I was just hoping it would work differently when it was fixed...

Thanks!

[paulvha]

thanks.

Before readValue() is called from the ATT-layer, it first calls valueLength(). ONLY if valueLength is NOT zero, readValue() is called. Valuelength is set to the amount bytes that have been written during writeValue(). It does not keep track of the amount of bytes read. If you do not do a writeValue() the valueLength stays as it is and thus you also get the "old data" repeatedly.

Now I better understand what you want, made a new setup

1. To get started you first have to do a writeValue() to the characteristic. This will set a valueLength and thus readValue() will be called. It is just a dummy
2. With the first readValue(), it will FIRST do the callback. You can then update the value with writeValue().
3. That updated value will then be sent in blocks of max 22 bytes.
4. Once the complete update value (e.g. 26 bytes) has been send it will consider a next readValue() as a first read for a next updated value.
5. So you will only get ONE callback with the next readValue() AFTER the current is completed.

Only the BLELocalCharacteristic.cpp needs to be replaced in ArduinoBLE/src/local. I have also updated the sketch in the top with my findings.

regards, Paul BLEread_v4.zip

[kk7ds]

Sorry for the delayed response.

I definitely see number 1 above. It's a bit annoying for a characteristic with a handler, because I have to write something into the characteristic for it to ever be called, and that defeats the point of the characteristic being data-on-demand when the handler is called. But that's fine, not a big deal.

It seems that number 2 is not true for me: as I noted before, one characteristic I have is a timestamp value where the handler reads the clock and writes it to the characteristic. If I read that characteristic from the central every ten seconds (more than enough time to complete a read), I get the time from the previous read, not the current one.

Anyway, the fix to make number 5 true (only one callback after the multi-cycle read has completed) is definitely very helpful and I can work around the other quirks much easier. When will that fix be put into the tree? I'm eager to get my stuff permanently changed to work with it :)

[paulvha]

I am working on other communication examples with ArduinoBLE and Ubuntu. With that, I discovered that the dummy (Number 1) needs to be the SAME length as the value you later update. If you make that dummy shorter (say 10 characters) the FIRST message sent will be 10 characters only. If you make the dummy longer (say 40 characters), it will try to send the FIRST message with 40 characters length. Reason: The length to send is obtained BEFORE performing a readValue(), even if you set a new value of a different length in the BLERead_call_back.

There is some misunderstanding on 2: write the dummy of the same length. As soon as readValue() is called from remote, it will FIRST do a call-back call. Then you set the most up-to-date value, which is then sent with numbers 3 and 4. Once that sending has been completed it will do a callback (number 5). I think that is what you wanted.

I will try to do a pull-request over the weekend. Not sure when that will be taken by ArduinoBLE team.

[kk7ds]

I am working on other communication examples with ArduinoBLE and Ubuntu. With that, I discovered that the dummy (Number 1) needs to be the SAME length as the value you later update. If you make that dummy shorter (say 10 characters) the FIRST message sent will be 10 characters only. If you make the dummy longer (say 40 characters), it will try to send the FIRST message with 40 characters length. Reason: The length to send is obtained BEFORE performing a readValue(), even if you set a new value of a different length in the BLERead_call_back.

Yes, I see this too and I have mitigations in my code for it. I write full-length strings to the chars before they are ever read so that the central doesn't see a short string when it reads. It would be nice to get that fixed, but having to write a dummy value at all is unfortunate, since the handler should (IMHO) just always be called on a read and the value it sets should be used.

There is some misunderstanding on 2: write the dummy of the same length. As soon as readValue() is called from remote, it will FIRST do a call-back call. Then you set the most up-to-date value, which is then sent with numbers 3 and 4. Once that sending has been completed it will do a callback (number 5). I think that is what you wanted.

I understand that you intend for it to work this way, but I think you're misunderstanding me that I am not seeing it work that way.

I have a string characteristic that has a handler function that reads from the RTC and constructs a time string for "now" and does writeValue() on the characteristic with that value. If my central device reads from that characteristic, then waits a minute and reads again, the second read returns the time from a minute ago, not the value now. I'm dumping the values to serial on my arduino, so I can see that the value I call writeValue() on is not what the central gets from its read.

[paulvha]

THanks Very strange you do not see that behavior not working for you. If you look in the top of the sketch that was provided with latest update, you will see what I observed and how that worked for me.

Edit : I have created attached sketch. It sets a dummy on connect and with each call thereafter it will set and send the latest RTC data with each readValue(). I have added the result in the top of sketch. For me it works as it should. regards, Paul

RTC_ph_example.zip