[NimBLEClient] When connecting multiple devices, a Panic error occurs on the third device

[wakwak-koba]

I am testing with multiple BLE Buttons with Bluetooth HID profile.
Pressing the button shows the equivalent behavior of pressing a key on the keyboard.

It seems to be very very stable compared to the original BLEClient !!

In simultaneous connection, if the number of BLE Buttons is one or two, no problem has been found, but if it is three, a Panic error will occur immediately after pairing.

#include <NimBLEDevice.h>

static void notifyCallback(BLERemoteCharacteristic* pRemoteCharacteristic, uint8_t* pData, size_t length, bool isNotify)  {
  Serial.printf("notifyCallback: %s %s handle: %02x value:", pRemoteCharacteristic->getRemoteService()->getClient()->getPeerAddress().toString().c_str(), pRemoteCharacteristic->getUUID().toString().c_str(), pRemoteCharacteristic->getHandle());
  for (int i=0; i<length; i++)
    Serial.printf(" %02x", pData[i]);
  Serial.println();
}

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

  NimBLEDevice::init("");
  auto* pBLEScan = NimBLEDevice::getScan();
  pBLEScan->setActiveScan(true);

  Serial.println("wait 10 secs..");
  auto pScanResults = pBLEScan->start(10);

  for (int i = 0; i < pScanResults.getCount(); i++) {
    auto advertisedDevice = pScanResults.getDevice(i);
    if (advertisedDevice.haveServiceUUID())  {
      Serial.print("Found Device ");
      Serial.print(advertisedDevice.toString().c_str());
      auto pClient = NimBLEDevice::createClient();
      if(pClient && pClient->connect(&advertisedDevice)) {
        auto* pRemoteServiceMap = pClient->getServices();
        for (auto itr : *pRemoteServiceMap)  {
          auto *pCharacteristicMap = itr.second->getCharacteristicsByHandle();
          for (auto itr : *pCharacteristicMap)
            if(itr.second->canNotify())
              if(itr.second->registerForNotify(notifyCallback)) {
                Serial.printf("registerForNotify: %s %s handle:%02x", pClient->getPeerAddress().toString().c_str(), itr.second->getUUID().toString().c_str(), itr.second->getHandle());
                Serial.println();
              }
        }
      }
    }
  }
}

void loop() {
  delay(1);
}

The log is too long, so here is the most recent panic error:

06:22:14.081 -> D NimBLERemoteCharacteristic: ">> registerForNotify(): Characteristic: uuid: 0x2a4d, handle: 23 0x0017, props:  0x12
06:22:14.081 -> Descriptor: uuid: 0x2902, handle: 24
06:22:14.128 -> Descriptor: uuid: 0x2908, handle: 25"
06:22:14.128 -> D NimBLERemoteCharacteristic: ">> getDescriptor: uuid: 0x2902"
06:22:14.128 -> D NimBLERemoteCharacteristic: "<< getDescriptor: found"
06:22:14.128 -> D NimBLERemoteCharacteristic: "<< registerForNotify()"
06:22:14.128 -> D NimBLERemoteDescriptor: ">> Descriptor writeValue: Descriptor: uuid: 0x2902, handle: 24"
06:22:14.128 -> D FreeRTOS: "Semaphore taking: name: WriteDescEvt (0x3ffd2178), owner: <N/A> for WriteDescriptor"
06:22:14.128 -> D FreeRTOS: "Semaphore taken:  name: WriteDescEvt (0x3ffd2178), owner: WriteDescriptor"
06:22:14.128 -> D FreeRTOS: ">> wait: Semaphore waiting: name: WriteDescEvt (0x3ffd2178), owner: WriteDescriptor for WriteDescriptor"
06:22:14.221 -> D NimBLERemoteDescriptor: "Write complete; status=0 conn_handle=2"
06:22:14.221 -> D FreeRTOS: "Semaphore giving: name: WriteDescEvt (0x3ffd2178), owner: WriteDescriptor"
06:22:14.221 -> D FreeRTOS: "<< wait: Semaphore released: name: WriteDescEvt (0x3ffd2178), owner: <N/A>"
06:22:14.221 -> D NimBLERemoteDescriptor: "<< Descriptor writeValue, rc: 0"
06:22:14.221 -> registerForNotify: ff:ff:c5:05:f5:2a 0x2a4d handle:17
06:22:15.066 -> D NimBLEClient: "Got Client event BLE_GAP_EVENT_L2CAP_UPDATE_REQ"
06:22:15.066 -> D NimBLEClient: "Peer requesting to update connection parameters"
06:22:15.066 -> D NimBLEClient: "MinInterval: 16, MaxInterval: 32, Latency: 2, Timeout: 100, min_ce_len:16,max_ce_len:768"
06:22:15.066 -> Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
06:22:15.066 -> Core 0 register dump:
06:22:15.066 -> PC      : 0x401184d6  PS      : 0x00060130  A0      : 0x80049b9c  A1      : 0x3ffb5d40  
06:22:15.066 -> A2      : 0x07ffffff  A3      : 0x00009660  A4      : 0x000000a8  A5      : 0x00000001  
06:22:15.113 -> A6      : 0x3ffb5da0  A7      : 0x00000000  A8      : 0x3ffb2ec4  A9      : 0x3ffb5d20  
06:22:15.113 -> A10     : 0x0030bb00  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x3ffafd68  
06:22:15.113 -> A14     : 0x00000000  A15     : 0x3ffb8360  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
06:22:15.113 -> EXCVADDR: 0x00000008  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  
06:22:15.113 -> 
06:22:15.113 -> ELF file SHA256: 0000000000000000000000000000000000000000000000000000000000000000
06:22:15.113 -> 
06:22:15.113 -> Backtrace: 0x401184d6:0x3ffb5d40 0x40049b99:0x3ffb5da0 0x400457cd:0x3ffb5dd0 0x4001a637:0x3ffb5e10 0x40019d11:0x3ffb5e40 0x40055b4d:0x3ffb5e60 0x40112ddf:0x3ffb5e80 0x40113331:0x3ffb5ea0 0x4009066d:0x3ffb5ed0
06:22:15.113 -> 
06:22:15.113 -> Rebooting...
06:22:15.160 -> ets Jun  8 2016 00:22:57

I don't know how to look at the backtrace, but it seems that an error occurs immediately after NimBLEClient :: handleGapEvent receives BLE_GAP_EVENT_L2CAP_UPDATE_REQ generated by the device and returns rc = 0 indicating normality.

Forcing the device to reject the request does not cause the Panic error, albeit with a different problem.

        case BLE_GAP_EVENT_CONN_UPDATE_REQ:
        case BLE_GAP_EVENT_L2CAP_UPDATE_REQ: {
            if(client->m_conn_id != event->conn_update_req.conn_handle){
                return 0; //BLE_HS_ENOTCONN BLE_ATT_ERR_INVALID_HANDLE
            }
            return BLE_ERR_CONN_PARMS;   // Adding this line will avoid Panic errors, but ... 

Is there anything you can think of ?
I'm just getting started with JTAG, but I'm glad if I can tell you what to try.

[h2zero]

Thanks for the info. That section of client code needs some work I think.

If you comment out the whole case statement and test I’d be interested in the results.

[h2zero]

Just did a test using the connection parameters I can see in your log. With the client connected to all 3 servers I have no issues at all.

For further investigation on your end I suggest you look here and un-comment those 3 statements and comment out the 3 below so you can see what the NimBLE stack is doing.

[h2zero]

I just had another look at this now and have a theory that the connection parameters are too tight for a third device.
To test this try adding pClient->setConnectionParams(16,32,2,100,8,12); after createClient()

Reason being; the default minimum connection event time is 10ms, but the connection interval may be as low as 20ms, so there only room to schedule 2 connections at once.

[wakwak-koba]

fter modifying modlog.h, there is no change in Panic errors after the suggested setConnectionParams ().
The logs are as follows:

I'm going to challenge JTAG debugging over the weekend.

08:17:52.548 -> D NimBLEClient: "Got Client event BLE_GAP_EVENT_ENC_CHANGE"
08:17:52.548 -> D NimBLEClientCallbacks: "onAuthenticationComplete: default"
08:17:52.548 -> D FreeRTOS: "Semaphore giving: name: Security (0x3ffcf410), owner: <N/A>"
08:17:52.548 -> ble_hs_hci_evt_acl_process(): conn_handle=2 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x01 0x08 0x03 0x00 0x0a 
08:17:52.548 -> rxed att command: error rsp; conn=2 req_op=8 handle=0x0003 error_code=10
08:17:52.548 -> D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: 2"
08:17:52.548 -> D FreeRTOS: "Semaphore giving: name: GetCharEvt (0x3ffcf58c), owner: retrieveCharacteristics"
08:17:52.548 -> D NimBLERemoteService: "<< Characteristic Discovered. status: 0"
08:17:52.548 -> D FreeRTOS: "<< wait: Semaphore released: name: GetCharEvt (0x3ffcf58c), owner: <N/A>"
08:17:52.548 -> Number of Completed Packets: num_handles=1
08:17:52.548 -> D NimBLERemoteService: "Found 1 Characteristics"
08:17:52.548 -> handle:2 pkts:1
08:17:52.548 -> D NimBLERemoteService: "Found UUID: 0x2a05 Handle: 3 Def Handle: 2"
08:17:52.548 -> Number of Completed Packets: num_handles=1
08:17:52.548 -> D NimBLERemoteService: "END CHARS"
08:17:52.548 -> handle:2 pkts:1
08:17:52.594 -> D NimBLERemoteCharacteristic: ">> retrieveDescriptors() for characteristic: 0x2a05"
08:17:52.594 -> D FreeRTOS: "Semaphore taking: name: GetDescEvt (0x3ffd047c), owner: <N/A> for retrieveDescriptors"
08:17:52.594 -> D FreeRTOS: "Semaphore taken:  name: GetDescEvt (0x3ffd047c), owner: retrieveDescriptors"
08:17:52.594 -> GATT procedure initiated: discover all descriptors; chr_val_handle=3 end_handle=4
08:17:52.594 -> txed att command: find info req; conn=2 start_handle=0x0004 end_handle=0x0004
08:17:52.594 -> host tx hci data; handle=2 length=9
08:17:52.594 -> ble_hs_hci_acl_tx(): 0x02 0x00 0x09 0x00 0x05 0x00 0x04 0x00 0x04 0x04 0x00 0x04 0x00 
08:17:52.626 -> D FreeRTOS: ">> wait: Semaphore waiting: name: GetDescEvt (0x3ffd047c), owner: retrieveDescriptors for retrieveCharacteristics"
08:17:52.626 -> Number of Completed Packets: num_handles=1
08:17:52.626 -> handle:2 pkts:1
08:17:52.719 -> ble_hs_hci_evt_acl_process(): conn_handle=1 pb=2 len=16 data=0x0c 0x00 0x05 0x00 0x12 0x01 0x08 0x00 0x10 0x00 0x20 0x00 0x02 0x00 0x64 0x00 
08:17:52.719 -> L2CAP - rxed signalling msg: 0x12 0x01 0x08 0x00 0x10 0x00 0x20 0x00 0x02 0x00 0x64 0x00 
08:17:52.719 -> D NimBLEClient: "Got Client event BLE_GAP_EVENT_L2CAP_UPDATE_REQ"
08:17:52.719 -> D NimBLEClient: "Peer requesting to update connection parameters"
08:17:52.719 -> D NimBLEClient: "MinInterval: 16, MaxInterval: 32, Latency: 2, Timeout: 100"
08:17:52.719 -> GAP procedure initiated: connection parameter update; conn_handle=1 itvl_min=16 itvl_max=32 latency=2 supervision_timeout=100 min_ce_len=16 max_ce_len=768
08:17:52.767 -> ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0013 len=14
08:17:52.767 -> 0x13 0x20 0x0e 0x01 0x00 0x10 0x00 0x20 0x00 0x02 0x00 0x64 0x00 0x10 0x00 0x00 0x03 
08:17:52.767 -> Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
08:17:52.767 -> Core 0 register dump:
08:17:52.767 -> PC      : 0x401185aa  PS      : 0x00060130  A0      : 0x80049b9c  A1      : 0x3ffb5d40  
08:17:52.767 -> A2      : 0x07ffffff  A3      : 0x00009660  A4      : 0x000000a9  A5      : 0x00000001  
08:17:52.767 -> A6      : 0x3ffb5da0  A7      : 0x00000000  A8      : 0x3ffb2ec4  A9      : 0x3ffb5d20  
08:17:52.767 -> A10     : 0x0030bb00  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x3ffafd68  
08:17:52.767 -> A14     : 0x00000000  A15     : 0x3ffb8360  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
08:17:52.767 -> EXCVADDR: 0x00000008  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  
08:17:52.767 -> 
08:17:52.767 -> ELF file SHA256: 0000000000000000000000000000000000000000000000000000000000000000
08:17:52.767 -> 
08:17:52.767 -> Backtrace: 0x401185aa:0x3ffb5d40 0x40049b99:0x3ffb5da0 0x400457cd:0x3ffb5dd0 0x4001a637:0x3ffb5e10 0x40019d11:0x3ffb5e40 0x40055b4d:0x3ffb5e60 0x40112eb3:0x3ffb5e80 0x40113405:0x3ffb5ea0 0x4009066d:0x3ffb5ed0
08:17:52.813 -> 
08:17:52.813 -> Rebooting...
08:17:52.813 -> ets Jun  8 2016 00:22:57

[chegewara]

Any chance to include backtrace?

[wakwak-koba]

I don't know how to analyze backtrace because of my lack of skills...

[chegewara]

There may be one more thing. As far as i know NimBLE got CCC descriptors limit in menuconfig, is it possible it has been exceeded? Dont ask me how many CCC is set by default, because i dont know.

You can use this tool standalone for backtrace decode:
https://github.com/me-no-dev/EspExceptionDecoder

[h2zero]

I can see from the nimble command sent that it appears it did not change the connection parameters in the reply. Do you still have your code modified to return 0 in the L2CAP_UPDATE gap event? If so please remove that and try again.

[h2zero]

@chegewara I have patched the problem in this library with the cccds.

Side note: you can change the limits in src/nimconfig.h.

[wakwak-koba]

Something strange happened.

When I increased CONFIG_BT_NIMBLE_MAX_CCCDS in nimconfig.h from 8 to 16 or 24, the condition became worse, but when I changed it back to 8, Panic error did not occur.

When comparing logs, it seems that 'Rejected peer params' are returned for BLE_GAP_EVENT_L2CAP_UPDATE_REQ.

After all, all changes made to NimBLE including CONFIG_BT_NIMBLE_MAX_CCCDS have been canceled and there is no difference even if compared with git.

Are connection parameters stored inside ESP32?
At some time the connection parameters were successfully updated and stored internally, after that, It looks like "Rejected peer params" because there is no difference from the parameters stored internally, and it seems that the connection parameter is not updated and the Panic error is avoided.

[wakwak-koba]

By the way, in NimBLEClient :: getPeerType (), there is a process that checks whether there is a difference in the connection parameters for BLE_GAP_EVENT_L2CAP_UPDATE_REQ, and if there is no difference, returns BLE_ERR_CONN_PARMS.
min_ce_len and max_ce_len seem to be missing from the check, is this OK?

[wakwak-koba]

I'm sorry to bother you over and over.
I'm looking for the cause of a strange phenomenon.

In the case of 'BLE_GAP_EVENT_L2CAP_UPDATE_REQ' in 'NimBLEClient :: handleGapEvent', it seems that 'client->m_pConnParams' was nullptr when a Panic error occurred.
Now that there are no Panic errors, 'client->m_pConnParams' does not seem to be a nullptr.

What does it mean that 'client->m_pConnParams' is nullptr ...

[h2zero]

No bother at all I’d like to get this stable so your input is greatly appreciated. I’ll have a look in a little while and get back to you with a better response.

[wakwak-koba]

I don't know if this is correct, but I modified 'NimBLEClient :: handleGapEvent()' as follows.

        case BLE_GAP_EVENT_CONN_UPDATE_REQ:
        case BLE_GAP_EVENT_L2CAP_UPDATE_REQ: {
            if(client->m_conn_id != event->conn_update_req.conn_handle){
                return 0; //BLE_HS_ENOTCONN BLE_ATT_ERR_INVALID_HANDLE
            }
            NIMBLE_LOGD(LOG_TAG, "Peer requesting to update connection parameters");
            NIMBLE_LOGD(LOG_TAG, "MinInterval: %d, MaxInterval: %d, Latency: %d, Timeout: %d, min_ce_len:%d,max_ce_len:%d",
                                    event->conn_update_req.peer_params->itvl_min,
                                    event->conn_update_req.peer_params->itvl_max,
                                    event->conn_update_req.peer_params->latency,
                                    event->conn_update_req.peer_params->supervision_timeout,
                                    event->conn_update_req.peer_params->min_ce_len,
                                    event->conn_update_req.peer_params->max_ce_len);
            rc = 0;
            // if we set connection params and the peer is asking for new ones, reject them.
            if(client->m_pConnParams != nullptr) {
                                         
                if(event->conn_update_req.peer_params->itvl_min != client->m_pConnParams->itvl_min ||
                    event->conn_update_req.peer_params->itvl_max != client->m_pConnParams->itvl_max ||
                    event->conn_update_req.peer_params->latency != client->m_pConnParams->latency ||
                    event->conn_update_req.peer_params->supervision_timeout != client->m_pConnParams->supervision_timeout ||
                    event->conn_update_req.peer_params->min_ce_len != client->m_pConnParams->min_ce_len ||
                    event->conn_update_req.peer_params->max_ce_len != client->m_pConnParams->max_ce_len)
                {
                    //event->conn_update_req.self_params->itvl_min = 6;//client->m_pConnParams->itvl_min;
                    rc = BLE_ERR_CONN_PARMS;
                }
            }
            else {
                rc = BLE_ERR_CONN_PARMS;
            }
            if(rc != 0) {
                NIMBLE_LOGD(LOG_TAG, "Rejected peer params");
            }
            return rc;
        } // BLE_GAP_EVENT_CONN_UPDATE_REQ, BLE_GAP_EVENT_L2CAP_UPDATE_REQ

[h2zero]

So after looking at the nimble code that handles this I think the cause might be in the stack but not necessarily a bug, that's yet to be determined. I think I need to explain this a bit from my interpretation, but fair warning I could be absolutely wrong, I don't know the nimble internals that well and they are hard to follow.

What I think is happening is when you accept the peer parameters it changes the timer in the nimble host stack and because the timing between the 3 connections is so close it causes an error. So the code I asked you to use in your app forced the stack to reject the peer request but kept the parameters the same as they showed in your log. As the client connecting to the server you are also the master in control of the connection parameters and they should be set such that you can juggle the 3 connections.

The min_ce_len and max_ce_len seem to play a role as well as the connection interval but I have not yet found how they are used and when you accept the peers requested parameters it sets those values to the nimble defaults.

I interpret their meanings to be the minimum and maximum length of the connection event that happens on each connection interval with the server. So if you have a 20ms interval and a 10ms minimum connection event time, this will mean there is only 10ms left, assuming more time was not needed. Now you add another device and it too uses 10ms, now you have no time left, but you add a 3rd device connection and get a crash.

That said I'm not sure that's how it works. The information I learned today was that when the peer parameters are accepted it seems to reset internal nimble host timing and may throw an error somewhere with connection timing but I'm not sure.

Lastly the code I had you try in your app creates the data for m_pConnParams and uses that for the initial connection, then when the peer tries to change them with the BLE_GAP_EVENT_L2CAP_UPDATE_REQ event we just reject them since we are in control of those and it does not reset the internal timers, thus no crash.

This is all just my theory and I need to find more ways to test it fully but I hope this gives you some idea of whats going on.