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

[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().