Zephyr async uart driver corrupts data on UARTE frame timeout

[Nick Ewalt]

Related to the issue reported here:  RE: Framing Errors seen on nRF54L15 UART. Is it super sensitive to stop bit timing? 

If the UARTE FRAMETIMEOUT fires while new data is coming in then some bits of the new data is dropped, leading to corruption and potentially framing errors.

I've attached a loopback sample app that reliably reproduces this issue within seconds on the nRF54L15 DK. Simply connect a jumper wire between pins P1.11 and P1.12 then build and flash the image for the nrf54l15dk/nrf54l15/cpuapp board.

async_uart_echo.tar.gz

[Nick Ewalt]

On my board with a frame timeout of 5000 us at 115200 baud I see that delays between 4920 us and 5430 us fail, but everything outside of that range works perfectly.

Here are the logs from the start of that failing region. Full logs attached.

[00:00:06.368,093] <dbg> app: main: testing delay of 4900 us
[00:00:06.379,810] <dbg> app: on_rx_data_ready: RX data
                              30 31 32 33 34 35 36 37  41 42 43 44 45 46 47 48 |01234567 ABCDEFGH
[00:00:06.434,494] <dbg> app: main: testing delay of 4910 us
[00:00:06.446,230] <dbg> app: on_rx_data_ready: RX data
                              30 31 32 33 34 35 36 37  41 42 43 44 45 46 47 48 |01234567 ABCDEFGH
[00:00:06.500,933] <dbg> app: main: testing delay of 4920 us
[00:00:06.507,083] <dbg> app: on_rx_data_ready: RX data
                              30 31 32 33 34 35 36 37  41 42 43 44 45          |01234567 ABCDE   
[00:00:06.512,695] <dbg> app: on_rx_data_ready: RX data
                              47 48                                            |GH               
[00:00:06.517,343] <err> app: unexpected number of bytes received: 15
[00:00:06.517,355] <err> app: test_buffer
                              30 31 32 33 34 35 36 37  41 42 43 44 45 47 48    |01234567 ABCDEGH 
[00:00:06.617,408] <dbg> app: main: testing delay of 4930 us
[00:00:06.623,544] <dbg> app: on_rx_data_ready: RX data
                              30 31 32 33 34 35 36 37  41 42 43 44 45          |01234567 ABCDE   
[00:00:06.629,226] <dbg> app: on_rx_data_ready: RX data
                              1d 21 ff                                         |.!.              
[00:00:06.633,823] <err> app: got corrupted data
[00:00:06.633,835] <err> app: test_buffer
                              30 31 32 33 34 35 36 37  41 42 43 44 45 1d 21 ff |01234567 ABCDE.!.
[00:00:06.733,886] <dbg> app: main: testing delay of 4940 us
[00:00:06.740,030] <dbg> app: on_rx_data_ready: RX data
                              30 31 32 33 34 35 36 37  41 42 43 44 45          |01234567 ABCDE   
[00:00:06.740,108] <dbg> app: on_rx_data_ready: RX data
[00:00:06.740,114] <err> app: UART framing error
[00:00:06.740,194] <dbg> app: on_rx_data_ready: RX data
[00:00:06.740,200] <err> app: UART framing error
[00:00:06.745,701] <dbg> app: on_rx_data_ready: RX data
                              fd                                               |.                
[00:00:06.750,362] <err> app: unexpected number of bytes received: 14
[00:00:06.750,377] <err> app: test_buffer
                              30 31 32 33 34 35 36 37  41 42 43 44 45 fd       |01234567 ABCDE.  

async_uart_log2.txt

[Nick Ewalt]

Note that in order to not have the driver immediately stop the peripheral on the first framing error you need to comment the call to uarte_nrfx_rx_disable(dev) in error_isr (drivers/serial/uart_nrfx_uarte.c).

[Elfving]

Hi,

Thanks for the heads-up, and the way to reproduce it. 

We're aware of the issue now and are working on it. Please talk to your RSM if you need this solved urgently and want us to prioritize this bug.

Regards,

Elfving

[jeroen_dekimo]

We're also experiencing this issue. 
We're using a custom protocol where a uart BREAK is immediately followed by (at least) two bytes of data. Due to this issue, we are not able to capture those bytes, and get framing errors instead. Further data (~2-3ms after the BREAK signal) also seems to get received wrongfully.

Tested on the nRF54L15DK. (with 19200 BAUD rate)

[Hardik Harpal]

Hi Elfving, 

we are having similar issue. Getting framing error and garbage character received. 

We have two boards one with NRF52840 which we are running on NRF5 SDK16 and in the similar board (Only MCU changed, no other change on board) with NRF54L15 running on NCS v3.0.2. 

With NRF52840 SDK16 no issue faced.

On NRF54L15, Schematic already reviewed by Nordic. We are using UART30, P0.0 and P0.1 gpio used.

See bellow logs for different cases. where we are getting error while communicating with cellular modem.


Log 1:  

00> [00:00:17.400,794] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:00:17.400,806] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:00:17.400,968] <err> app_uart: RX stopped: reason 4
00> [00:00:17.401,080] <err> app_uart: RX stopped: reason 4
00> [00:00:17.401,367] <err> app_uart: RX stopped: reason 4
00> [00:00:17.401,512] <dbg> app_uart: free_rx_buf: Freed RX buffer 2
00> [00:00:17.401,522] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:00:17.401,533] <dbg> app_uart: app_uart_cb: RX disabled, restarting with timeout
00> [00:00:17.401,561] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:00:17.401,642] <err> app_uart: RX stopped: reason 4
00> [00:00:17.401,726] <err> app_uart: RX stopped: reason 4
00> [00:00:17.401,935] <err> app_uart: RX stopped: reason 4
00> [00:00:17.402,170] <dbg> app_uart: free_rx_buf: Static rx_buf released; ignoring.
00> [00:00:17.402,182] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:00:17.402,192] <dbg> app_uart: app_uart_cb: RX disabled, restarting with timeout
00> [00:00:17.402,210] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:00:17.431,399] <dbg> app_uart: free_rx_buf: Static rx_buf released; ignoring.
00> [00:00:17.431,420] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 2
00> [00:00:17.866,819] <dbg> app_cellular: Cell_Parser: Cell App Ready
00> [00:00:17.866,846] <inf> app_uart: app_uart_clear_rx_buf:
00> RDY
00>
00> +CFUN: 1
00>
00> +QUSIM: 1
00>
00> +TJ5ʪH
00> +CPIN: READY
00>
00> APP RDY


Log 2:

00> [00:08:13.248,710] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:08:13.248,731] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:08:13.249,054] <err> app_uart: RX stopped: reason 4
00> [00:08:13.249,140] <err> app_uart: RX stopped: reason 4
00> [00:08:13.249,226] <err> app_uart: RX stopped: reason 4
00> [00:08:13.249,313] <err> app_uart: RX stopped: reason 4
00> [00:08:13.249,400] <err> app_uart: RX stopped: reason 4
00> [00:08:13.249,598] <dbg> app_uart: free_rx_buf: Freed RX buffer 2
00> [00:08:13.249,610] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:08:13.249,621] <dbg> app_uart: app_uart_cb: RX disabled, restarting with timeout
00> [00:08:13.249,648] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:08:13.270,019] <dbg> app_uart: free_rx_buf: Static rx_buf released; ignoring.
00> [00:08:13.270,042] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 2
00> [00:08:13.289,073] <dbg> app_uart: free_rx_buf: Freed RX buffer 0
00> [00:08:13.289,084] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 0
00> [00:08:13.298,908] <dbg> app_uart: free_rx_buf: Freed RX buffer 2
00> [00:08:13.298,919] <dbg> app_uart: alloc_rx_buf: Allocating RX buffer 2
00> [00:08:13.642,746] <inf> app_uart: app_uart_clear_rx_buf:
00> RDY
00>
00> +U9
00> +QUSIM: 1
00>
00> +QIND: SMS DONE
00>
00> +CPIN: READY
00>
00> AP RDY