Reason/details for ERROR 17 [NRF_ERROR_BUSY]

[MarieMaurer]

Hello,

when my application runs, from time to time I see the following:

[00:00:29.000,000] <debug> nrf_sdh_ble: BLE event: 0x26.
[00:00:29.000,000] <error> app: ERROR 17 [NRF_ERROR_BUSY] at :0
PC at: 0x00000000
[00:00:29.000,000] <error> app: End of error report
[00:00:29.000,000] <warning> app: System reset

My application uses latest S132 and SDK 17.2.0. Currently only for a test, I am doing heavy SPI traffic, perhaps interrupt routine for SPI (via GPIOTE) is called too often, but it is not very long. I have no Bluetooth connection established at all during this time. Just collecting data and printing them out in main thread via NRF_LOG_INFO via serial port.

I searched for the error and saw e.g. this

https://devzone.nordicsemi.com/f/nordic-q-a/49085/spim-error-17-nrf_error_busy

but "volatile" was already there.

Can you tell me what the error means? What does it check? If I used too much time and Softdevice is getting too less time, is there perhaps some page with some details above it? Must I cut my interrupt routine in smaller junks? Move more outside interrupt routine?

BTW: I tried using DWT_CYCCNT. A bit it runs, but later in my app it does not work anymore, returning always the same data. Is it used by SoftDevice, so not free for me to use? Is it perhaps used for the above check?

Best regards,

Marie

[MarieMaurer]

One more trace, with a different event number:

[00:00:26.00[00:00:26.000,000] <info> app: 2715

[00:00:26.000,000] <debug> nrf_sdh_ble: BLE event: 0x10.

[00:00:26.000,000] <error> app: ERROR 17 [NRF_ERROR_BUSY] at :0

PC at: 0x00000000

[00:00:26.000,000] <error> app: End of error report

[00:00:26.000,000] <warning> app: System reset

If you want me to try something out, or deliver more info, please let me know. I can reproduce it very good in our test rack.
Meanwhile, a version which has 30 times less SPI/GPIOTE interrupts, but each interrupt is 30 times longer, show the same error.

0x10 / 0x26 is the following?

"BLE_GAP_EVT_CONNECTED", /*0x10*/
...
"BLE_GAP_EVT_ADV_SET_TERMINATED", /*0x26*/

---

Some news! It was running on my desk for over two hours without any reset.
Now I tried to query characteristics (with nRF-Connect-App) in parallel and each time

I do this, I get a reset now with this ouput:

[00:02:04.000,000] <info> app: data 12243 1280 -5120 -15616
[00:02:04.000,000] <info> app: data 12244 1280 -5376 -15872
[00:02:04.000,000] <debug> nrf_sdh_ble: BLE event: 0x39.
[00:02:04.000,000] <info> app: 396/0/0
[00:02:04.000,000] <info> app: data 12245 1[00:02:04.000,000] <info> app: data 12245 1280 -5120 -16128
[00:02:04.000,000] <debug> nrf_sdh_ble: BLE event: 0x3A.
[00:02:04.000,000] <error> app: ERROR 17 [NRF_ERROR_BUSY] at :0
PC at: 0x00000000
[00:02:04.000,000] <error> app: End of error report
[00:02:04.000,000] <warning> app: System reset

[Vidar Berg]

Hello,

 

MarieMaurer said:

[00:00:26.000,000] <error> app: ERROR 17 [NRF_ERROR_BUSY] at :0

PC at: 0x00000000

Have you confirmed that the busy error is always returned from the SPIM send function? The crash log will usually include the file name and line number in addition to the error code, but I notice it is not doing it here. Maybe you are not using the default app_error_fault_handler() implmentation?

MarieMaurer said:

0x10 / 0x26 is the following?

"BLE_GAP_EVT_CONNECTED", /*0x10*/
...
"BLE_GAP_EVT_ADV_SET_TERMINATED", /*0x26*/

 Yes, correct.

Best regards,

Vidar

[MarieMaurer]

Further investigation shows that I am coming from this function:

void app_error_handler_bare(ret_code_t error_code)
{
    error_info_t error_info =
    {
        .line_num    = 0,
        .p_file_name = NULL,
        .err_code    = error_code,
    };

    app_error_fault_handler(NRF_FAULT_ID_SDK_ERROR, 0, (uint32_t)(&error_info));

    UNUSED_VARIABLE(error_info);
}

It has line_num=0 and p_file_name=NULL, so no info to display. Therefore in my logs I see ":0".

If I do init of SPI sensor, but let never fire my SPI interrupt, then also got no reset. Instead a normal working debug output:

[00:00:08.000,000] <debug> nrf_sdh_ble: BLE event: 0x10.
[00:00:08.000,000] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 40 bytes on connection 0x0.
[00:00:08.000,000] <debug> nrf_ble_gatt: Updating data length to 37 on connection 0x0.
[00:00:08.000,000] <info> app: Connected.
[00:00:08.000,000] <info> app: Initialized ADC
[00:00:08.000,000] <debug> nrf_sdh_ble: BLE event: 0x39.
[00:00:08.000,000] <debug> nrf_sdh_ble: BLE event: 0x3A.
[00:00:08.000,000] <debug> nrf_ble_gatt: ATT MTU updated to 40 bytes on connection 0x0 (response).
[00:00:09.000,000] <debug> nrf_sdh_ble: BLE event: 0x14.
[00:00:09.000,000] <info> peer_manager_handler: Connection security failed: role: Peripheral, conn_handle: 0x0, procedure: Encryption, error: 4102
[00:00:09.000,000] <debug> app: Value write: 1
[00:00:09.000,000] <info> app: Writing file: 0xA010, key: 0xA004, len: 1 words, 4 bytes
[00:00:09.000,000] <info> app: Write Record ID: 0x0002  File ID: 0xA010 Record key: 0xA004
[00:00:09.000,000] <info> app: Battery: 2756mV TempAdj: 10mV, 20%
[00:00:09.000,000] <debug> app: Value write: 2766
[00:00:09.000,000] <info> app: Writing file: 0xA010, key: 0xA008, len: 1 words, 4 bytes
[00:00:09.000,000] <info> app: Write Record ID: 0x0003  File ID: 0xA010 Record key: 0xA008
[00:00:09.000,000] <debug> nrf_sdh_ble: BLE event: 0x11.
[00:00:09.000,000] <debug> app: pm_whitelist_get returns 0 addr in whitelist and 0 irk whitelist
[00:00:09.000,000] <info> app: Fast advertising.
[00:00:09.000,000] <info> app: Disconnected, reason 19.
[00:00:09.000,000] <info> app: Shut off ADC
[00:00:39.000,000] <debug> nrf_sdh_ble: BLE event: 0x26.
[00:00:39.000,000] <debug> app: pm_whitelist_get returns 0 addr in whitelist and 0 irk whitelist
[00:00:39.000,000] <info> app: Slow advertising.

So it looks it has something to do with SPI interrupt via GPIOTE?

[MarieMaurer]

Hopefully not completely wrong...?

As you can see in above log, I not only collect a lot values, but also dump them via NRF_LOG_INFO.
100 times per second * 61 bytes per line.

I have searched a bit, there was a switch if file and line shall be included or app_error_handler_bare is used.
I have commented out this check and now got a file and line number:

It is this function and check:

static void serial_tx(void const * p_context, char const * p_buffer, size_t len)
{
uint8_t len8 = (uint8_t)(len & 0x000000FF);
m_xfer_done = false;
ret_code_t err_code = nrf_drv_uart_tx(&m_uart, (uint8_t *)p_buffer, len8);
APP_ERROR_CHECK(err_code); /* wait for completion since buffer is reused*/
while (m_async_mode && (m_xfer_done == false)) { }
}

So nrf_drv_uart_tx() is failing.

So perhaps debug logging is not fast enough to print out all info?
I just commented out only printing of info and then Bluetooth connection is working again without resetting.

There is at least a BUSY error code used:

if (nrfx_uarte_tx_in_progress(p_instance))
{
    err_code = NRFX_ERROR_BUSY;
    NRFX_LOG_WARNING("Function: %s, error code: %s.",
                     __func__,
                     NRFX_LOG_ERROR_STRING_GET(err_code));
    return err_code;
}

Additional notice/test: Error happens only if NRF_LOG_DEFERRED is 0.
Otherwise (if it is 1, DEFERRED enabled) it is also working without a reset.
(I had switched it off because then debugging is easier)

[Vidar Berg]

I think you have found the problem :) Because it  looks like the logging queue may be processed from both interrupt and non-interrupt contexts when NRF_LOG_DEFERRED  is disabled, which may lead to a reentry into serial_tx().