ASYNC uart and UART_RX_RDY timeout

[mmm]

I saw some similar question, but none is what I am experiencing.

I notice some weird behavior while testing DMA mode, so I made a simple setup:

I set the DMA buffer to be 100 bytes, and a timeout of 100ms, and a custom callback:

uart_callback_set(dev_uart, app_uart_async_callback, NULL);

uart_rx_enable(dev_uart, uart_double_buffer[0], UART_BUF_SIZE, UART_RX_TIMEOUT_MS);

Then on PC side, i send message of 10 bytes, this is to make sure there is no buffer switch, only timeout from UART_RX_RDY, to avoid any possible mistake with buffer management.

Baudrate is 921600

WHAT DO I EXPECT:

100ms after i sent the message, the callback app_uart_async_callback() get called with event data rx.buf containing my 10 byte message, rx.offset to be 0, and rx.len of 10

If i send another message, the same as above, only difference is the rx.offset is now 10.

And so on until the buffer is full and all the required callback to change buffer get called

WHAT IS HAPPENING:

while sending the message from pc, the callback app_uart_async_callback() get called with event data rx.buf containing ONLY X bytes, rx.offset to be 0, and rx.len of X, where X is between 1 and 10; the TIMEOUT is not respected at all!

What is worse is that i do NOT get a second callback with the remaining data!

Now, at this point, if i send an extra message lets say 1 bytes, the callback is called and all, with rx.len = 1, but as result i see the OLD data that was not served!

MY CONCLUSION:

- according to docs, the TIMEOUT should start at the END of the last bytes, as it is inactivity, this is NOT happening

- even if timeout is counting since the first message is received, ad 921600 baud i should be able to receive 9216 bytes before timeout

- clearly something is wrong in the way the timeout for UART_RX_RDY or the event rx.len is calculated!

- this lead to possibility where data is received, and my application has NO WAY to know it has been

- UART_RX_BUF_REQUEST and RELEASED seems to work properly and get called at the right time, with the correct amount of data in rx.len. SEEMS because due to the delay output, is a bit difficult to notice if data is missing without a proper automated test.

[Edvin]

Hello,

What NCS version are you using? The reason I ask is that we have a bug in some of the previous ncs versions (fixed in v2.4.0) where the uart_rx_enable() expects a timeout in microseconds, but we provided it in milliseconds. So depending on what your UART_RX_TIMEOUT_MS is set to, it may only receive 1/1000 of what you expect it to be. 

If that is the issue, the fix is easy. Just increase the UART_RX_TIMEOUT_MS by a factor of 1000, and you should be fine. 

Let me know if that doesn't help.

Best regards,

Edvin

[mmm]

Hi, long time, new update.

Im testing with toolchain 2.4.2 and seems better but still some issues.

Output and code from my test follow.
First column is time in seconds, if data is send/received and what is sent/received (received data has b'' around them as i print the raw bytes, to see if i get weird non-visible ascii bytes, for example \n is an actual line feed)

The test send a message every 2 seconds, the nrf is set to 100ms timeout, and send back data immediately.

1 byte is systematically not reported as received (tested with different length of data, seems always 1 is "lost"), the buffer swap happen correctly at 100 bytes, and all no data is lost.

1697713032.61: sent: 0123456789
1697713032.811: recv: b'INF: got 9 bytes\nDATA: -012345678-\n'
1697713034.618: sent: 0123456789
1697713034.818: recv: b'INF: got 9 bytes\nDATA: -901234567-\n'
1697713036.624: sent: 0123456789
1697713036.825: recv: b'INF: got 9 bytes\nDATA: -890123456-\n'
1697713038.631: sent: 0123456789
1697713038.832: recv: b'INF: got 9 bytes\nDATA: -789012345-\n'
1697713040.638: sent: 0123456789
1697713040.839: recv: b'INF: got 9 bytes\nDATA: -678901234-\n'
1697713042.645: sent: 0123456789
1697713042.846: recv: b'INF: got 9 bytes\nDATA: -567890123-\n'
1697713044.652: sent: 0123456789
1697713044.853: recv: b'INF: got 9 bytes\nDATA: -456789012-\n'
1697713046.66: sent: 0123456789
1697713046.861: recv: b'INF: got 9 bytes\nDATA: -345678901-\n'
1697713048.667: sent: 0123456789
1697713048.868: recv: b'INF: got 9 bytes\nDATA: -234567890-\n'
1697713050.674: sent: 0123456789
1697713050.774: recv: b'INF: detected end of buffer for 19 bytes\nDATA: -1234567890123456789-\n'
1697713052.681: sent: 0123456789
1697713052.882: recv: b'INF: got 9 bytes\nDATA: -012345678-\n'
1697713054.688: sent: 0123456789
1697713054.889: recv: b'INF: got 9 bytes\nDATA: -901234567-\n'

Code python:

import serial
import time

last_write = time.time()
with serial.Serial('/dev/ttyACM0', 921600, timeout=0.1) as ser:
 while True:
 x = ser.read(100) # read one byte
 if len(x):
 print(f"{round(time.time(), 3)}: recv: {x}")
 if time.time() - last_write >= 2:
 last_write = time.time()
 msg = "0123456789ABCDEFGHILMNOPQRSTUVZ"
 print(f"{round(time.time(), 3)}: sent: {msg}")
 ser.write(msg.encode("ascii"))
print("failed to open serial")

Code NRF:

#include <zephyr/types.h>
#include <zephyr/kernel.h>
#include <zephyr/drivers/uart.h>
#include <zephyr/usb/usb_device.h>

#include <zephyr/device.h>
#include <zephyr/devicetree.h>
#include <soc.h>

#include <stdio.h>

#define LOG_MODULE_NAME peripheral_uart
LOG_MODULE_REGISTER(LOG_MODULE_NAME);

uint8_t uart_buffer_rx[100];
volatile size_t uart_buffer_written = 0;
volatile size_t uart_buffer_completed = 0;
volatile bool disabled = true;

static const struct device *uart = DEVICE_DT_GET(DT_CHOSEN(nordic_nus_uart));

const int32_t UART_RX_TIMEOUT_US = 1000 * 100; // 100 millisecond timeout

void app_uart_async_callback(const struct device *uart_dev, struct uart_event *evt, void *user_data) {
 switch (evt->type) {
 case UART_TX_DONE:
 // do nothing
 break;
 
 case UART_RX_RDY:
 uart_buffer_written += evt->data.rx.len;
 break;
 
 case UART_RX_BUF_REQUEST:
 //assign same buffer; basically this is now a circular buffer
 uart_rx_buf_rsp(uart, uart_buffer_rx, sizeof(uart_buffer_rx));
 uart_buffer_completed++;
 uart_buffer_written = 0; 
 break;

 case UART_RX_BUF_RELEASED:
 break;

 case UART_RX_DISABLED:
 disabled = true;
 break;
 
 default:
 break;
 }
}

static int uart_init(void) {
 int err = 0;
 struct uart_config serial_config;
 uart_config_get(uart, &serial_config);
 uart_configure(uart, &serial_config);

 if (!device_is_ready(uart)) {
 return -ENODEV;
 }

 err |= uart_callback_set(uart, app_uart_async_callback, NULL);
 err |= uart_rx_enable(uart, uart_buffer_rx, sizeof(uart_buffer_rx), UART_RX_TIMEOUT_US);
 disabled = false;
 return err;
}

void log(const char *msg, ...) {
 static char s[1000];
 va_list argptr;
 va_start(argptr, msg);
 size_t len = vsnprintf(s, sizeof(s), msg, argptr);
 va_end(argptr);
 
 uart_tx(uart, s, len, SYS_FOREVER_MS);
 k_sleep(K_MSEC(1)); //92 char
}

void error(void) {
 while (true) {
 /* Spin for ever */
 k_sleep(K_MSEC(1000));
 }
}

int main(void) {
 int err = 0;

 err = uart_init();
 if (err) {
 log("ERR: uart_init");
 error();
 }

 log("started!");

 size_t last_uart_buffer_written = uart_buffer_written;
 size_t last_uart_buffer_completed = uart_buffer_completed;
 for (;;) {
 if (disabled){
 uart_rx_enable(uart, uart_buffer_rx, sizeof(uart_buffer_rx), UART_RX_TIMEOUT_US);
 if (err == 0)
 disabled = false;
 log("ERR: Serial re-enabled");
 }
 size_t number_of_oveflow = uart_buffer_completed - last_uart_buffer_completed;
 switch (number_of_oveflow){
 default: 
 {
 log("ERR: TOO MANY OVERFLOW FOR %d TIMES", number_of_oveflow);
 // we want to fallthrough to read whatever we got
 }
 case 1:
 {
 // now we print remaining buffer
 size_t remaining_data = sizeof(uart_buffer_rx) - last_uart_buffer_written;
 log("INF: detected end of buffer for %d bytes\n", remaining_data);
 log("DATA: -%.*s-\n", remaining_data, uart_buffer_rx+last_uart_buffer_written);
 // now reset buffer counters
 last_uart_buffer_completed += number_of_oveflow;
 last_uart_buffer_written = 0;
 // we want to fallthrough to read the initial data
 }
 case 0:
 {
 size_t available = uart_buffer_written - last_uart_buffer_written;
 if (!available){
 break;
 }
 log("INF: got %d bytes\n", available);
 log("DATA: -%.*s-\n", available, uart_buffer_rx+last_uart_buffer_written);
 last_uart_buffer_written += available;
 }
 }
 k_sleep(K_MSEC(10));
 }
}

[Einar Thorsrud]

Hi,

Edvin is our of office so the case has been re-assigned. We will look into it and get back to you. Please let us know if you have had any updates on your end in the meantime.

Br,

Einar

[Øivind]

Hi,

From your log it seems that the single byte is not lost, as it is included at the start of the following message.

Could you try debugging and check where this byte is when the RX RDY event is triggered in your event handler? Check the contents of the RX buffer and whether data.rx.len matches the number of bytes in the RX buffer. A logic trace on the UART lines could also be insightful.

[mmm]

> From your log it seems that the single byte is not lost, as it is included at the start of the following message.

correct, this ticket is not about data getting lost, but UART_RX_RDY reporting an incorrect number of bytes received.

With 2.4.0 the number was kinda random, with 2.4.2 seems is it always under-reported by 1, but may be just a coincidence.

> Could you try debugging and check where this byte is when the RX RDY event is triggered

I do see the byte are all the 10 bytes in the buffer as expected; but UART_RX_RDY's evt->data.rx.len is wrong

[Øivind]

Hi, an update, we have received multiple tickets about this, so it appears that it may be a bug in the driver. I am currently looking into these reports and I'll keep you updated.

[MrBurvall]

Hello mmm,

Where you able to find a solution for this problem?

I see the same behavior, workaround for me is to send some extra data, which is ignored. This triggers UART_RX_RDY.

Best Regards, Markus