SOFTDEVICE: ASSERTION FAILED during/before l2cap channel release

[istvan]

We would like to stream data through an l2cap channel from a nRF52840 module to a smartphone.

The l2cap connection is initiated by the smartphone, I configured an l2cap tx queue size 12 with the sd_ble_cfg_set call.
The application crashes with softdevice assertion failed error during the closing of the l2cap channel. It happens sporadically, sometimes I have to open and close an l2cap channel ~30 times in order to reproduce the error, sometimes it happens after the first few tries.The error happens usually when the devices are further apart and several buffers are needed to be released before closing the channel. Before all the sdu buffers could be released and before the l2cap channel release event would come the application crashes.

I tried it with several softdevices and with smaller queue (6) and buffer sizes (500 bytes) and the error is still reproducible.

I got the following information from the error handler:

• softdevice 6.0.0:
  
  • id: 1 pc: 68142 info: 0
• softdevice 6.1.0
  • id: 1 pc: 75598 info: 0
• softdevice 6.1.1 (currently used in production):
  • id: 1 pc: 75706 info: 0
• softdevice 7.2
  • id: 1 pc: 77130 info: 0

Is this a known issue? How can we fix it?

[Einar Thorsrud]

Hi,

The assert is caused by a buffer overflow. We have not been able to reproduce this, though. Can you provide code and exact steps on how to reproduce this issue?

[istvan]

I simplified the code as much as possible, we can still reproduce the error with the following example.

Softdevice configuration for L2CAP:

#define L2CAP_RX_MPS          257     /**< Size of L2CAP Rx MPS (must be at least BLE_L2CAP_MPS_MIN).*/
#define L2CAP_TX_MPS          257    /**< Size of L2CAP Tx MPS (must be at least BLE_L2CAP_MPS_MIN).*/
#define L2CAP_RX_MTU          257     /**< Rx L2CAP MTU size (must be at least BLE_L2CAP_MTU_MIN).*/

#define L2CAP_TX_QUEUE_SIZE             12

static void ble_stack_init(void)
{
  ret_code_t err_code;

  err_code = nrf_sdh_enable_request();
  APP_ERROR_CHECK(err_code);

  // Configure the BLE stack using the default settings.
  // Fetch the start address of the application RAM.
  uint32_t ram_start = 0;
  err_code = nrf_sdh_ble_default_cfg_set(APP_BLE_CONN_CFG_TAG, &ram_start);
  APP_ERROR_CHECK(err_code);
    
  // Overwrite some of the default configurations for the BLE stack.
  ble_cfg_t ble_cfg;

  // Configure the number of custom UUIDS.
  memset(&ble_cfg, 0x00, sizeof(ble_cfg));
  ble_cfg.common_cfg.vs_uuid_cfg.vs_uuid_count = BLE_UUID_VS_COUNT_DEFAULT;

  // Set l2cap channel configuration
  ble_cfg.conn_cfg.conn_cfg_tag                        = APP_BLE_CONN_CFG_TAG;
  ble_cfg.conn_cfg.params.l2cap_conn_cfg.rx_mps        = L2CAP_RX_MPS;
  ble_cfg.conn_cfg.params.l2cap_conn_cfg.rx_queue_size = 1;
  ble_cfg.conn_cfg.params.l2cap_conn_cfg.tx_mps        = L2CAP_TX_MPS;
  ble_cfg.conn_cfg.params.l2cap_conn_cfg.tx_queue_size = L2CAP_TX_QUEUE_SIZE;
  ble_cfg.conn_cfg.params.l2cap_conn_cfg.ch_count      = 1;

  err_code = sd_ble_cfg_set(BLE_CONN_CFG_L2CAP, &ble_cfg, ram_start);
  APP_ERROR_CHECK(err_code);

  // Enable BLE stack.
  err_code = nrf_sdh_ble_enable(&ram_start);
  APP_ERROR_CHECK(err_code);

  // Register a handler for BLE events.
  NRF_SDH_BLE_OBSERVER(m_ble_observer, APP_BLE_OBSERVER_PRIO, ble_evt_handler, NULL);
}

L2CAP demo code:

#include "nrfx_log.h"
#include <string.h>

#define L2CAP_RX_BUFFER_SIZE    256
#define L2CAP_TX_BUFFER_SIZE    1050

typedef struct l2cap_setup_t
{
  uint16_t connection_handle;
  bool channel_open;
  bool channel_released;
  int8_t tx_in_progress_count;
  uint16_t local_cid;
  uint16_t local_psm;
}l2cap_setup_t;

static void on_l2cap_ch_setup_request(ble_evt_t const * p_ble_evt);
static void on_l2cap_ch_setup(ble_evt_t const * p_ble_evt);
static void on_l2cap_sdu_buffer_release();
static void on_l2cap_ch_release();
static void on_l2cap_ch_tx_ready();

static void l2cap_tx_data(const ble_data_t* data);

static uint8_t l2cap_tx_data_buffer[L2CAP_TX_QUEUE_SIZE][L2CAP_TX_BUFFER_SIZE];
static ble_data_t l2cap_tx_data_p[L2CAP_TX_QUEUE_SIZE];
static uint8_t next_tx_buffer_index = 0;

static l2cap_setup_t l2cap_setup;
static uint8_t l2cap_rx_data_buffer[L2CAP_RX_BUFFER_SIZE];


void l2cap_init()
{
    l2cap_setup.tx_in_progress_count = 0;
    l2cap_setup.channel_released = true;
    next_tx_buffer_index = 0;
}

void l2cap_on_ble_event(ble_evt_t const * p_ble_evt)
{
    if (p_ble_evt == NULL)
    {
        return;
    }

    switch (p_ble_evt->header.evt_id)
    {
        case BLE_L2CAP_EVT_CH_SETUP_REQUEST:
            on_l2cap_ch_setup_request(p_ble_evt);
            break;

        case BLE_L2CAP_EVT_CH_SETUP_REFUSED:
            // This should not happen because the client should be the initiator.
            break;

        case BLE_L2CAP_EVT_CH_SETUP:
            on_l2cap_ch_setup(p_ble_evt);
            break;

        case BLE_L2CAP_EVT_CH_RELEASED:
            on_l2cap_ch_release();
            break;

        case BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED:
            on_l2cap_sdu_buffer_release(p_ble_evt);
            break;

        case BLE_L2CAP_EVT_CH_CREDIT:
            break;

        case BLE_L2CAP_EVT_CH_RX:
            break;

        case BLE_L2CAP_EVT_CH_TX:
            on_l2cap_ch_tx_ready(p_ble_evt);
            break;

        default:
            // No implementation needed.
            break;
    }
}


static void on_l2cap_ch_setup_request(ble_evt_t const * p_ble_evt)
{
    if(l2cap_setup.channel_released)
    {
      l2cap_setup.channel_released = false;
      l2cap_setup.connection_handle = p_ble_evt->evt.l2cap_evt.conn_handle;

      ble_l2cap_ch_rx_params_t rx_params = {.rx_mtu = L2CAP_RX_MTU, .rx_mps = L2CAP_RX_MPS,
              .sdu_buf.p_data = l2cap_rx_data_buffer, .sdu_buf.len = L2CAP_RX_BUFFER_SIZE};
      l2cap_setup.local_cid = p_ble_evt->evt.l2cap_evt.local_cid;
      l2cap_setup.local_psm = p_ble_evt->evt.l2cap_evt.params.ch_setup_request.le_psm;

      ble_l2cap_ch_setup_params_t ble_l2cap_ch_setup_params ={.rx_params = rx_params, .le_psm = l2cap_setup.local_psm};

      sd_ble_l2cap_ch_setup(p_ble_evt->evt.l2cap_evt.conn_handle,
                                                &l2cap_setup.local_cid,
                                                &ble_l2cap_ch_setup_params);
    }
}

static void on_l2cap_ch_setup(ble_evt_t const * p_ble_evt)
{
    l2cap_setup.channel_open = true;

    //transfer dummy data
    int i = 0;
    while(i < L2CAP_TX_QUEUE_SIZE)
    {
      l2cap_request_data_tx(l2cap_tx_data_buffer[next_tx_buffer_index], L2CAP_TX_BUFFER_SIZE);
      ++i;
    }
}


static void on_l2cap_sdu_buffer_release(ble_evt_t const * p_ble_evt)
{
    l2cap_setup.channel_open = false;
    if(p_ble_evt->evt.l2cap_evt.params.ch_sdu_buf_released.sdu_buf.p_data != l2cap_rx_data_buffer)
    {
      --l2cap_setup.tx_in_progress_count;
    }
    NRF_LOG_INFO("BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: %d buff: %x", l2cap_setup.tx_in_progress_count, p_ble_evt->evt.l2cap_evt.params.ch_sdu_buf_released.sdu_buf.p_data);
}

static void on_l2cap_ch_release()
{
    l2cap_setup.channel_open = false;
    l2cap_setup.channel_released = true;
    NRF_LOG_INFO("BLE_L2CAP_EVT_CH_RELEASED, tx in prog: %d", l2cap_setup.tx_in_progress_count);
    l2cap_setup.tx_in_progress_count = 0;
}

static void on_l2cap_ch_tx_ready(ble_evt_t const * p_ble_evt)
{
    --l2cap_setup.tx_in_progress_count;

    //transfer dummy data
    l2cap_request_data_tx(l2cap_tx_data_buffer[next_tx_buffer_index], L2CAP_TX_BUFFER_SIZE);
}

static void l2cap_tx_data(const ble_data_t* data)
{
  uint32_t error_code = sd_ble_l2cap_ch_tx(l2cap_setup.connection_handle,
                                    l2cap_setup.local_cid,
                                    data);

  ++l2cap_setup.tx_in_progress_count;
  ++next_tx_buffer_index;
  if(next_tx_buffer_index >= L2CAP_TX_QUEUE_SIZE)
  {
    next_tx_buffer_index = 0;
  }

  if(error_code)
  {
    --l2cap_setup.tx_in_progress_count;
    NRF_LOG_INFO("TX ERROR: %x", error_code);
  }
}

void l2cap_request_data_tx(uint8_t* tx_data_buffer, uint16_t buffer_size)
{
  if(l2cap_setup.channel_open)
  {
    if(l2cap_setup.tx_in_progress_count < (L2CAP_TX_QUEUE_SIZE - 1))
    {
      l2cap_tx_data_p[next_tx_buffer_index].p_data = tx_data_buffer;
      l2cap_tx_data_p[next_tx_buffer_index].len = buffer_size;
      l2cap_tx_data(&l2cap_tx_data_p[next_tx_buffer_index]);
    }
  }
}

With a smartphone app I open and close the l2cap channel several times (we also have a gatt connection running in the meantime). After multiple tries, in some of the l2cap connections I get a NRF_ERROR_INVALID_STATE error for the last sd_ble_l2cap_ch_tx() command before the first sdu buffer release event. This is how it looks like in our logs:

<info> app: TX ERROR: 8
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 9 buff: 200045AC 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 8 buff: 20005B38 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 7 buff: 20005F52 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 6 buff: 2000636C 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 5 buff: 20006786 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 4 buff: 20006BA0 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 3 buff: 20006FBA 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 2 buff: 200073D4 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 1 buff: 200046B6 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 0 buff: 20004AD0
<info> app: BLE_L2CAP_EVT_CH_RELEASED, tx in prog: 0

Usually after a few connection closes which had a NRF_ERROR_INVALID_STATE error like above, comes the softdevice assert, here are again the log messages:

<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 10 buff: 200045AC 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 9 buff: 20005F52 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 8 buff: 2000636C 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 7 buff: 20006786
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 6 buff: 20006BA0 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 5 buff: 20006FBA 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 4 buff: 200073D4 
<info> app: BLE_L2CAP_EVT_CH_SDU_BUF_RELEASED, tx in prog: 3 buff: 200046B6 
<error> app: SOFTDEVICE: ASSERTION FAILED

We suspect that this error has some connection to the softdevice assert, because the softdevice assert comes only after we had this error occur at least once. We don't know however how could we avoid this error, because at the first buffer release event we already stop the transmission, and don't send more buffers to the queue. Is there a way to know even earlier if an l2cap channel is being released? The assert always come during the releases of the buffers, there are always at least one buffer in the queue which could not be released before the assert.

Could you tell us something more about the buffer overflow what you said is causes the assert? Do you have some tipps what we could try or some quick workaround for this problem?

[Einar Thorsrud]

Hi,

Thanks for the detailed information. The SoftDevice team is looking into this and I will get back to you when they have something to report.

[Einar Thorsrud]

We have not been able to explain or reproduce this yet.

Is it possible for you to provided he following?:

1. Complete Application instead of a code snippet (one that runs on a DK, preferably based on an SDK example).
2. Call trace when the assert error occurred.
3. A sniffer log with the assert error case captured.

We expect that will help us to better understand the issue.