uart async api notifys fewer bytes than it has received.

[srocky]

I use CONFIG_UART_ASYNC_API feature of NCS v2.0 with nRF52840DK, but when UART_RX_RDY event triggered, evt->data.rx.len is smaller than the number of bytes it has received. I use dslogic tool to analysis uart signal, and print out evt->data.rx.len+2 bytes and can be sure that data is all there, but evt->data.rx.len is just smaller than it should be. And next UART_RX_RDY is only triggered when more data arrives.

**To Reproduce**
related configuations in prj.conf:
CONFIG_SERIAL=y
CONFIG_CBPRINTF_FP_SUPPORT=y
CONFIG_UART_ASYNC_API=y
CONFIG_UART_1_ASYNC=y

uart handler:

void uart1_handler_callback(const struct device *dev,
                  struct uart_event *evt, void *user_data)
{
    // int err;
    ARG_UNUSED(dev);

    switch (evt->type) {
    case UART_TX_DONE:
        sent = evt->data.tx.len;
        ilog("UART_TX_DONE: %d bytes sent.", sent);
        hex_dump2("UART_TX_DONE: ", evt->data.tx.buf, evt->data.tx.len);
        k_sem_give(&tx_done);
        break;
    case UART_TX_ABORTED:
        sent = evt->data.tx.len;
        ilog("UART_TX_ABORTED: %d bytes sent.", sent);
        k_sem_give(&tx_aborted);
        break;
    case UART_RX_RDY:
        received = evt->data.rx.len;
        ilog("UART_RX_RDY: %d bytes recved at 0x%x.", received, (unsigned int)(evt->data.rx.buf+evt->data.rx.offset));
        hex_dump2("UART_RX_RDY: ", evt->data.rx.buf+evt->data.rx.offset, received);
        k_sem_give(&rx_rdy);
        break;
    case UART_RX_DISABLED:
        ilog("UART_RX_DISABLED");
        // err = k_sem_take(&rx_buf_released, K_NO_WAIT);
        // failed_in_isr |= (err < 0);
        k_sem_give(&rx_disabled);
        break;
    default:
        break;
    }
}


static void uart1_dorx_thread(void *p1, void *p2, void *p3) {
    ARG_UNUSED(p1);
    ARG_UNUSED(p2);
    ARG_UNUSED(p3);
    while (true)
    {
        if (!device_is_ready(uart1_dev)) {
            // printk("UART1 device not ready\n");
            k_yield();
            k_sleep(K_MSEC(5));
            continue;
        }
        if (get_free_buf(&rxBuf, &tmp_rx, &tmp_rx_len) < 0) {
            k_yield();
            // printk("no free space in rx buffer.\n");
            k_sleep(K_MSEC(5));
            continue;
        }

        const int rx_period = 10;
        received = 0;
        // printk("uart_rx_enable 0x%x, %d.\n", tmp_rx, tmp_rx_len);
        uart_rx_enable(uart1_dev, tmp_rx, tmp_rx_len, rx_period*USEC_PER_MSEC);
        while (tmp_rx_len > 0) {
            int ret = k_sem_take(&rx_rdy, K_MSEC(rx_period+1));
            while (ret != 0) {
                ret = k_sem_take(&rx_disabled, K_MSEC(10));
                if (ret == 0) {
                    uart_rx_enable(uart1_dev, tmp_rx, tmp_rx_len, rx_period*USEC_PER_MSEC); // only reenable after disabled.
                }
                ret = k_sem_take(&rx_rdy, K_MSEC(rx_period+1));
            }
            if (received > 0) {
                tmp_rx += received;
                tmp_rx_len -= received;
                lba_putdata_len(&rxBuf, received); //no data copy, just modify loop buffer position variables.
                ilog("%d bytes put into uart rx buffer.", received);
                received = 0;
                if (tmp_rx_len < 0) {
                    ilog("rx: this should never happen! after -%d, %d left", received, tmp_rx_len);
                    break;
                }
            } else {
                ilog("rx: this should not happen!");
            }
        }
    }
}

I have a 10K loop buffer, the packets are no more than 30 bytes, and another thread is keeping handling data, I can be sure
that buffer is long enough.

**Logs and console output**
Some log:
[17.438] ========== sending packet, id = 12 ==========
[17.447] UART_TX_DONE: 34 bytes sent.
[17.450] UART_TX_DONE: 34 0c 00 a5 86 1b 00 17 00 04 00 09 07 0b 00 02 4...............
[17.458] UART_TX_DONE: 0c 00 29 2a 0d 00 02 0e 00 24 2a 0f 00 02 10 00 ..)*.....$*.....
[17.465] UART_TX_DONE: 27 2a '*

[18.853] ========== receiving packet, id = 12 ==========
[18.856] UART_RX_RDY: 33 bytes recved at 0x20001b2c.
[18.860] UART_RX_RDY: 34 0c 00 a5 86 1b 00 17 00 04 00 09 07 0b 00 02 4...............
[18.868] UART_RX_RDY: 0c 00 29 2a 0d 00 02 0e 00 24 2a 0f 00 02 10 00 ..)*.....$*.....
[18.875] UART_RX_RDY: 27 '
** 0x2a is there acturally. **

[17.730] ========== sending packet, id = 13 ==========
[17.738] UART_TX_DONE: 20 bytes sent.
[17.741] UART_TX_DONE: 34 0d 00 43 71 0d 00 09 00 04 00 09 07 11 00 02 4..Cq...........
[17.749] UART_TX_DONE: 12 00 28 2a ..(*

[19.145] ========== receiving packet, id = 13 ==========
[19.148] UART_RX_RDY: 20 bytes recved at 0x20001b4d.
[19.152] UART_RX_RDY: 2a 34 0d 00 43 71 0d 00 09 00 04 00 09 07 11 00 *4..Cq..........
[19.160] UART_RX_RDY: 02 12 00 28 ...(
** it should have received 21 bytes, but it tell me 20, so another 0x2a at the end of packet is delayed.**

[18.030] ========== sending packet, id = 14 ==========
[18.037] UART_TX_DONE: 16 bytes sent.
[18.041] UART_TX_DONE: 34 0e 00 19 bb 09 00 05 00 04 00 01 08 12 00 0a 4...............

[19.442] ========== receiving packet, id = 14 ==========
[19.445] UART_RX_RDY: 16 bytes recved at 0x20001b61.
[19.450] UART_RX_RDY: 2a 34 0e 00 19 bb 09 00 05 00 04 00 01 08 12 00 *4..............
** 0x0a is delayed too.**

**Impact**
When protocal packet has fixed sizes, I can use a litten trick to work around this, but in other cases it's blocking my way.
It happens quite often, not always though, which means it should be a bug.

**Environment (please complete the following information):**
- NCS 2.0
- nRF52840DK

Please help, thanks:)

[C.Thilo]

Hi srocky

Could you solve your problem anyhow?
We experience exactly the same problem. At some point, RX Ready reports just 1 Byte but there are 6 or so received. At least is the signal on the wire corretly. And when there is more received, the missing bytes will be received.

But the count of bytes later received needs always to be received with other data.

Our uart callback is very slim, so should not be a problem :(....

Cheers,
Thilo

[C.Thilo]

One thing I just found out is, when I possibly received not enough bytes, disabling Uart triggers RX Ready with the missing bytes.
This works as workaround with a uart enable in the uart callback UART_DISABLED part. So uart is directly reenabled when disabling it, caused by missing bytes.

Hope this helps!

[lanwer]

In that case, I would recommend using the UART Async Api with hardware counting feature enabled: it basically uses a hardware timer in counter mode to count received bytes. I had also a similar issue, and with the configs below, everything started working as a charm.

This feature is necessary for the reliability. To activate, set the following configs (adjust for the correct instances):

CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2
CONFIG_UART_0_NRF_HW_ASYNC=y

See my ticket here for more info: https://devzone.nordicsemi.com/f/nordic-q-a/110657/modbus-missing-rx-bytes-at-high-baud-rate-460800

Another related ticket: Link