OnConnect() callback is not triggring

[dinesh-slx]

I am using nimble version 2.2.3, with extended advertisiig i am trying to get the multiple connection for the very first time connect is going to onConnect and advertising for the next device to connect but when i do second connect from different device it is not trigerring onConnect because of that i am unabe to do multiple connection and i have provice the serial logs also

#include <NimBLEDevice.h>
#include <NimBLEExtAdvertising.h>
#include "ble.h"
#include "NimBLECharacteristic.h"
#include "NimBLEService.h"
#include "NimBLEUUID.h"
#include "bond.h"
#include "device_info.h"
#include "device_status.h"
#include "error.h"
#include "esp32-hal-log.h"
#include "esp32-hal.h"
#include "gatt.h"
#include "neopixel.h"
#include "ringtone.h"
#include <Adafruit_NeoPixel.h>
#include <string>
#include <strings.h>
// #include "device_info.h"

uint8_t primaryPhy = BLE_HCI_LE_PHY_1M;
uint8_t secondaryPhy = BLE_HCI_LE_PHY_1M;

NimBLEExtAdvertisement extAdv(primaryPhy, secondaryPhy);

/*

NimBLE-Arduino API doc:
https://h2zero.github.io/NimBLE-Arduino/

BLE Connection Parameters:
https://software-dl.ti.com/lprf/simplelink_cc2640r2_latest/docs/blestack/ble_user_guide/html/ble-stack-3.x/gap.html
https://www.btframework.com/connparams.htm
https://punchthrough.com/manage-ble-connection/
https://interrupt.memfault.com/blog/ble-throughput-primer

TODO: api for ble power control by central setting different connections parameters
- increase throughput for OTA firmware transfer

*/

static const char *TAG = "ble";
static uint16_t connHandle;

class ServerCallbacks : public NimBLEServerCallbacks {
  void onConnect(NimBLEServer *pServer, NimBLEConnInfo& connInfo) {
    NimBLEAddress centralAddr = connInfo.getAddress();
    ESP_LOGI(TAG, "central connected: %s", centralAddr.toString().c_str());
    connHandle = connInfo.getConnHandle();
    pServer->updateConnParams(connHandle,24,40,0,500);
    bool phyUpdated = pServer->updatePhy(connHandle, BLE_HCI_LE_PHY_1M_PREF_MASK, BLE_HCI_LE_PHY_1M_PREF_MASK, 0);
    ESP_LOGI(TAG, "PHY update %s", phyUpdated ? "success" : "failed");
    
    NimBLEDevice::startAdvertising(0);
  };

  void onDisconnect(NimBLEServer *pServer, NimBLEConnInfo& connInfo, int reason) {
    NimBLEAddress centralAddr = connInfo.getAddress();
    ESP_LOGI(TAG, "central disconnected: %s", centralAddr.toString().c_str());
    NimBLEDevice::startAdvertising(0);
  };
};

class CharacteristicCallbacks : public NimBLECharacteristicCallbacks {
  void onRead(NimBLECharacteristic *pCharacteristic, NimBLEConnInfo& connInfo) {
    
  };

  void onWrite(NimBLECharacteristic *pCharacteristic, NimBLEConnInfo& connInfo) {
  };
};

static CharacteristicCallbacks chrCallbacks;

void addServices(NimBLEServer *pServer);

NimBLEServer *InitBLE() {
  NimBLEDevice::init("VST-CL");

  // Get the device mac address
  NimBLEAddress address = NimBLEDevice::getAddress();

  // const uint8_t *native = address.getNative();
  const uint8_t *native = address.getBase()->val;

  // Compose unique device name by using the Lower Address Part (3 bytes) of bluetooth device
  // address, which uniquely identifies the device as long as we stick to ESP controllers.
  char buffer[14];
  sprintf(buffer, "VST-CL-%02X%02X%02X", native[2], native[1], native[0]);
  NimBLEDevice::setDeviceName(buffer);
  // NimBLEDevice::getAdvertising()->setName(buffer);
  ESP_LOGI(TAG, "Device name: %s", buffer);
  ESP_LOGI(
      TAG,
      "DeviceInfo: {Manufacturer:%s Serial: %s Model: %s HardwareVersion: %s FirmwareVersion: %s}",
      GetManufacturer(), GetSerial(), GetModel(), GetHardwareVersion(), GetFirmwareVersion());

  

  // Set BLE TX power
  // https://docs.espressif.com/projects/esp-idf/en/v4.4.6/esp32s3/api-reference/bluetooth/controller_vhci.html#_CPPv420esp_ble_tx_power_set20esp_ble_power_type_t17esp_power_level_t
  NimBLEDevice::setPower(ESP_PWR_LVL_P9); /** +9db*/
  NimBLEDevice::setSecurityAuth(true, false, true);
  NimBLEDevice::setSecurityIOCap(BLE_HS_IO_NO_INPUT_OUTPUT);

  NimBLEServer *pServer = NimBLEDevice::createServer();
  addServices(pServer);
  // NimBLEExtAdvertisement extAdv;

  extAdv.setName(buffer);
  extAdv.setConnectable(true);
  extAdv.addTxPower();
  extAdv.setFlags(0x06);
  // extAdv.addServiceUUID(NimBLEUUID(LIGHT_SERVICE));
  // extAdv.addServiceUUID(NimBLEUUID(AUDIO_SERVICE));
  // extAdv.addServiceUUID(NimBLEUUID(DEVICE_INFO_SERVICE));
  // extAdv.addServiceUUID(NimBLEUUID(DEVICE_STATUS_SERVICE));
  // extAdv.addServiceUUID(NimBLEUUID(BOND_SERVICE));

  extAdv.setMinInterval(0x20);
  extAdv.setMaxInterval(0x40);
  extAdv.setAppearance(0x0340); 
  return pServer;
}

void addServices(NimBLEServer *pServer) {
  pServer->setCallbacks(new ServerCallbacks());

  
  extAdv.setMinInterval(0x20);
  extAdv.setMaxInterval(0x40);
  extAdv.setAppearance(0x0340); 
}

bool StartAdvertising() {
  // NimBLEAdvertising *pAdvertising = NimBLEDevice::getAdvertising();
  // pAdvertising->addTxPower();
  // return pAdvertising->start();
  NimBLEExtAdvertising *pAdvertising = NimBLEDevice::getAdvertising();
  // Pass the configured advertisement to instance 0.
  pAdvertising->setInstanceData(0, extAdv);
  // Start advertising using instance ID 0.
  pAdvertising->start(0);
  return true;
}

uint16_t GetConnHandle() { return connHandle; }

void setup() {
  
  
  NimBLEServer *pServer = InitBLE();

  bool ok = StartAdvertising();

}

void loop() {delay(100);}

Serial logs

[12:04:08:432] [ 10547][I][ble.cpp:48] onConnect(): [ble] central connected: e8:48:b8:c8:20:00␍␊
[12:04:08:441] [ 10558][I][ble.cpp:52] onConnect(): [ble] PHY update success␍␊
[12:04:08:450] D NimBLEServer: << handleGapEvent␍␊
[12:04:08:450] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:08:450] D NimBLEExtAdvertisingCallbacks: onStopped: Default␍␊
[12:04:08:454] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:08:459] D NimBLEServerCallbacks: onPhyUpdate: default, txPhy: 1, rxPhy: 1␍␊
[12:04:08:547] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:08:547] D NimBLEServer: << handleGapEvent␍␊
[12:04:08:553] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:08:553] I NimBLEServer: mtu update event; conn_handle=1 mtu=517␍␊
[12:04:08:563] D NimBLEServerCallbacks: onMTUChange(): Default␍␊
[12:04:08:563] D NimBLEServer: << handleGapEvent␍␊
[12:04:09:762] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:09:762] I NimBLEServer: subscribe event; attr_handle=8, subscribed: true␍␊
[12:04:09:771] D NimBLEServer: << handleGapEvent␍␊
[12:04:17:032] D NimBLEServer: >> handleGapEvent: ␍␊
[12:04:17:032] D NimBLEExtAdvertisingCallbacks: onStopped: Default␍␊

[h2zero]

Please try with v2.3.0 as it may be resolved already.

[Abasz]

I have the same issue with 2.3.1.

In order for my Garmin watch to be able to connect to the ESp32s3 in Power Meter Sensor mode I had to add the line NimBLEDevice::setSecurityAuth(true, true, true);.

Once this security auth is set (note I only call setSecurityAuth no other methods) the watch is able to connect but does not trigger onConnect (if I remove the set auth call, the watch fails to create a stable permanent connection, but onConnect and onDisconnect gets called correctly).

onDisconnect gets called correctly always.

Strangely if I connect with my phone (with NRF Connect for instance) onConnect gets called. Same for my PC.

I think onConnect does not get called only when a central is connecting via secure connection.

I will do a test on an ESP32 wroom later to confirm if that is affected by this.

EDIT:

Just to add one thing:

onAuthenticationComplete gets called for the watch

[Abasz]

As an additional update:

Also the NimBleServer->getConnectedCount() does not get updated. Almost like the device is not connected. But centrals can subscribe to notifications and receive data.

I tried this with an older garmin watch which does not support secure connection and for that onConnection is not triggered either but also no onAuthenticationComplete.

Here you can find two log files: (i) is for a forerunner 255 (has secure BLE) (ii) forerunner 645 (has no secure BLE)

Both gets a second connection from a PC at some point.

• FR645.txt

I think onConnect is not getting called becuase connection seemingly fails:
D NimBLEServer: >> handleGapEvent: BLE_GAP_EVENT_CONNECT
E NimBLEServer: Connection failed

But regardless the device completes subscription and receives notifications.

When you get to this line:
00:00:57.640948 VERBOSE - Device connected: 1

Actually device count should already be 2 as that is the second device.

• FR255.txt

There is the same connection failure for the watch. But there is also onAuthenticationCompleted call.

on an probably unrelated note:

For some reason I am not seeing debug logs on the ESP32S3 (ARDUINO_USB_CDC_ON_BOOT) even though I have enabled them. I was only able to get the logs on a firebeetle2 board (ESP32 wroom)

/** @brief Un-comment to set the debug log messages level from the NimBLE host stack.\n
 *  Values: 0 = DEBUG, 1 = INFO, 2 = WARNING, 3 = ERROR, 4 = CRITICAL, 5+ = NONE\n
 *  Uses approx. 32kB of flash memory.
 */
#define CONFIG_BT_NIMBLE_LOG_LEVEL  0

/** @brief Un-comment to set the debug log messages level from the NimBLE CPP Wrapper.\n
 *  Values: 0 = NONE, 1 = ERROR, 2 = WARNING, 3 = INFO, 4+ = DEBUG\n
 *  Uses approx. 32kB of flash memory.
 */
#define CONFIG_NIMBLE_CPP_LOG_LEVEL 5

/** @brief Un-comment to enable the debug asserts in NimBLE CPP wrapper.*/
// #define CONFIG_NIMBLE_CPP_DEBUG_ASSERT_ENABLED 1

/** @brief Un-comment to see NimBLE host return codes as text debug log messages.
 *  Uses approx. 7kB of flash memory.
 */
#define CONFIG_NIMBLE_CPP_ENABLE_RETURN_CODE_TEXT

/** @brief Un-comment to see GAP event codes as text in debug log messages.
 *  Uses approx. 1kB of flash memory.
 */
#define CONFIG_NIMBLE_CPP_ENABLE_GAP_EVENT_CODE_TEXT

/** @brief Un-comment to see advertisement types as text while scanning in debug log messages.
 *  Uses approx. 250 bytes of flash memory.
 */
#define CONFIG_NIMBLE_CPP_ENABLE_ADVERTISEMENT_TYPE_TEXT

[h2zero]

Thank you for the details, that will help me to reproduce the issue, though I think this may be caused by something upstream. I'll look into this soon.

[Abasz]

I was affraid of this (yesterday evening I was digging in your code and came to the same conclusion) :)

its clear that the connect.status is false when my watch connects. Question is why :)

Sorry, on additional thing:

When the watch is trying to connect the status is BLE_ERR_UNSUPP_REM_FEATURE 0x1A

I mean its possible that the watch does not support 'just works' protocol, but then I dont understand why it is able to subscribe and connect. Not to mention that the FR255 with new firmware says the connection type is "secure".

EDIT:

I did further tests and interestingly for FR255 (i.e. secure capable watch), also the link_estab fails with the same code, but pairing_complete works

BLE_GAP_EVENT_CONNECT: conn_handle=1, status=1A
BLE_GAP_EVENT_LINK_ESTAB: conn_handle=1, status=1A
BLE_GAP_EVENT_PARING_COMPLETE: conn_handle=1, status=00

FR645 (i.e. non secure capable watch)

The same goes for the connect and the link_estab events, but paring_complete is not called

[h2zero]

@Abasz I think this has been fixed upstream:
espressif/esp-nimble@5a1882e

If you'd like to test this I will be looking to update the core soon

Nevermind, we already have this commit.

[Abasz]

If you were to create a branch and update esp-nimble code to the latest master I am happy to test.

Only thing is I need to understand what to change for espS3 CDC so debug logs show up. For some reason for S3 no logs are showing on the serial (serial is working as putting Serial.printf specifically in works), while on a older Wroom (DRRobot's firebeetle 2) the same code shows serial debug from nimble

EDIT:

There are changes to the authorisation behaviour in the code 5 days ago:

espressif/esp-nimble@84e02a6

[h2zero]

@Abasz This is very strange for sure, does this happen with version 2.2.3 or just 2.3.x?

[h2zero]

@Abasz what happens if you disable all the security features?:
NimBLEDevice::setSecurityAuth(false, false, false);

[Abasz]

NimBLEDevice::setSecurityAuth(false, false, false);

So this is a bit complicated.

In terms the onConnect being called, there is no difference.

On the pairing side, if I have made a pair with NimBLEDevice::setSecurityAuth(true, false, false); (or any other combination) and then flash the triple false version, I am able to connect to the sensor/esp32. (no onConnect call though). Disconnect event gets called without any accompanied connect call

If I remove and try to re-pair with the triple false it fails to connect. It goes into a connect disconnect loop (I have only esp32-S3 until Wednesday and as I mentioned above I cannot get nimble logs working on that for some reason) and eventually the watch says "failed to connect"

@Abasz This is very strange for sure, does this happen with version 2.2.3 or just 2.3.x?

In 2.2.3 onConnect indeed works.

In terms of pairing with the watch the same situation i.e. if all false for setSecurityAuth watch is not able to pair, if at least bonding is true pairing works

[h2zero]

Thanks @Abasz, that confirms the suspicion that this is an upstream bug, that was the major change in 2.3, so I will look into this and for now just used 2.2.3 until this is resolved.

[h2zero]

@Abasz I decided to workaround this issue, it will apply to esp-idf users as well so it made sense to do so. Please test #987 and let me know if it's resolved.

[Abasz]

Thanks, I confirm that the workaround works. onConnect is now being called properly, connected device count is increased in case of this unsupported feature status.

I have 2 questions:

1. What is the purpose of checking for a non-zero status in the BLE_GAP_EVENT_CONNECT event? I dont know the cases when the stack calls this event but I assume that when this is called a connection is already established and there will be a disconnect event if something goes south (at least even in my case disconnect was called properly). In this sense, for me it would make more sense to act only on specific error events (rather doing this on any non-zero and now this unsupported remote feature status) and pass the event status to the onConnect so consumers can decide what they want with it (for instance now you are effectively swallowing this remote feature not supported response that may be important for some)
2. Can you add some debug logging here, either to show the status when the BLE_GAP_EVENT_CONNECT is called or inside the if statement when you change rc to zero.