Esp32-snippets: [BLE] Callback function calls three or four times

[Granyy]

Hello,
Thank you so much for providing these very usefull C++ classes! You are a life saver!

I am mostly using the BLE classes. Lately, a bug appeared. When I click on the _read button_ on nRF Connect, the callback function is called three or four times without any reason. Maybe, you can help me figure it out this bug.

Thank you!
Leo

My code :
```
void run_server(void) {
MainBLEServer* pMainBleServer = new MainBLEServer();
pMainBleServer->setStackSize(20000);
pMainBleServer->start(static_cast(&gasValue));

}

My Bluetooth server:

void MainBLEServer::run(void *data) {

BLEDevice::init("MYDEVICE");
BLEServer* pServer = BLEDevice::createServer();

GasValue* gasPtr = static_cast<GasValue*>(data);

BLEService* pServiceValue = pServer->createService("91bad492-b950-4226-aa2b-4ede9fa42f59");

BLECharacteristic* pCharacteristicValue = pServiceValue->createCharacteristic(
    BLEUUID("0d563a58-196a-48ce-ace2-dfec78acc814"),
    BLECharacteristic::PROPERTY_READ
);
pCharacteristicValue->setCallbacks(new CallbackValue(*gasPtr));
pCharacteristicValue->setValue("READ");

BLECharacteristic* pCharacteristicRaw = pServiceValue->createCharacteristic(
    BLEUUID("01bf2093-f2d3-4fcc-8d2b-eda1667d96f4"),
    BLECharacteristic::PROPERTY_READ
);
pCharacteristicRaw->setCallbacks(new CallbackRawValue(*gasPtr));
pCharacteristicRaw->setValue("READ_RAW");
pServiceValue->start();


BLEService* pServiceWrite = pServer->createService("3978601c-634d-41c1-a33f-dbdd92b68dbf");
BLECharacteristic* pCharacteristicWrite = pServiceWrite->createCharacteristic(
    BLEUUID("16ce95bb-8ce1-48ff-8043-680cb323324d"),
    BLECharacteristic::PROPERTY_WRITE
);
pCharacteristicWrite->setCallbacks(new CallbackWrite());
pCharacteristicWrite->setValue("WRITE");
pServiceWrite->start();


BLEAdvertising* pAdvertising = pServer->getAdvertising();
pAdvertising->addServiceUUID(BLEUUID(pServiceValue->getUUID()));
pAdvertising->addServiceUUID(BLEUUID(pServiceWrite->getUUID()));
pAdvertising->start();
delay(1000000);

}

My callback function (executed three or four times):

void CallbackValue::onRead(BLECharacteristic pCharacteristic) {
cout << "*** READ VALUE " << endl;
gasValue = m_gasVal.get_gasValue();
cJSON *gasJSON;
gasJSON = cJSON_CreateObject();
cJSON_AddNumberToObject(gasJSON, "CO",(float)gasValue.CO);
cJSON_AddNumberToObject(gasJSON, "CO2",(float)gasValue.CO2);
cJSON_AddNumberToObject(gasJSON, "NO2",(float)gasValue.NO2);
cJSON_AddNumberToObject(gasJSON, "VOC",(float)gasValue.VOC);
string gasStr(cJSON_Print(gasJSON));
cJSON_Delete(gasJSON);
pCharacteristic->setValue(gasStr);
}
```

[chegewara]

Can you paste logs that shows all read in callback?

[nkolban]

My test plan: Create a BLE Server that invokes a callback when a read request is made by a client and see how often it gets invoked.

11:26 - First test pass. One callback for onRead seen ... but I currently only have one characteristics defined. Now defining a second charactertic and re-testing.

(Updated the post to clarify)

[Granyy]

Thank you for your responses.

I use an ESP32 to read gas sensors and transmit the values via BLE.

The examples provided in cpp_utils work properly. However, since I changed MyCallBackHandler class in order to have access to the gas measurements, it starts to call OnRead function several times as you can see on the following screenshot.

(@chegewara, if you want ESP32 logs, I don't really know how to access/activate them...)

One possibility is that the Task running the server is lauchned several times since I did my modification. I looked at the code executed in the function and I don't see why.

@nkolban: unless I don't understand what you suggest, I've already done that running your example. The problem appeared after I did a pretty simple modification on the example.

I attached the source code of my classes with comments on what I changed (based on the examples).
MyBLE.zip

Thank you.
Leo

[nkolban]

Sorry Leo ... my apologies ... the last post was for ME ... as I make my notes ... I'm working on the puzzle right now and trying to get into the habit of logging what I do :-)

[chegewara]

Sorry its not english, but you could have turn on logs verbose:

[nkolban]

I tested with two characteristics ... and still only saw the callback run once for any given characteristic. So I then went back to your code and read it carefully and noticed that you have created TWO service. I'm not saying that is a problem ... but that hasn't been in my test. Am testing that scenario now.

[chegewara]

Having 2 services with the same UUID is not allowed, at least in this library

[Granyy]

@nkolban I tested to create several services before and it was not an issue (see ESP32 project attached)
ble_demo.zip

@chegewara I don't use Arduino IDE but thanks to your message, I found something under make menuconfig! Thank you! I will be back soon with some information!
About having two identic UUID, I checked and I have two different!

ERRATUM:
I put verbose mode and that's not good... Nothing is executed, the binary seems too big to fit! (I have a pretty heavy project). I'm going to try to make it lighter.

[chegewara]

No need, just create custom partition table like this one https://github.com/nkolban/ESP32_Explorer/blob/master/partitions.csv and setup it in menuconfig

[Granyy]

Thank you, it worked. Please find attached the logs when I connect and read a value with my phone.

D (94769) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_CONNECT_EVT
D (94769) BLEUtils: GATT ServerEvent: ESP_GATTS_CONNECT_EVT
D (94769) BLEUtils: [conn_id: 0, remote_bda: 4c:6c:3b:02:ed:8e]
D (94769) BLEServer: >> handleGATTServerEvent: ESP_GATTS_CONNECT_EVT
V (94779) FreeRTOS: Semaphore giving: name: ConfEvt (0x3ffdf454), owner: <N/A>
V (94789) FreeRTOS: Semaphore giving: name: ConfEvt (0x3ffdeb94), owner: <N/A>
V (94799) FreeRTOS: Semaphore giving: name: ConfEvt (0x3ffded7c), owner: <N/A>
D (94799) BLEServer: << handleGATTServerEvent
D (95449) BLEUtils: Received a GAP event: ESP_GAP_BLE_UPDATE_CONN_PARAMS_EVT
D (95449) BLEUtils: [status: 0, bd_addr: 4c:6c:3b:02:ed:8e, min_int: 0, max_int: 0, latency: 0, conn_int: 6, timeout: 2000]
D (95459) BLEServer: BLEServer ... handling GAP event!
D (95799) BLEUtils: Received a GAP event: ESP_GAP_BLE_UPDATE_CONN_PARAMS_EVT
D (95799) BLEUtils: [status: 0, bd_addr: 4c:6c:3b:02:ed:8e, min_int: 0, max_int: 0, latency: 0, conn_int: 39, timeout: 2000]
D (95809) BLEServer: BLEServer ... handling GAP event!
D (98139) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_READ_EVT
D (98139) BLEUtils: GATT ServerEvent: ESP_GATTS_READ_EVT
D (98139) BLEUtils: [conn_id: 0, trans_id: 1, bda: 4c:6c:3b:02:ed:8e, handle: 0x2a, is_long: 0, need_rsp:1]
D (98149) BLEServer: >> handleGATTServerEvent: ESP_GATTS_READ_EVT
********** READ VALUE
D (98159) BLECharacteristic: >> setValue: length=48, data=7b0a0922434f223a0932352c0a0922434f32223a09362c0a09224e4f32223a093137392c0a0922564f43223a09300a7d, characteristic UUID=0d563a58-196a-48ce-ace2-dfec78acc814
D (98179) BLECharacteristic: << setValue
D (98189) BLECharacteristic: Sending a response (esp_ble_gatts_send_response)
D (98189) BLECharacteristic:  - Data: length=22, data=7b0a0922434f223a0932352c0a0922434f32223a0936, offset=0
D (98199) BLEServer: << handleGATTServerEvent
D (98209) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_RESPONSE_EVT
D (98209) BLEUtils: GATT ServerEvent: ESP_GATTS_RESPONSE_EVT
D (98219) BLEUtils: [status: ESP_GATT_OK, handle: 0x2a]
D (98229) BLEServer: >> handleGATTServerEvent: ESP_GATTS_RESPONSE_EVT
D (98229) BLEServer: << handleGATTServerEvent
D (98289) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_READ_EVT
D (98289) BLEUtils: GATT ServerEvent: ESP_GATTS_READ_EVT
D (98289) BLEUtils: [conn_id: 0, trans_id: 2, bda: 4c:6c:3b:02:ed:8e, handle: 0x2a, is_long: 1, need_rsp:1]
D (98299) BLEServer: >> handleGATTServerEvent: ESP_GATTS_READ_EVT
********** READ VALUE
D (98309) BLECharacteristic: >> setValue: length=48, data=7b0a0922434f223a0932352c0a0922434f32223a09362c0a09224e4f32223a093137392c0a0922564f43223a09300a7d, characteristic UUID=0d563a58-196a-48ce-ace2-dfec78acc814
D (98329) BLECharacteristic: << setValue
D (98329) BLECharacteristic: Sending a response (esp_ble_gatts_send_response)
D (98339) BLECharacteristic:  - Data: length=22, data=2c0a09224e4f32223a093137392c0a0922564f43223a, offset=22
D (98349) BLEServer: << handleGATTServerEvent
D (98359) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_RESPONSE_EVT
D (98359) BLEUtils: GATT ServerEvent: ESP_GATTS_RESPONSE_EVT
D (98369) BLEUtils: [status: ESP_GATT_OK, handle: 0x2a]
D (98369) BLEServer: >> handleGATTServerEvent: ESP_GATTS_RESPONSE_EVT
D (98379) BLEServer: << handleGATTServerEvent
D (98429) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_READ_EVT
D (98439) BLEUtils: GATT ServerEvent: ESP_GATTS_READ_EVT
D (98439) BLEUtils: [conn_id: 0, trans_id: 3, bda: 4c:6c:3b:02:ed:8e, handle: 0x2a, is_long: 1, need_rsp:1]
D (98449) BLEServer: >> handleGATTServerEvent: ESP_GATTS_READ_EVT
********** READ VALUE
D (98459) BLECharacteristic: >> setValue: length=48, data=7b0a0922434f223a0932352c0a0922434f32223a09362c0a09224e4f32223a093137392c0a0922564f43223a09300a7d, characteristic UUID=0d563a58-196a-48ce-ace2-dfec78acc814
D (98469) BLECharacteristic: << setValue
D (98479) BLECharacteristic: Sending a response (esp_ble_gatts_send_response)
D (98489) BLECharacteristic:  - Data: length=4, data=09300a7d, offset=44
D (98489) BLEServer: << handleGATTServerEvent
D (98499) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_RESPONSE_EVT
D (98499) BLEUtils: GATT ServerEvent: ESP_GATTS_RESPONSE_EVT
D (98509) BLEUtils: [status: ESP_GATT_OK, handle: 0x2a]
D (98519) BLEServer: >> handleGATTServerEvent: ESP_GATTS_RESPONSE_EVT
D (98519) BLEServer: << handleGATTServerEvent

[chegewara]

I see some issues here, when did you last time update cpp_snippets library?

[Granyy]

This morning! (git clone and copy-paste into my project)

[chegewara]

You see this logs:

********** READ VALUE
D (98309) BLECharacteristic: >> setValue: length=48, data=7b0a0922434f223a0932352c0a0922434f32223a09362c0a09224e4f32223a093137392c0a0922564f43223a09300a7d, characteristic UUID=0d563a58-196a-48ce-ace2-dfec78acc814
D (98329) BLECharacteristic: << setValue
D (98329) BLECharacteristic: Sending a response (esp_ble_gatts_send_response)
D (98339) BLECharacteristic:  - Data: length=22, data=2c0a09224e4f32223a093137392c0a0922564f43223a, offset=22
D (98349) BLEServer: << handleGATTServerEvent
D (98359) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_RESPONSE_EVT
D (98359) BLEUtils: GATT ServerEvent: ESP_GATTS_RESPONSE_EVT
D (98369) BLEUtils: [status: ESP_GATT_OK, handle: 0x2a]
D (98369) BLEServer: >> handleGATTServerEvent: ESP_GATTS_RESPONSE_EVT
D (98379) BLEServer: << handleGATTServerEvent
D (98429) BLEDevice: gattServerEventHandler [esp_gatt_if: 3] ... ESP_GATTS_READ_EVT
D (98439) BLEUtils: GATT ServerEvent: ESP_GATTS_READ_EVT
D (98439) BLEUtils: [conn_id: 0, trans_id: 3, bda: 4c:6c:3b:02:ed:8e, handle: 0x2a, is_long: 1, need_rsp:1]
D (98449) BLEServer: >> handleGATTServerEvent: ESP_GATTS_READ_EVT

We can see that setValue is 48 bytes long and it should be send with 3 segments, but is send only one segment with 22 bytes. Even if here we have set flag is_long:
D (98439) BLEUtils: [conn_id: 0, trans_id: 3, bda: 4c:6c:3b:02:ed:8e, handle: 0x2a, is_long: 1, need_rsp:1]
I dont know why is this happened, i have to check with some code but until now it seemed to works fine to me.

[Granyy]

Indeed, weird enough... Maybe the value sent is too long?
However, I receive a complete and correct JSON on nRF Connect...

[chegewara]

Give us some time to make tests.

[chegewara]

Or just let mr @nkolban to fix the issue 👍

[nkolban]

What a great bug!!! Thank you @Granyy ... perfect report and perfect debug traces. The problem has been found and resolved and a fix applied to the code base.

For our interest and records, here is the back story.

When we are running a BLE Server on the ESP32, the ESP32 is passively sitting there waiting for read requests to arrive. These will be requests from the partner BLE client saying "Hello, please give me the value of the characteristic". This results in an event being raised asynchronously inside the BLE C++ classes which says "Here is a request to read a characteristic". In that processing, we say "Do we have a user callback that will be invoked to get the value ... if yes ... call it". That all sounds sane and fair. However, there was a scenario we missed.

When a read request arrives, we don't send back the WHOLE data ... instead the data is chunked into MTU units ... this is the biggest chunk of data that can be transmitted in one time. For example, if our data to send back is 60 bytes and our MTU is 25, then we will need to send back 3 units ... 25 + 25 + 10. When we send back the first unit, the client will then come back and say "Thank you, now send me the next unit". And in there was the problem. We were invoking the user callback function for EVERY request to read data ... not just the first request to read data in a chunked sequence. The code has now been changed so that we invoke the user callback only for the FIRST unit of a chunked chain and not every one.

Please get the latest code and see if all is now good. If not, PLEASE let us know as soon as possible.

[Granyy]

It works great! :D
Thank you @nkolban!

(One question out of context: is there a way to catch the _connection/deconnection_ event of a device? - If you could just named the class or the function and I'll figure it out myself how to do this)

Thank you again!

[chegewara]

@Granyy There is BLEServer callback function with onConnect() and onDisconnect()

[NIoSaT]

I just noticed, that the same bug (or a very similar one) appears on the callbacks for descriptors as well.
Same things are happening:
Read the descriptor once
Got 3 callbacks