Esp32-snippets: Reboot after some minutes sending BLE notifications [Wemos Lolin32]

[elloza]

Hello everyone,

I have been using the example of Mr.Kolban (BLE UART) in order to send the readings of a sensor via BLE to an Android APP.

The Wemos Lolin 32 reads the measure and it sends it as soon as possible writting the characteristic and notifiying. Aproximately a notification every 80 ms.

After some minutes working this happens:

[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=13, data=3131342c3132312c39362c3831, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 13
[D][BLEC()racterillic.cpp:C 0x400tif4f on <onotif

Backtrace: 0x4008993c:0x3ffe4d50 0x40089a3b:0x3ffe4d70 0x4008554f:0x3ffe4d90 0x40085570:0x3ffe4db0 0x400856b5:0x3ffe4de0 0x4015caba:0x3ffe4e00 0x4015fd29:0x3ffe5110 0x400854cd:0x3ffe5140 0x40134d1d:0x3ffe5190 0x401140e6:0x3ffe51c0 0x4013c8f0:0x3ffe5450 0x4012d9de:0x3ffe54a0 0x4012df81:0x3ffe54c0 0x4011063e:0x3ffe54e0

Rebooting...
ets Jun  8 2016 00:22:57


##############################################################################


Decoding 14 results
0x4008993c: invoke_abort at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/esp32/./panic.c line 553
0x40089a3b: abort at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/esp32/./panic.c line 553
0x4008554f: lock_init_generic at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/newlib/./locks.c line 81
0x40085570: lock_acquire_generic at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/newlib/./locks.c line 132
0x400856b5: _lock_acquire_recursive at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/newlib/./locks.c line 169
0x4015caba: _vfprintf_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c line 860 (discriminator 2)
0x4015fd29: vprintf at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vprintf.c line 39
0x400854cd: esp_log_write at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/log/./log.c line 111
0x40134d1d: attp_build_sr_msg at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/stack/gatt/att_protocol.c line 442 (discriminator 2)
0x401140e6: GATTS_HandleValueNotification at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/stack/gatt/gatt_api.c line 768
0x4013c8f0: bta_gatts_indicate_handle at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/bta/gatt/bta_gatts_act.c line 675
0x4012d9de: bta_gatts_hdl_event at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/bta/gatt/bta_gatts_main.c line 88
0x4012df81: bta_sys_event at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/bta/sys/bta_sys_main.c line 631
0x4011063e: btu_task_thread_handler at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/bt/bluedroid/stack/btu/btu_task.c line 559

Could someone give me a clue with this?

Thank you so much in advance!!!!

[nkolban]

Looking at the trace, we see that the exception has occurred within the BLE task that is owned by the ESP32 BLE libraries. It appears to fail deep within the bowels of vprintf() while trying to acquire some internal locks. Unfortunately, none of this is the BLE C++ classes otherwise I could assist more quickly.

One of the first things I would check is memory availability. When a solution runs for a period of time and then stops, something has changed in state. The first thing to check is how much free heap we have available to us. If we had a memory leak, the heap space would start to decrease over time until such time when an internal request for RAM fails and we would get a failure.

Do I also sense that you are trying to write console data every 80ms? That's pretty fast. We would want to check that you aren't trying to log faster than the consumer could consume ... in which case the issue might be that we are queuing up too much data to write and again we might fail.

[elloza]

Thanks so much for your quickly answer! I will investigate it!

[elloza]

Hello again Mr. Kolban!

As you guessed it is a memory issue. I have been checking the memory available with xPortGetFreeHeapSize() which is (as the documentation says) a FreeRTOS function which returns the number of free bytes in the (data memory) heap.. (Heap tracing Documentation)

When I connect the Android App to Wemos Lolin32 and it start to notify values, the memory start to decrease:

I am printing the values sent to app then we can see the BLE Debug trace and then the number which return xPortGetFreeHeapSize() function.

``
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323032, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79860
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323032, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79776
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323032, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79692
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323130, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79608
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323130, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79524
150 0 182 237 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3233372c323130, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79440
150 0 182 79 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=14, data=3138322c3138312c37392c313831, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 14
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79356
150 0 182 272 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3237322c323036, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79272
150 0 182 272 0
[D][BLECharacteristic.cpp:629] setValue(): >> setValue: length=15, data=3138322c3138312c3237322c323036, characteristic UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e
[D][BLECharacteristic.cpp:636] setValue(): << setValue
[D][BLECharacteristic.cpp:492] notify(): >> notify: length: 15
[D][BLECharacteristic.cpp:511] notify(): << notifications disabled; ignoring
79188
.....

``
It seems that is related with the function which set the value and notifies via BLE.
I dont know exactly how to debug more deeply this so any clue will be really welcomed.

Thank you so much for your time!!!

[elloza]

If I use setValue with a constant string like "hello world" everything is working properly, but when I use the variable char payload[20] declared globally where I later make a sprintf to format the msg then the memory start to decrease. I have been reading the issue #79 where you recommend to use setValue with std::string myString(pointerToData, lengthOfData); but the result is the same.

I will continue doing tests.

Thanks so much! :)

[nkolban]

It is always possible (likely?) that there is a bug in the BLE C++ classes where code in this repository allocates heap storage and doesn't release it. It is also possible that there is a bug in the underlying ESP-IDF APIs that allocates storage and doesn't release it. And ... of course, there is the possibility that there is a bug in your code where you are allocating storage and not releasing. These last few sentences are, of course, a waste of time ... as they boil down to "there could be a bug somewhere" which is pretty much a tautology and adds nothing. However, it does postulate the notion ... well .. if there is a memory leak in one of these areas ... who causes it?

Thankfully, there is a very elegant (but complicated) solution.

See the following.

http://esp-idf.readthedocs.io/en/latest/api-reference/system/heap_debug.html

To get "serious" in ESP32, one has to unfortunately invest time studying and playing with the heap debugging stories. At a high level, once this subsystem is engaged, all requests to allocate storage are recorded and all releases of storage are recorded. We can cause an allocation and then a release to cancel each other out such that the history of those two are discarded ... which would leave only history of allocated storage that had no subsequent releases ... and that is the definition of a memory leak.

When a record is captured, it contains:
o The address of the storage that was allocated
o The size of the storage allocated
o The time when the storage was allocated
o The EXACT statement in the code that allocated the storage

And that last one is our solution. If we engage the recording of heap debugging, let it run for a while, stop the recording, dump the recording ... then ... if there is a memory leak, in principle we will see a string of allocations with no corresponding de-allocations that should all come from the same place and that would pin down our leak.

Realize ... that debugging memory leaks is like debugging physical plumbing leaks. You can easily tell you have a problem (your carpet around your shower is damp) but finding where the water is leaking can take time and effort.

[chegewara]

Just my 2 cents. There is also a chance that IDLE task does not have time to garbage collect and clean up and you will have to do it in your code.

[nkolban]

I didn't know there was a garbage collector in C/C++ land? What are we thinking gets garbage collected in the IDLE task? (Note: I'm for SURE not saying that there is no garbage collection ... just that this is the first time I'm hearing about it).

[chegewara]

Maybe its not good word choice. What i mean is IDLE task free heap when variables created by tasks, or RTOS itself are deleted. But if there is not enough time for IDLE task it cant be done. Best option is to ask projectgus on iirc, he can explain it better than i do.

[elloza]

I'm sorry Mr. Kolban for the delay.

I have been doing some little tests in my free time. I have been changing the lengh of the message setted to the characteristic. I though that the max payload in BLE was 20 bytes so my buffer was of that length. I reduced it to the length of 9 and the memory leak dissapear.

If the length of the message id bigger than 9 then the memory start to decrease when a device is connected.

Here the complete code, (basically, it is your BLE UART example with 2 lines of code more for debugging memory and so on):

#include <BLEDevice.h>
#include <BLEServer.h>
#include <BLEUtils.h>
#include <BLE2902.h>

#include <esp_heap_caps.h>
#include <esp_heap_trace.h>

BLECharacteristic *pCharacteristic;
bool deviceConnected = false;
uint8_t txValue = 0;

// See the following for generating UUIDs:
// https://www.uuidgenerator.net/

#define SERVICE_UUID           "6E400001-B5A3-F393-E0A9-E50E24DCCA9E" // UART service UUID
#define CHARACTERISTIC_UUID_RX "6E400002-B5A3-F393-E0A9-E50E24DCCA9E"
#define CHARACTERISTIC_UUID_TX "6E400003-B5A3-F393-E0A9-E50E24DCCA9E"


class MyServerCallbacks: public BLEServerCallbacks {
    void onConnect(BLEServer* pServer) {
      deviceConnected = true;
    };

    void onDisconnect(BLEServer* pServer) {
      deviceConnected = false;
    }
};

class MyCallbacks: public BLECharacteristicCallbacks {
    void onWrite(BLECharacteristic *pCharacteristic) {
      std::string rxValue = pCharacteristic->getValue();

      if (rxValue.length() > 0) {
        Serial.println("*********");
        Serial.print("Received Value: ");
        for (int i = 0; i < rxValue.length(); i++)
          Serial.print(rxValue[i]);

        Serial.println();
        Serial.println("*********");
      }
    }
};


void setup() {
  Serial.begin(115200);

  // Create the BLE Device
  BLEDevice::init("UART Service");

  // Create the BLE Server
  BLEServer *pServer = BLEDevice::createServer();
  pServer->setCallbacks(new MyServerCallbacks());

  // Create the BLE Service
  BLEService *pService = pServer->createService(SERVICE_UUID);

  // Create a BLE Characteristic
  pCharacteristic = pService->createCharacteristic(
                      CHARACTERISTIC_UUID_TX,
                      BLECharacteristic::PROPERTY_NOTIFY
                    );

  pCharacteristic->addDescriptor(new BLE2902());

  BLECharacteristic *pCharacteristic = pService->createCharacteristic(
                                         CHARACTERISTIC_UUID_RX,
                                         BLECharacteristic::PROPERTY_WRITE
                                       );

  pCharacteristic->setCallbacks(new MyCallbacks());

  // Start the service
  pService->start();

  // Start advertising
  pServer->getAdvertising()->start();
  Serial.println("Waiting a client connection to notify...");
}

void loop() {

  if (deviceConnected) {
    Serial.printf("*** Sent Value: %d ***\n", txValue);
    //If you changes the size to 9 the memory leak issue disappear.
    pCharacteristic->setValue((uint8_t *)"1234567890",(size_t)10);
    pCharacteristic->notify();
  }

  Serial.println(xPortGetFreeHeapSize());

  delay(200);
}

Thanks again for your time and your patience with noobs like me 👍 😄

[nkolban]

Howdy bud,
This issues seems to have gotten lost ... do we still have an issue that needs addressed?