Zephyr uarte library missing UART_RX_BUF_RELEASED events

[Kyrre Aalerud]

I run newest nRF53 chip as of writing with 1.6.0 nRF Connect SDK from nRF Connect Toolchain manager 3.6.1 using SES 5.50c.

I use a array of 5 rx-buffers (Increased from 3 to figure out what was going on) and handle UART_RX_BUF_REQUEST and UART_RX_BUF_RELEASED events in the registered callback.
Most of the time it runs fine but during a continuous test I notice that at random intervalls it may skip a UART_RX_BUF_RELEASED event which leads my application to detect a request of using a buffer that is not yet freed. If these buffers had been allocated dynamically this would have caused a memory leak. Instead I catch it and log it while actually allowing the reassigning of already assigned buffer.

Since I use the buffers round-robin and process data (transfer to other threads) during any UART_RX_RDY events I do not miss data but this behavior is worrying.
Is there a race-condition in the library?

[Susheel Nuguru]

Hi Kyrre,

Sounds very much like a race condition. I need to understand more about the chain of events that happened before digging into the code. Could you please help me understand with these questions.

1. Your application seems to be tracking which buffer is free and not instead of relying solely on these events. Is it possible that the application tracking logic might have a race condition? Could you rule that out?
2. Could you provide me the chain of UART events that are received by your application (a log file with a way to see EVENTS/buffer mapping would help).
3. What other application peripheral interrupts are enabled and being used when your application detected that a request arrived for a buffer that is not yet free?

[Kyrre Aalerud]

The logs are very long before things happen so I had to use pastebin. Bottom of the log is the relevant part but all is included.

Log of REQ and FREE

The app keeps track of this array separately but it prints each event as they occur in the log.
It is clear that a free event does not happen. It does ask for two buffers in quick succession without freeing buffer 3 though, but frees 3 right after.

[Kyrre Aalerud]

Here is the same log with RX events as well. I had to compact it a bit to fit within 512k pastebin limits.
https://pastebin.com/15AJpMP9

[Susheel Nuguru]

This smells like a race condition but before that can you please explain to me what the number next to "Buf FREE X" means here? Is X something that is tracked by your application or you identify the index based on the buff pointer or you identify the buffer index freed based on some other logic?

In the above highlighted context, why does your application think that Buf Free is index 1 instead of index 0?

It looks like two buffer request can come in succession if second buffer is already given and is full before the application can process the UART_RX_RDY/UART_RX_BUF_RELEASED events. This might be something undocumented behavior but might not necessary translate to a missed event. It is possible that the Free event got postponed and your application index tracking is now confused due to two buffer requests coming in succession.

[Kyrre Aalerud]

My application checks the buffer reference and compares to it's list of buffers to identify the buffer number being freed.
The buffers are allocated statically so these values/pointers never change.

Buf FREE x means it has identified the referenced buffer as buffer number x from 0 to 4.

It always responds to a buffer request with the next buffer in succession and starts the system by setting up the enable rx call using buffer 0. The Buf 1 request event has been logged inbetween something else during startup and thus was missing in the log but happened correctly.

Since I run a total of 5 buffers to debug this issue I see it usually always frees a buffer immediately once full, however this does not appear to always happen which leads me to believe the problem is either in the hardware or in the library during the handling of the events. I am thinking that there may exist a short timeframe where a flag may be set by hardware buy is cleared by software before or after the execution of the rx events callback etc.