MPSL Assert in project involving BLE, async UART and Nordic Distance Measurement Library

[Javier Reyes]

We are developing a project that runs BLE, the Nordic Uart Service, the Nordic Distance Measurement toolikt and Async UART (NCS v2.9.0). The Peripheral device shall advertise (connectable) the Nordic Uart Service UUID, the Central Scans for this and connects to the found Peripheral, and registers the NUS Service. After the connection it starts/changes the required advertising-scanning for the distance measurement, as in the example provided from the SDK nrf_dm (we adapted only the part of Distance Estimation, and not the DDFS service or the Azimuth simulation). So only the pair advertising-scanning with the corresponding manufacturer data values, and the call to dm_request_add in the callback to the advertising scanned and scan filter match.

It works as expected, but sometime after the measurement has been running, an assert is triggered:

D: Sending Uart State
D: Idle State
W: Dist measurement updated: 2.050781
D: Sending Ble State
D: Idle State
D: Sending Uart State
D: Idle State
D: Sending Ble State
D: Idle State
D: Sending Uart State
D: Idle State
D: Sending Ble State
D: Idle State
D: Sending Uart State
D: Idle State
D: Sending Ble State
D: Idle State
D: Sending Uart State
D: Idle State
D: Sending Ble State
D: Idle State
D: Sending Uart State
D: Idle State
D: Sending Ble State
D: Idle State
ASSERTION FAIL [0] @ WEST_TOPDIR/nrf/subsys/mpsl/init/mpsl_init.c:299
  MPSL ASSERT: 106, 520

E: ***** HARD FAULT *****
E:   Fault escalation (see below)
E: ARCH_EXCEPT with reason 4

E: r0/a1:  0x00000004  r1/a2:  0x0000012b  r2/a3:  0x00000001
E: r3/a4:  0x00000004 r12/ip:  0x00000000 r14/lr:  0x000357e3
E:  xpsr:  0x21000018
E: s[ 0]:  0x00000008  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x000288bb
E: s[ 4]:  0x00020000  s[ 5]:  0x0002887d  s[ 6]:  0x00000000  s[ 7]:  0x00000000
E: s[ 8]:  0x00000000  s[ 9]:  0x0004007d  s[10]:  0x00000000  s[11]:  0x2000c36c
E: s[12]:  0x00000000  s[13]:  0x000357d9  s[14]:  0x0004d2e0  s[15]:  0x2000c384
E: fpscr:  0x00000208
E: Faulting instruction address (r15/pc): 0x00040068
E: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
E: Fault during interrupt handling

E: Current thread: 0x20009cc8 (idle)
E: Halting system

As fas as we can understand, the MPSL is being used in the DM toolkit (or BLE, or both?), but we do not interact directly with it. So we are unsure what the problem might be. From other posts here we might interpret that it might be a timing problem with an interrupt, but we are not directly stopping or missusing any interrupt that we know of. The software would receive data via UART, pass it to the main task, that would check the data with CRC32, decode the data with nanopb, and encode a response that is sent via the NUS to the other node, where something similar is performed. All of this is made in main task, only callbacks that might come from an interrupt are the UART callback and NUS RX callback, but they only load data into a FIFO and return. Similarly with the BLE callbacks, except for the 2 callbacks for advertising and scanning that contain the call to the DM library.

Also, we have the problem that the assert behaves differently in our EvalBoard (Ezurio BL653-DVK based on the BL653/nRF52833) and our custom hardware around the BL653micro/nRF52833. In the EvalBoard, the system seems to hang, but the LOG output (using Segger RTT backend) freezes (no assert is seen, but the whole system is unresponsive), while in the custom hardware the Assert output is there. Both configurations have the CONFIG_ASSERT as seen above.

Central prj.conf

CONFIG_FPU=y
CONFIG_UART_ASYNC_API=y
CONFIG_UART_1_NRF_HW_ASYNC=y
CONFIG_UART_1_NRF_HW_ASYNC_TIMER=3
CONFIG_CRC=y
CONFIG_NANOPB=y
CONFIG_BT=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_DEVICE_NAME="central"
CONFIG_BT_EXT_ADV=y
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_MANUFACTURER_DATA_CNT=1
CONFIG_BT_SCAN_UUID_CNT=1
CONFIG_BT_SCAN_WITH_IDENTITY=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_GATT_DM=y
CONFIG_HEAP_MEM_POOL_SIZE=1024
CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_CTLR_PHY_CODED=y
CONFIG_BT_AUTO_PHY_UPDATE=n
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_USER_DATA_LEN_UPDATE=y
CONFIG_BT_PERIPHERAL_PREF_MIN_INT=6
CONFIG_BT_PERIPHERAL_PREF_MAX_INT=6
CONFIG_BT_PERIPHERAL_PREF_LATENCY=2
CONFIG_BT_PERIPHERAL_PREF_TIMEOUT=500
CONFIG_BT_GAP_AUTO_UPDATE_CONN_PARAMS=n
CONFIG_BT_L2CAP_TX_MTU=247
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=251
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_NUS_CLIENT=y
CONFIG_DM_MODULE=y
CONFIG_DM_HIGH_PRECISION_CALC=y
CONFIG_MPSL=y
CONFIG_MPSL_TIMESLOT_SESSION_COUNT=1
CONFIG_MPSL_WORK_STACK_SIZE=2048
CONFIG_NRFX_PPI=y

Central DM Adv-Scan parameters:

static struct bt_le_adv_param app_ble_adv_params_noconnectable =
    BT_LE_ADV_PARAM_INIT(BT_LE_ADV_OPT_USE_IDENTITY | BT_LE_ADV_OPT_SCANNABLE | BT_LE_ADV_OPT_NOTIFY_SCAN_REQ,
                            BT_GAP_ADV_SLOW_INT_MIN, // 160 * 0.625 ms = 100 ms
                            BT_GAP_ADV_SLOW_INT_MAX, // 240 * 0.625 ms = 150 ms
                            NULL);

static struct bt_data app_ble_advertisement_data[] = {
    BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
    BT_DATA(BT_DATA_NAME_COMPLETE, APP_BLE_DEVICE_NAME, APP_BLE_DEVICE_NAME_LEN),
};

static struct bt_data app_ble_scan_response_dm_data[] = {
    BT_DATA(BT_DATA_MANUFACTURER_DATA, (unsigned char*)&app_ble.mfg_data, sizeof(app_ble.mfg_data)),
};

static struct bt_le_scan_param app_ble_scan_params = {
    .type = BT_LE_SCAN_TYPE_ACTIVE,
    .interval = BT_GAP_SCAN_FAST_INTERVAL,
    .window   = BT_GAP_SCAN_FAST_WINDOW,
    .options = BT_LE_SCAN_OPT_NONE,
    .timeout = 0,
};

// callback for the bt_data_parse in the scan filter match callback
static bool app_ble_scan_data_cb(struct bt_data* data, void* user_data)
{
    struct adv_mfg_data* recv_mfg_data;
    struct dm_request req;

    switch (data->type)
    {
    case BT_DATA_MANUFACTURER_DATA:
        if (sizeof(struct adv_mfg_data) == data->data_len)
        {
            recv_mfg_data = (struct adv_mfg_data*)data->data;

            bt_addr_le_copy(&req.bt_addr, user_data);
            req.role = DM_ROLE_INITIATOR;
            req.ranging_mode = DM_RANGING_MODE_MCPD;

            req.rng_seed = sys_le32_to_cpu(recv_mfg_data->rng_seed) + app_ble.scanner_random_share;
            req.start_delay_us = 0;
            req.extra_window_time_us = 0;

            dm_request_add(&req);
        }
        return false;
    default:
        return true;
    }
}

// callback for the advertising scanned callback
static void app_ble_adv_scanned_cb(struct bt_le_ext_adv* adv, struct bt_le_ext_adv_scanned_info* info)
{
    struct dm_request req;

    if (peer_supported_test(info->addr))
    {
        bt_addr_le_copy(&req.bt_addr, info->addr);
        req.role = DM_ROLE_REFLECTOR;
        req.ranging_mode = DM_RANGING_MODE_MCPD;

        req.rng_seed = peer_rng_seed_get() + app_ble_scanner_addr_to_random_share(&info->addr->a);
        req.start_delay_us = 0;
        req.extra_window_time_us = 0;

        dm_request_add(&req);
        app_ble_adv_update_data();
    }
}

// DM library data ready callback
static void app_ble_dm_data_ready_cb(struct dm_result* result)
{
    if (result->status)
    {
        peer_update(result);
    }
}

Peripheral prj.conf

CONFIG_FPU=y
CONFIG_UART_ASYNC_API=y
CONFIG_UART_1_NRF_HW_ASYNC=y
CONFIG_UART_1_NRF_HW_ASYNC_TIMER=3
CONFIG_CRC=y
CONFIG_NANOPB=y
CONFIG_BT=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_DEVICE_NAME="Peripheral"
CONFIG_BT_EXT_ADV=y
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_MANUFACTURER_DATA_CNT=1
CONFIG_BT_SCAN_WITH_IDENTITY=y
CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_CTLR_PHY_CODED=y
CONFIG_BT_AUTO_PHY_UPDATE=n
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_USER_DATA_LEN_UPDATE=y
CONFIG_BT_PERIPHERAL_PREF_MIN_INT=6
CONFIG_BT_PERIPHERAL_PREF_MAX_INT=6
CONFIG_BT_PERIPHERAL_PREF_LATENCY=2
CONFIG_BT_PERIPHERAL_PREF_TIMEOUT=500
CONFIG_BT_GAP_AUTO_UPDATE_CONN_PARAMS=n
CONFIG_BT_L2CAP_TX_MTU=247
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=251
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_NUS=y
CONFIG_DM_MODULE=y
CONFIG_DM_HIGH_PRECISION_CALC=y
CONFIG_MPSL=y
CONFIG_MPSL_TIMESLOT_SESSION_COUNT=1
CONFIG_MPSL_WORK_STACK_SIZE=2048
CONFIG_NRFX_PPI=y
CONFIG_UART_CONSOLE=n
CONFIG_CONSOLE=y
CONFIG_LOG=y
CONFIG_LOG_MODE_MINIMAL=y
CONFIG_LOG_PRINTK=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=y
CONFIG_ASSERT=y
CONFIG_ASSERT_VERBOSE=y
CONFIG_ASSERT_NO_COND_INFO=n
CONFIG_ASSERT_NO_MSG_INFO=n
CONFIG_RESET_ON_FATAL_ERROR=n

peripheral DM Adv-Scan parameters

static struct bt_le_adv_param app_ble_adv_params_noconnectable =
    BT_LE_ADV_PARAM_INIT(BT_LE_ADV_OPT_USE_IDENTITY | BT_LE_ADV_OPT_SCANNABLE | BT_LE_ADV_OPT_NOTIFY_SCAN_REQ,
                            BT_GAP_ADV_FAST_INT_MIN_2, // 160 * 0.625 ms = 100 ms
                            BT_GAP_ADV_FAST_INT_MAX_2, // 240 * 0.625 ms = 150 ms
                            NULL);

static struct bt_data app_ble_advertisement_data[] = {
    BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
};

static struct bt_data app_ble_scan_response_dm_data[] = {
    BT_DATA(BT_DATA_MANUFACTURER_DATA, (unsigned char*)&app_ble.mfg_data, sizeof(app_ble.mfg_data)),
};

static struct bt_le_scan_param app_ble_scan_params = {
    .type = BT_LE_SCAN_TYPE_ACTIVE,
    .interval = BT_GAP_SCAN_FAST_INTERVAL,
    .window = BT_GAP_SCAN_FAST_WINDOW,
    .options = BT_LE_SCAN_OPT_NONE,
    .timeout = 0,
};

static bool app_ble_scan_data_cb(struct bt_data* data, void* user_data)
{
    struct adv_mfg_data* recv_mfg_data;
    struct dm_request req;

    switch (data->type)
    {
    case BT_DATA_MANUFACTURER_DATA:
#if APP_BLE_DEBUG_DM == 1
        RTT_LOG_INF("Scanner filter: MFG found, len: %d, sizeof: %d", data->data_len, sizeof(struct adv_mfg_data));
#endif
        if (sizeof(struct adv_mfg_data) == data->data_len)
        {
            recv_mfg_data = (struct adv_mfg_data*)data->data;

            bt_addr_le_copy(&req.bt_addr, user_data);
            req.role = DM_ROLE_INITIATOR;
            req.ranging_mode = DM_RANGING_MODE_MCPD;

            req.rng_seed = sys_le32_to_cpu(recv_mfg_data->rng_seed) + app_ble.scanner_random_share;
            req.start_delay_us = 0;
            req.extra_window_time_us = 0;

            dm_request_add(&req);
        }
        return false;
    default:
        return true;
    }
}

static void app_ble_adv_scanned_cb(struct bt_le_ext_adv* adv, struct bt_le_ext_adv_scanned_info* info)
{
    struct dm_request req;

    if (peer_supported_test(info->addr) == true)
    {
        bt_addr_le_copy(&req.bt_addr, info->addr);
        req.role = DM_ROLE_REFLECTOR;
        req.ranging_mode = DM_RANGING_MODE_MCPD;

        req.rng_seed = peer_rng_seed_get() + app_ble_scanner_addr_to_random_share(&info->addr->a);
        req.start_delay_us = 0;
        req.extra_window_time_us = 0;

        dm_request_add(&req);
        app_ble_adv_update_data();
    }
}

What should be checked when an MPSL assert happens? Is there any helpful guide on how does the MPSL internally works, or how is it used in the Distance Measurement Library? What might cause such assert error?

How to explain the difference in the error behavior between the EvalBoard and the custom hardware? What might cause the Logging output to be visible in one hardware but not in another?

Any idea or comment would be helpful.

Thanks in advance

Regards

Javier

[mathiaso]

Hi, Javier.

Thank you for reaching out. Have you made any changes to the sample you're using?

Additionally,

• Does the application disable interrupts?
• Does the application use the highest interrupt priority?
• Is the application using a timeslot?
• Did you perform any changes to the DT? Could you upload your zephyr.dts file?

From other posts here we might interpret that it might be a timing problem with an interrupt, but we are not directly stopping or missusing any interrupt that we know of.

What timeout did you use for uart_rx_enable?

Best regards,
Mathias

[Javier Reyes]

Hi, thanks for the fast feedback. To your questions:

We integrated the example (nrf_dm) in our code. What I meant is that we only took the part specific for distance measurement, and not the parts that create the DDFS service, or the part for the PWM to the LED, or the simulation of the Azimuth.

We do not disable interrupts anywhere in our code.

Our application uses the default priority (all is done from the main function aka the main task).

We do not use MPSL timeslots directly, but as far as we understand, the DM library uses it. We are not sure if the BLE stack itself uses MPSL and how. See the config for both Central and Peripheral in the initial post, that contains the configs:

CONFIG_MPSL=y
CONFIG_MPSL_TIMESLOT_SESSION_COUNT=1
CONFIG_MPSL_WORK_STACK_SIZE=2048

We have a DT overlay that defines the timer for the DM library (timer2, as in the nrf_dm example) and pins for UART1 with HW control flow.

/ {
     chosen {
        ncs,dm-timer = &timer2;
    };
};

&uart1 {
    compatible = "nordic,nrf-uarte";
    status = "okay";
    pinctrl-0 = <&uart1_default>;
    pinctrl-1 = <&uart1_sleep>;
    pinctrl-names = "default", "sleep";
    current-speed = <115200>;
    hw-flow-control;
};

&pinctrl {
    uart1_default: uart1_default {
        group1 {
            psels = <NRF_PSEL(UART_TX, 0, 28)>, <NRF_PSEL(UART_RX, 0, 29)>, <NRF_PSEL(UART_CTS, 1, 06)>, <NRF_PSEL(UART_RTS, 1, 04)>;
        };
    };

    uart1_sleep: uart1_sleep {
        group1 {
            psels = <NRF_PSEL(UART_TX, 0, 28)>, <NRF_PSEL(UART_RX, 0, 29)>, <NRF_PSEL(UART_CTS, 1, 06)>, <NRF_PSEL(UART_RTS, 1, 04)>;
            low-power-enable;
        };
    };
};

The timeout for the UART (Async API) is currently 500 microseconds. It should be noted, that the callback from UART does no blocking at all, and does not interact with BLE or DM functions at all.

static void uart1_event_cb(const struct device *dev, struct uart_event *evt, void *user_data)
{
    if (dev == NULL || evt == NULL)
    {
        return;
    }

    switch (evt->type)
    {
    case UART_TX_DONE:
        if (app_uart.tx_status == UART_TX_STATUS_SENDING)
        {
            /* The State Machine is waiting for this event to go back to idle */
            app_uart.tx_status = UART_TX_STATUS_SENT;
        }
        else
        {
            RTT_LOG_WRN("Unexpected UART TX status: %d", app_uart.tx_status);
        }
        break;
    case UART_TX_ABORTED:
        if (app_uart.tx_status == UART_TX_STATUS_SENDING)
        {
            /* The State Machine can also wait for this event to go back to idle */
            app_uart.tx_status = UART_TX_STATUS_ERROR;
            RTT_LOG_ERR("UART TX aborted");
        }
        break;
    case UART_RX_RDY:
        if ((evt->data.rx.buf != NULL) &&
            (evt->data.rx.len > APP_UART_RX_MIN_SIZE) &&
            (evt->data.rx.len <= APP_UART_BUFFER_SIZE))
        {
            app_uart.rx.buf_len = evt->data.rx.len;
            for (size_t i = 0; i < APP_UART_QUEUE_NUM_ITEMS; ++i)
            {
                if (app_uart.fifo_storage.items[i].len == 0)
                {
                    app_uart.fifo_storage.items[i].len = app_uart.rx.buf_len;
                    memcpy(app_uart.fifo_storage.items[i].data, &evt->data.rx.buf[evt->data.rx.offset], app_uart.rx.buf_len);
                    /* To restart the DMA, UART needs to be disabled first. It will be shortly re enabled in the UART_RX_DISABLED event */
                    int err;
                    if ((err = uart_rx_disable(uart1_dev)) < 0)
                    {
                        RTT_LOG_ERR("IRQ uart_rx_disable %d", err);
                    }
                    /* Address of the FIFO slot is sent to the State Machine */
                    k_fifo_put(&app_uart.fifo, &app_uart.fifo_storage.items[i]);
                    break;
                }
                else if (i == APP_UART_QUEUE_NUM_ITEMS - 1)
                {
                    RTT_LOG_WRN("No FIFO items for UART RX");
                }
            }
        }
        else
        {
            RTT_LOG_WRN("Wrong UART Event params: %p, %u", (void*)evt->data.rx.buf, evt->data.rx.len);
        }
        break;
    case UART_RX_BUF_REQUEST:
        break;
    case UART_RX_BUF_RELEASED:
        break;
    case UART_RX_DISABLED:
        /* UART RX was disabled in the UART_RX_RDY event to restart the DMA, hier RX is started again */
        int err;
        if ((err = uart_rx_enable(uart1_dev, app_uart.rx.buf, sizeof(app_uart.rx.buf), APP_UART_IDLE_TIMEOUT_US)) < 0)
        {
            RTT_LOG_ERR("IRQ uart_rx_enable %d", err);
        }
        break;
    case UART_RX_STOPPED:
        RTT_LOG_ERR("UART_RX_STOPPED");
        break;
    default:
        break;
    }
}

Regards,

Javier

[mathiaso]

Sorry for the lack of response here, Javier.

I've forwarded the information you provided internally and am still waiting for an update.

Best regards,
Mathias