uart async api notifys fewer bytes than it has received.

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:)

  • 2844.uart_async.zip

    I'm not able to reproduce this. Could you test the sample above and see if you're able to reproduce the issue?

    I used the attached sample with NCS v2.0.0 and nRF52840 DK.

    You can test the sample by open a serial terminal and send commands (uart0 is used for async uart). Then you can open an RTT viewer (RTT logging is enabled) to see how many bytes were received (length of evt->data.rx.len is printed).

    Best regards,

    Simojn

  • Thank you for your reply:) I tried your sample and was able to reproduce:

    It was OK for the first few times, and then the last char '9' was delayed until next data arrival, from then on, the last byte was delayed for many times. And then this may be corrected:

    Or things may become worse:

  • Hi srocky,

    I had a similar problem and solved it reducing to minimum operations done in the uart callback. Notice that this is an interrupt handler and must be careful with operations done inside.

    I removed all LOG_ and malloc functions and worked. Try removing ilog and hex_dump2 calls. You can copy data to a buffer and then print it outside the interrupt handler.

    Hope it works!

    Regards,

    Pedro.

  • Hi Pedro,

    Thanks for your solution, I may try this later. But I think there must be something wrong in lower level logic. I tried three types of uart API before I found what happened, I thought it must be my fault because UART is a quite common tech, and nordic has sold quite a lot of chips and NCS has released many versions. But I got the same results in all three ways. In two other ways I could/did not test internal buffer and just could not get enough data.

    If the reason is I do too many operations in the interrupt handler, what expects to happen is that data would get lost when flow control not used? In my case data is still there, but delayed. And one more thing, this also happened when there was not too much data,  I sent data by clicking button, 45 bytes a time.

  • Hi srocky,

    If the reason is I do too many operations in the interrupt handler, what expects to happen is that data would get lost when flow control not used?

    When using async UART API, data is transferred through DMA, so no data would be lost, but counters of number of received bytes of API can be affected.

    In my case data is still there, but delayed.

    Same happened to me. Data was in buffer but API showed less bytes that in fact received. It was in the next data ready event when the delayed data was revealed.

    And one more thing, this also happened when there was not too much data,  I sent data by clicking button, 45 bytes a time.

    For me it was depending on the size of the assigned buffer. Have you tried to increase buffer size?

    Be careful to do not assign a buffer size greater than 2^(RXD.MAXCNT number of bits), because there is no software check and the value is just assigned to the register. For me (nRF52832) was 8 bits, so when I defined 256 as buffer size, that is -> 0b1 0000 0100, the value written to RXD.MAXCNT (buffer size) was in fact 0b0000 0100 (4 bytes buffer).

    I hope you find the solution soon!

    Regards,

    Pedro.

Related