nRF52840 logging crashes in FreeRTOS

[Nopik]

Recently I have encountered a software hanging issue on one of our products. It was based on nRF52840, with FreeRTOS (Thread SDK v1.0). The issue was apparently related to NRF_LOG_* stuff - if I added lots of logs, software would hang very quickly (whole FreeRTOS seems to be hanging - not just one task). If I have moderate amount of logs, crashes were random and rare. After a bit, I managed to reproduce this problem on PCA10056 board (to rule out our hardware), and then on one of the examples provided within the SDK.

To reproduce the issue:

- download fresh Thread SDK 1.0

- replace examples/thread/freertos_coap_server/main.c with https://gist.github.com/Nopik/6efc683c0f5cfd709302261b81ccee4d

- make

- nrfjprog -f NRF52 --chiperase --program _build/nrf52840_xxaa.hex

- connect RTT viewer (I'm using JLink + JLinkRTTClient)

- run CPU (I'm using just 'r' in JLink)

- some logs should appear in large amounts on RTT, leds should be blinking

- if leds are still blinking after 10-20 seconds, reset CPU and start it again (I'm using just 'r' and 'g' in JLink)

Expected behavior: CPU never crashes, example runs indefinitely

Observed behavior: CPU halts very often. Sometimes after 7 logs, sometimes after 9500 of them. On my setup, I just started CPU 10 times, 3 times it was running for at least 20 seconds (and I did reset manually), 4 times it hung after 7 debugs, 3 times it hung after few seconds (logs number 9713, 8529, and 11639, respectively).

It seems, that the hangs still occur, even if we remove NRF_LOG_INFO() from led task. They stop occurring only if I remove log flushing task as well.

I tested it on MacOS and Linux machines, on 2 different PCA10056 boards, also on custom software running on custom board. Interestingly, we've been developing our software for quite long time, and been using logging a lot - and this is first time we've encountered instability like this.

On our software, if deferred logs are turned off, situation is much worse, usually crashes are much more frequent.

Is this known bug? Any fix recommended?

[Susheel Nuguru]

Hi Nopik,

FreeRTOS does not do any flash operations by itself. I would not correlate the flash corruption to FreeRTOS. Flash operations are application specific and could go wrong if you gave an uninitialized pointer to a flash operation. 

Adding a lot of logs seems to worsen the behavior, which indicates that there must be a timings issue too. It is really hard for us to narrow down the problem without getting your whole setup to replicate the issue. 

[Nopik]

Did you tried to reproduce the flash corruption issue, as I described here?

[Susheel Nuguru]

Hi Nopik, This thread somehow skipped my queue, otherwise I would not miss this for so many days. Sorry about that. I just tried to test your code, I see what you see now. Very strange that the flash is getting corrupted. I am debugging this now. Will be back to you when i find something.

[Susheel Nuguru]

Nopik,

What is your usecase exactly? why do you want to reset the hardware with such a high frequency?

There is some flash activity(Read/Write) happening in the initialization phase and I am almost certain that such frequent resets would interrupt an ongoing flash activity. As the result of this the behavior of the thread stack would become unpredictable and eventually cause a hardfault. Looking at the call stack of when the hardfault occurs, it matches my theory that it happens when there is a flash read from a previous written (interrupted write, most probably, corrupting the flash).

[Nopik]

The high frequency reset was just a by-product of trying to revel the logging crash (which started this thread). I though I was able to reproduce easily it earlier, but apparently I wasn't. But since I've realized, that in many cases logging is crashing mostly in first few milliseconds, I added quick resets to pinpoint the problem. It, however, uncovered the flash corruption problem, instead.

[Susheel Nuguru]

Hi Nopik,

The flash corruption is clearly a bi-product of the high frequency reset. Please let me know of any other way of reproducing this issue other than this reset.