BLE Client connection failure causes m_connectedCount to incorrectly decrement

[jamesi8086]

Hardware:

Board: M5Stick-C
Core Installation version: 1.0.4
IDE name: Arduino IDE
Flash Frequency: 40Mhz
PSRAM enabled: no
Upload Speed: 1500000
Computer OS: Win 10

Description:

I have an initialized BLE Server and BLE Client on the same device.
BLE Client connects and disconnects repeatedly to another device e.g. my android phone.

When the Client fails to connect, a ESP_GATTS_DISCONNECT_EVT is somehow triggered, decrementing m_connectedCount. This should not happen, as m_connectedCount was not incremented.

Symptom is that m_connectedCount is now 1 less than expected, and potentially underflowing to 65535.

Reproducibility happens rarely, probably only during the boundary where the phone changes its MAC address and the ESP32 is just about to read it. We can increase the chance of this happening by turning off the radio at the right time, during the connecting phase.

Sketch: (leave the backquotes for code formatting)

Related code:


uint16_t _OT_ProtocolV2::get_connected_count()
{
  return this->bleServer->getConnectedCount();
}


bool _OT_ProtocolV2::connect_and_exchange(BLEAddress address, int8_t rssi)
{
  // Connect to the BLE Server
  // - we need BLE_ADDR_TYPE_RANDOM as phones are using random addressing which changes over time
  this->bleClient->connect(address, BLE_ADDR_TYPE_RANDOM);
  BLERemoteService* pRemoteService;
  BLERemoteCharacteristic* pRemoteCharacteristic;

  if(!this->bleClient->isConnected()) 
  {
    Serial.println(F("Client connection failed"));
    return false;
  }

  pRemoteService = this->bleClient->getService(this->serviceUUID);
  if (pRemoteService == NULL)
  {
    if(this->bleClient->isConnected()) this->bleClient->disconnect();
    Serial.println(F("Failed to find our service UUID"));
    return false;
  }

  pRemoteCharacteristic = pRemoteService->getCharacteristic(this->characteristicUUID);
  if (pRemoteCharacteristic == NULL)
  {
    if(this->bleClient->isConnected()) this->bleClient->disconnect();
    Serial.println(F("Failed to find our characteristic UUID"));
    return false;
  }

  if(!pRemoteCharacteristic->canRead() || !pRemoteCharacteristic->canWrite())
  {
    if(this->bleClient->isConnected()) this->bleClient->disconnect();
    Serial.println(F("Unable to read or write"));
    return false;
  }

  std::string buf;
  this->prepare_central_write_request(buf, rssi);
  pRemoteCharacteristic->writeValue(buf, false);
  Serial.print("BLE central Send: ");
  Serial.println(buf.c_str());

  OT_ConnectionRecord connectionRecord;
  buf = pRemoteCharacteristic->readValue();

  // no need for ble client after this point
  if(this->bleClient->isConnected()) this->bleClient->disconnect();  
  
  if(!this->process_central_read_request(buf, connectionRecord))
  {
    Serial.println(F("Json parse error or read failed"));
    return false;
  }

  Serial.print("BLE central Recv: ");
  Serial.println(buf.c_str());
  
  // TODO: store data read into connectionRecord somewhere

  return true;
}

/**

**/

Debug Messages:

Enable Core debug level: Debug on tools menu of Arduino IDE, then put the serial output here 

Recompiled with debug level: Debug, but I don't see any debug messages.

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 188777542, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5816
entry 0x400806ac
;�⸮⸮U⸮⸮⸮2-hal-cpu.c:178] setCpuFrequencyMhz(): PLL: 320 / 4 = 80 Mhz, APB: 80000000 Hz
M5StickC initializing...OK
Devices connected: 0
Devices connected: 0
Devices connected: 0
...
Devices connected: 0
Devices connected: 0
Devices connected: 0
5a:62:51:40:dd:99 rssi: -65
Device connected to BLE
BLE central Send: {"id":"8Vej+n4NAutyZlS1ItKDL//RcfqWP/Tq/T/BBBUOsmAF0U+TGBqd2xcMhpfcSOyN1cSGN3znSGguodP+NQ==","v":2,"o":"SG_MOH","mc":"TraceStick V0.1","rs":-65}
BLE central Recv: {"mp":"Pixel 3a XL","v":2,"id":"SElnQHsPCfc/TGSQ6kR0sdTRS07g1KABGxRwcBzAjB6C884CIVB89SIdiwiDMBCbL9wCEKMaDaXOQQKMvg==","o":"SG_MOH"}
Device disconnected from BLE
Devices connected: 0
Devices connected: 0
...
Devices connected: 0
Devices connected: 0
Devices connected: 0
47:aa:ac:6c:32:ce rssi: -55
Device disconnected from BLE
Client connection failed
Devices connected: 65535
Devices connected: 65535
...
Devices connected: 65535
Devices connected: 65535
Devices connected: 65535
7f:46:54:44:b6:57 rssi: -71
Device disconnected from BLE
Client connection failed
Devices connected: 65534
Devices connected: 65534
Devices connected: 65534

[jamesi8086]

On a related note, I'm noticing that this crash happens when we try to restart advertising after the client connection-failure underflow. It does not always happen, suspect there could be some invalid pointer there. I've been leaving the device running 24/7, allow the glitch to happen, and see if it could remain stable even with the underflow glitch.

Update: Ok I don't think this crash is related to the m_connectedCount underflow, seems closer to start/stop advertising repeatedly over long periods of time.

Heres the stack trace:

assertion "head != NULL" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c", line 214, function: multi_heap_free

0x40092678: invoke_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c line 155
0x400928a9: abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c line 170
0x400efaaf: __assert_func at ../../../.././newlib/libc/stdlib/assert.c line 63
0x40092305: multi_heap_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c line 214
0x40085862: heap_caps_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c line 268
0x40085e1d: _free_r at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/syscalls.c line 42
0x40174399: operator delete(void*) at /builds/idf/crosstool-NG/.build/src/gcc-5.2.0/libstdc++-v3/libsupc++/del_op.cc line 46
0x40174721: operator delete at /builds/idf/crosstool-NG/.build/src/gcc-5.2.0/libstdc++-v3/libsupc++/del_opv.cc line 32
0x400d42b5: BLEAdvertising::start() at C:\Users\nexuslord\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\libraries\BLE\src\BLEAdvertising.cpp line 227
0x400d23e5: _OT_ProtocolV2::advertising_start() at C:\Users\NEXUSL~1\AppData\Local\Temp\arduino_build_532939\sketch\opentracev2.cpp line 185
0x400d1e6a: loop() at E:\Dropbox\Git Workspace\tracestick\firmware_alpha\alpha/alpha.ino line 88
0x400dfce1: loopTask(void*) at C:\Users\nexuslord\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\cores\esp32\main.cpp line 19
0x4008edb5: vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 143

[jamesi8086]

bump, this is an active bug

[Alvin1Zhang]

@me-no-dev

[me-no-dev]

@yongkimleng can you please enable the core debug to "Debug" and do that same thing again? Unfortunately the person who wrote and maintained the BLE lib in Arduino is no longer around. I had a look at the code, but the flow of events is not very clear to me. Debug will help track what is going on. I imagine that a server event should not be received for a client, it could be an IDF issue, or it could be some miss-configuration in the code.

[chegewara]

Unfortunately the person who wrote and maintained the BLE lib in Arduino is no longer around.

Unfortunately that part of code has been wrote by me. It was intended to support multiple connections.

[me-no-dev]

@chegewara any clues on a fix?

[chegewara]

I will look into it.

[jamesi8086]

@yongkimleng can you please enable the core debug to "Debug" and do that same thing again? Unfortunately the person who wrote and maintained the BLE lib in Arduino is no longer around. I had a look at the code, but the flow of events is not very clear to me. Debug will help track what is going on. I imagine that a server event should not be received for a client, it could be an IDF issue, or it could be some miss-configuration in the code.

Thats what I did when I took the console output, but did not see any additional output even after enabling debug in the IDE. I can again later tomorrow.

[me-no-dev]

@yongkimleng can I bother you to try a small change?
https://github.com/espressif/arduino-esp32/blob/master/libraries/BLE/src/BLEServer.cpp#L167-L176

change to:

        case ESP_GATTS_DISCONNECT_EVT: {
            if (m_pServerCallbacks != nullptr) {         // If we have callbacks, call now.
                m_pServerCallbacks->onDisconnect(this);
            }
            if(m_connId == ESP_GATT_IF_NONE){
                return;
            }
            removePeerDevice(param->disconnect.conn_id, false);
            m_connectedCount--;                          // Decrement the number of connected devices count.
            break;
        } // ESP_GATTS_DISCONNECT_EVT

[me-no-dev]

sorry wrong lines linked: https://github.com/espressif/arduino-esp32/blob/master/libraries/BLE/src/BLEServer.cpp#L204-L212

[jamesi8086]

Applied this fix, leaving it to run overnight

[jamesi8086]

Hmm nope the problem still occurs

I think that ESP_GATTS_CONNECT_EVT isn't even triggered in such a case, but ESP_GATTS_DISCONNECT_EVT is.
But looking at the code, I'm not sure where I could add any connected-flag checks.

BLEClient waiting for disconnected
Device disconnected from BLE
Devices connected: 0
Devices connected: 0
Devices connected: 0
Devices connected: 0
Devices connected: 0
Devices connected: 0
5e:fe:cb:54:a4:ee rssi: -59
Connecting to ble device
Device disconnected from BLE
Client connection failed
Devices connected: 65535
Devices connected: 65535
Devices connected: 65535
Devices connected: 65535
Devices connected: 65535
Devices connected: 65535
5e:fe:cb:54:a4:ee rssi: -65
Connecting to ble device
Device connected to BLE
Getting service

[jamesi8086]

Ok I modified removePeerDevice to return true if element is found and removed, so that we can at least do a check. Testing now.

// only decrement if connection is found in map and removed
// sometimes this event triggers w/o a valid connection
if(removePeerDevice(param->disconnect.conn_id, false)) {
        m_connectedCount--;                          // Decrement the number of connected devices count.
}