Issue with the auto connect feature

[Victor Groux]

Hi,

I'm developing a BLE Central using a nRF52840 DK. My project goal is to analyze the quality and the robustness of a peripheral's BLE connection.

For some parts of my testing procedure, I need the central to automatically reconnect to the peripheral. I achieve that by calling bt_le_set_auto_conn right after bt_conn_le_create.

I will add a reproducible sample at the end of this question. Nevertheless the central works this way:

1. Scan the nearby until it found a device with a particular name (actually hardcoded in the central)
2. Connect to that peripheral
3. Activate bt_le_set_auto_conn
4. Set the BLE security level to 3 (Encryption and authentication)
   
   1. Automatically confirm the passkey
5. Start some threads (one to read the RSSI and one to retrieve the packet error rate)
6. Wait
   1. When the connection is lost
      1. Stop the threads
      2. Release some memory
      3. Do not start scanning
   2. Reconnect to the peripheral when it comes back in range

What I observed

When the auto connect feature is enable, the disconnected callback is not called on a disconnection. However the connected callback is called on every reconnection.

The kernel was panicking on reconnection because since the disconnection callback is not called, the thread created before isn't close indeed that on reconnection, the central try to recreate the thread that already exist making him panicking.
I highly suspect that because then I tried to correct this by passing the bt_conn object to the thread on creation and in the while (1) loop in the thread's entrypoint, adding a switch to check the connection state and returning (to close the thread) if the connection was in a other state than BT_CONN_STATE_CONNECTED and now the thread is closed on disconnection, the kernel isn't panicking on reconnection.

After the first disconnection, the connection with the peripheral will closed every 30 seconds (I suspect that because the link isn't encrypted (neither the pairing complete callback or the security changed callback are call on a reconnection) and my peripheral need at least a security level 3)

The errors

[00:00:01.973,541] <inf> main: Connected: 7F:D6:F3:3C:D3:8A
[00:00:01.974,060] <dbg> main: bla bla bla
[00:00:02.075,500] <inf> main: Data length updated. Length 69/69 bytes, time 2120/2120 us
[00:00:02.327,972] <inf> main: Passkey confirmed
[00:00:02.775,115] <inf> main: Security changed to level 4
[00:00:02.876,007] <inf> main: pairing_complete: Pairing complete
[00:00:02.974,182] <dbg> main: bla bla bla
[00:00:03.569,091] <inf> main: Phy updated to 2M
[00:00:03.974,334] <dbg> main: bla bla bla
[00:00:04.974,517] <inf> main: peer disconnected
<---- I disconnected the peripheral by turning off the bluetooth ---->
<---- Then I turned on the bluetooth on the peripheral ---->
[00:00:09.155,853] <err> bt_l2cap: No available L2CAP context for conn 0x20002040
[00:00:09.155,883] <err> bt_smp: No available SMP context for conn 0x20002040
[00:00:09.155,914] <err> bt_att: No available ATT context for conn 0x20002040
[00:00:09.155,914] <inf> main: Connected: CA:D5:C8:E6:52:E9
[00:00:09.156,036] <dbg> main: bla bla bla
[00:00:09.157,531] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x0004
[00:00:09.257,415] <inf> main: Data length updated. Length 69/69 bytes, time 2120/2120 us
[00:00:10.156,097] <dbg> main: bla bla bla
[00:00:10.657,501] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x0006
[00:00:11.156,219] <dbg> main: bla bla bla
...

My questions

I presume that the auto connect feature "disable" the disconnected callback, why this behavior ?

What are this L2CAP, SMP and ATT errors ?? I know for sure that they are not raised by the connected callback in itself (my function) because I added a print at its beginning and the errors printed before mine.

What are this L2CAP warning that come after the connection callback saying that it's ignoring data for "unknown channel" ??

Limitations

I don't have access to the peripheral code. However, it must work with any peripheral. I actually use 4 different peripherals and the result are the same.

Setup

• nRF52840 DK
• nRF SDK v2.7.0
• WSL2 (Ubuntu 22.04) on a Windows 10 host
• If it's matter, I do not use the VS Code extension but the CLI version

Minimum reproducible example (main.c & prj.conf)

I reduce a lot the code by removing threads, discovering phases, buttons, ect... However, I added a dummy thread just to see if the device is connected or not

#include <zephyr/types.h>
#include <stddef.h>
#include <errno.h>
#include <zephyr/kernel.h>
#include <zephyr/device.h>
#include <zephyr/sys/printk.h>
#include <zephyr/sys/util.h>
#include <zephyr/drivers/gpio.h>

#include <zephyr/logging/log.h>
#include <zephyr/logging/log_ctrl.h>

#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/hci.h>
#include <zephyr/bluetooth/conn.h>
#include <zephyr/bluetooth/uuid.h>
#include <zephyr/bluetooth/gatt.h>
#include <zephyr/sys/byteorder.h>

#define PERIPHERAL_TO_CONNECT_TO "HereIsThePeripheralName"

LOG_MODULE_REGISTER(main, LOG_LEVEL_DBG);

static struct bt_conn *default_conn;

#define THREAD_STACK_SIZE_EXAMPLE 1000
static k_tid_t th_id_example;
static struct k_thread th_data_example;
static K_THREAD_STACK_DEFINE(th_stack_example, THREAD_STACK_SIZE_EXAMPLE);

static void start_scan(void);

static bool parse_data_cb(struct bt_data *data, void *user_data)
{
  bt_addr_le_t *addr = user_data;

  switch (data->type)
  {
    case BT_DATA_NAME_SHORTENED:
    case BT_DATA_NAME_COMPLETE:
      ((uint8_t *)data->data)[data->data_len] = '\0';
      LOG_INF("[DEVICE]: %02X:%02X:%02X:%02X:%02X:%02X\tDevice name: %s", addr->a.val[5], addr->a.val[4], addr->a.val[3], addr->a.val[2], addr->a.val[1], addr->a.val[0], data->data);
      if (strncmp(data->data, PERIPHERAL_TO_CONNECT_TO, data->data_len) == 0)
      {
        int err = bt_le_scan_stop();
        if (err)
        {
          LOG_ERR("Stop LE scan failed (err %d)", err);
          return false;
        }

        struct bt_conn_le_create_param *create_param = BT_CONN_LE_CREATE_CONN;
        struct bt_le_conn_param *param = BT_LE_CONN_PARAM_DEFAULT;
      
        err = bt_conn_le_create(addr, create_param, param, &default_conn);
        if (err)
        {
          LOG_WRN("Connection failed (err %d)", err);
          start_scan();
        }
        err = bt_le_set_auto_conn(addr, param);
        if (err)
        {
          LOG_ERR("Error: bt_le_set_auto_conn() return %d", err);
          start_scan();
        }
        return false;
      }
      break;
    default:
      break;
    }
  return true;
}

static void on_device_found_cb(const bt_addr_le_t *addr, int8_t rssi, uint8_t type, struct net_buf_simple *ad)
{
  if (type == BT_GAP_ADV_TYPE_ADV_IND || type == BT_GAP_ADV_TYPE_ADV_DIRECT_IND || type == BT_GAP_ADV_TYPE_EXT_ADV || type == BT_GAP_ADV_TYPE_SCAN_RSP)
  {
    if (rssi < -30)
      bt_data_parse(ad, parse_data_cb, (void *)addr);
  }
}

static void start_scan(void)
{
  int err;

  struct bt_le_scan_param scan_param = {
    .type = BT_LE_SCAN_TYPE_ACTIVE,
    .options = BT_LE_SCAN_OPT_NONE,
    .interval = BT_GAP_SCAN_FAST_INTERVAL,
    .window = BT_GAP_SCAN_FAST_WINDOW,
  };

  err = bt_le_scan_start(&scan_param, on_device_found_cb);
  if (err)
  {
    LOG_ERR("Scanning failed to start (err %d)", err);
    return;
  }

  LOG_INF("Scanning successfully started");
}

static enum bt_conn_state get_state(struct bt_conn *conn)
{
  struct bt_conn_info info;

  int err = bt_conn_get_info(conn, &info);
  if (err)
  {
    LOG_ERR("Error: bt_conn_get_info() return %d", err);
    return BT_CONN_STATE_DISCONNECTED;
  }
  return info.state;
}

static void thread_entrypoint_example(void *p1, void *p2, void *p3)
{
  struct bt_conn *conn = p1;

  while (1)
  {
    switch (get_state(conn))
    {
      case BT_CONN_STATE_CONNECTED:
        LOG_DBG("bla bla bla");
        break;
      default:
        LOG_INF("peer disconnected");
        return;
    }
    k_sleep(K_SECONDS(1));
  }
}

static void connected_cb(struct bt_conn *conn, uint8_t conn_err)
{
  const bt_addr_le_t * addr = bt_conn_get_dst(conn);

  if (conn_err)
  {
    LOG_ERR("Failed to connect to %02X:%02X:%02X:%02X:%02X:%02X (err %u)", addr->a.val[5], addr->a.val[4], addr->a.val[3], addr->a.val[2], addr->a.val[1], addr->a.val[0], conn_err);
    bt_conn_unref(default_conn);
    default_conn = NULL;
    start_scan();
  }

  LOG_INF("Connected: %02X:%02X:%02X:%02X:%02X:%02X", addr->a.val[5], addr->a.val[4], addr->a.val[3], addr->a.val[2], addr->a.val[1], addr->a.val[0]);

  if (conn == default_conn)
  {
    int err = bt_conn_set_security(conn, BT_SECURITY_L3);
    if (err)
      LOG_ERR("Error while pairing %d", err);

    th_id_example = k_thread_create(&th_data_example,
      th_stack_example,
      K_THREAD_STACK_SIZEOF(th_stack_example),
      thread_entrypoint_example,
      conn,
      NULL,
      NULL,
      K_PRIO_PREEMPT(1),
      0,
      K_NO_WAIT);
  }
}

static void disconnected_cb(struct bt_conn *conn, uint8_t reason)
{
  LOG_INF("Beginning disconnected_cb");

  k_thread_abort(th_id_example);

  const bt_addr_le_t * addr = bt_conn_get_dst(conn);
  if (default_conn != conn)
    return;

  LOG_INF("Disconnected: %02X:%02X:%02X:%02X:%02X:%02X (reason 0x%02x)", addr->a.val[5], addr->a.val[4], addr->a.val[3], addr->a.val[2], addr->a.val[1], addr->a.val[0], reason);
}

static void auth_passkey_display_cb(struct bt_conn *conn, unsigned int passkey)
{
  LOG_INF("Passkey is: %06u", passkey);
}

static void auth_passkey_confirm_cb(struct bt_conn *conn, unsigned int passkey)
{
  LOG_INF("Passkey confirmed");
  bt_conn_auth_passkey_confirm(conn);
}

static void le_param_updated_cb(struct bt_conn *conn, uint16_t interval, uint16_t latency, uint16_t timeout)
{
  LOG_INF("CONN PARAMS UPDATED interval %d, latency %d, timeout %d", interval, latency, timeout);
}

static bool le_param_req_cb(struct bt_conn *conn, struct bt_le_conn_param *param)
{
  LOG_INF("CONN PARAMS UPDATE REQUESTED interval_min %d, interval_max %d, latency %d, timeout %d", param->interval_min, param->interval_max, param->latency, param->timeout);

  return true;
}

static void auth_cancel_cb(struct bt_conn *conn)
{
  LOG_INF("Pairing cancelled");
}

static void le_phy_update_cb(struct bt_conn *conn, struct bt_conn_le_phy_info *param)
{
  switch (param->tx_phy)
  {
    case BT_CONN_LE_TX_POWER_PHY_1M:
    case BT_CONN_LE_TX_POWER_PHY_2M:
      LOG_INF("Phy updated to %dM", param->tx_phy);
      break;
    default:
      LOG_INF("Phy updated to CODED");
      break;
  }
}

static void le_data_len_updated(struct bt_conn *conn, struct bt_conn_le_data_len_info *info)
{
  uint16_t tx_len = info->tx_max_len;
  uint16_t tx_time = info->tx_max_time;
  uint16_t rx_len = info->rx_max_len;
  uint16_t rx_time = info->rx_max_time;
  LOG_INF("Data length updated. Length %d/%d bytes, time %d/%d us", tx_len, rx_len, tx_time, rx_time);
}

static void security_changed_cb(struct bt_conn *conn, bt_security_t level, enum bt_security_err err)
{
  if (err)
    LOG_ERR("Error on security changed. err %d", err);
  else
  {
    switch (level)
    {
      case BT_SECURITY_L0:
        LOG_INF("Security changed to level 0");
        break;
      case BT_SECURITY_L1:
        LOG_INF("Security changed to level 1");
        break;
      case BT_SECURITY_L2:
        LOG_INF("Security changed to level 2");
        break; 
      case BT_SECURITY_L3:
        LOG_INF("Security changed to level 3");
        break;
      case BT_SECURITY_L4:
        LOG_INF("Security changed to level 4");
        break;
      default:
        LOG_INF("Security changed to FORCE_PAIR");
        break;
    }
  }
}

static void pairing_complete(struct bt_conn *conn, bool bonded)
{
  if (!bonded)
    LOG_INF("Pairing failed");
  else
    LOG_INF("Pairing complete");
}

BT_CONN_CB_DEFINE(conn_callbacks) = {
  .connected = connected_cb,
  .disconnected = disconnected_cb,
  .le_param_req = le_param_req_cb,
  .le_param_updated = le_param_updated_cb,
  .le_data_len_updated = le_data_len_updated,
  .le_phy_updated = le_phy_update_cb,
  .security_changed = security_changed_cb,
};

static struct bt_conn_auth_cb conn_auth_callbacks = {
  .passkey_display = auth_passkey_display_cb,
  .passkey_confirm = auth_passkey_confirm_cb,
  .cancel = auth_cancel_cb,
};

static struct bt_conn_auth_info_cb auth_info_cb = {
  .pairing_complete = pairing_complete
};

int main(void)
{
  LOG_INIT();

  int err = bt_conn_auth_cb_register(&conn_auth_callbacks);
  bt_conn_auth_info_cb_register(&auth_info_cb);

  err = bt_enable(NULL);
  if (err)
  {
    LOG_ERR("Bluetooth init failed (err %d)", err);
    return 1;
  }

  bt_set_bondable(true);
  LOG_INF("Bluetooth initialized");

  start_scan();

  return 0;
}

CONFIG_BT=y
CONFIG_BT_DEVICE_NAME="test"
CONFIG_BT_CENTRAL=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_CONSOLE=y
CONFIG_GPIO=y
CONFIG_SERIAL=y
CONFIG_EVENTS=y
CONFIG_BT_SMP=y
CONFIG_BT_BONDABLE=y
CONFIG_LOG=y
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_PRINTK=y
CONFIG_DEBUG=y
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_AUTO_PHY_UPDATE=n
CONFIG_BT_USER_DATA_LEN_UPDATE=y
CONFIG_BT_AUTO_DATA_LEN_UPDATE=n

[Victor Groux]

Hi Edvin,

I reinstall J-Link, using the version v7.88j and the link you provided. It did not solve the issue.

I tried with three different devkits:

• 2x nRF52840 DK
• 1x nRF52840-Preview-DK

I flashed the .hex file named "sniffer_nrf52840dk_nrf52840_4.1.1.hex" on the three previously said devkit.

I connected a terminal to the devkit through the COM port, I did see some values, absolutely not human readable, but at least this means that the devkits was running.

Kind regards,

Victor

[Edvin]

I see the same output as you do when running the "nrf_sniffer_ble.bat --extcap-interfaces".

But it doesn't show up as a device in Wireshark?

What happens if you try to select one of the USBPcap1 or USBPcap2? 

BR,
Edvin