Libuarte_async bug(s) - missing data / wrong buffer returned.

[Gasper]

Hi,

We've been having problems trying to implement a high-speed uart communication between the nRF52832 and an STM32.

We switched to using libuarte so we can use DMA even though our communication protocol has variable-sized packets Unfortunately, after several seconds of working perfectly, we suddenly start seeing errors. In between good new data blocks, we suddenly have one block that has old data. So either the data was never written by DMA, or it was written somewhere other than we are told to read from. It was only for the amount of data that the NRF_LIBUARTE_ASYNC_EVT_RX_DATA reported. It seemed kinda like the timeout triggered before the data was actually copied by the DMA or something along those lines.

We've reduced the transmission speed to 115200, and the error still occurs. We've used a logic analyzer to check if the data is really being transferred - it definitely is, but the nordic is not getting it. We've tried it with SDK 15.0, 15.3 and 16.0, the problem remains.

Since our codebase is way too complex to try and post something helpful here, we tried recreating the issue with two nRF52840 DKs.

Unfortunately, we're not getting the same errors, but are getting another error in the first RX event. First, right after we initialize libuarte_async we get NRF_LIBUARTE_ASYNC_EVT_ERROR errorSrc 0 - this started with SDK 16.0, it wasn't occurring when using SDK 15.x with ported libuarte. Then we get a bunch of skipped bytes reported (check the attached project):

<info> app: Rx 128@x20004B84
<error> app: RX: expected x65, got x39 instead
<error> app: RX: expected x3A, got x3D instead
<error> app: RX: expected x3E, got x41 instead
<error> app: RX: expected x42, got x45 instead
<error> app: RX: expected x46, got x49 instead
<error> app: RX: expected x4A, got x4D instead

Note: We're using arm-none-eabi-gcc  v4.9.3 to build it the test project, targeting nrf52840 chip sitting on development kits. They are connected and both running the same firmware, both doing RX and TX using libuarte.

ble_app_libuarte_test.tar.gz

[Kenneth]

I am not aware of any issue, but using the latest is in general the recommended.

My only input is that I would recommend to increase .timeout_us = 100 to 300 (or possible more for testing). Reasoning is that depending on other interrupts that may be occurring (causing the uart to be pending), you want to make sure that you can always handle the uart interrupt in time before the next may occur.

"errorSrc 0" was very odd, maybe you can set a breakpoint on the error and double check value. Making sure RXD is always pulled up can be something to check.

Best regards,
Kenneth

[thefool]

I'm working with Gasper on this, and when looking at the libuarte implementation, I can't help but wonder if the byte counter/timer is really the best way to handle getting the amount of bytes received. DMA HAS to know where it should write the next byte it gets from UART, so I'd assume there must be a way to somehow get that information. Whether it's a register or a memory location...

ie when the timeout fires, we fetch that information (eg by subtracting the current buffer start pointer from the current dma pointer, which should give us the number of bytes received).

would this not be possible and save resources (and potential error sources)?

[Gasper]

Hi, We're using the latest SDK (16.0.0), but we first ported to 15.0 because that's what the project is using. I have also increased timeout_us to 500 for testing, but it didn't change a thing. We're still seeing a bunch of wrong incoming data, usually in the first RX event. I have confirmed that the other side is sending a continuous stream of bytes from 0x00 - 0x9A, then it resets and starts with 0x00 again. This doesn't make sense, since it reports values above 0x9A, which are not being sent over the line at all: 

<warning> app: Boot
<error> app: NRF_LIBUARTE_ASYNC_EVT_ERROR errorSrc 4
<error> app: NRF_LIBUARTE_ASYNC_EVT_ERROR errorSrc 4
<warning> app: Test TX started.
<info> app: Debug logging for UART over RTT started.
<error> app: NRF_LIBUARTE_ASYNC_EVT_ERROR errorSrc 4
<info> app: Rx 128@x20004B84
<error> app: RX: expected x65, got xAB instead
<error> app: RX: expected x11, got xD5 instead
<error> app: RX: expected x3B, got xE5 instead
<error> app: RX: expected x4B, got xF5 instead
<error> app: RX: expected x5B, got x85 instead
<error> app: RX: expected x86, got x89 instead
<error> app: RX: expected x8A, got x8D instead
<error> app: RX: expected x8E, got x91 instead
<error> app: RX: expected x92, got x95 instead
<error> app: RX: expected x96, got x99 instead
<error> app: RX: expected x9A, got x9D instead
<error> app: RX: expected x03, got xA1 instead
<error> app: RX: expected x07, got xA5 instead
<error> app: RX: expected x0B, got xA9 instead
<error> app: RX: expected x0F, got xAD instead
<error> app: RX: expected x13, got xB1 instead
<error> app: RX: expected x17, got xB5 instead
<error> app: RX: expected x1B, got xB9 instead
<error> app: RX: expected x1F, got xBD instead
<error> app: RX: expected x23, got xC1 instead
<error> app: RX: expected x27, got xC5 instead
<error> app: RX: expected x2B, got xC9 instead
<error> app: RX: expected x2F, got xCD instead
<error> app: RX: expected x33, got xD1 instead
<error> app: RX: expected x37, got xD5 instead
<error> app: RX: expected x3B, got xD9 instead
<error> app: RX: expected x3F, got xDD instead
<error> app: RX: expected x43, got xE1 instead
<error> app: RX: expected x47, got xE5 instead
<error> app: RX: expected x4B, got xE9 instead
<error> app: RX: expected x4F, got xED instead
<error> app: RX: expected x53, got xF1 instead
<error> app: RX: expected x57, got xF5 instead
<error> app: RX: expected x5B, got xF9 instead
<error> app: RX: expected x5F, got xFD instead
<error> app: RX: expected x63, got x81 instead
<error> app: Errors: 36 -> when got 128 @ x20004B84
<info> app: Rx 128@x20004C04
<info> app: Rx 128@x20004C84

As for the errorSrc 0 thing, I found the error, not sure how I've missed it before: in libuarte_async.c in the handler for NRF_LIBUARTE_DRV_EVT_ERROR, you didn't actually copy the errorSrc. Basically, the .data portion is missing: 

        nrf_libuarte_async_evt_t evt = {
            .type = NRF_LIBUARTE_ASYNC_EVT_ERROR,
            .data = {
                .errorsrc = p_evt->data.errorsrc
            }
        };

Now that I've added that I get the errorsrc4 == framing error, which makes sense, since the other side is already sending while this side is initializing, meaning RX line is changing, and so we get framing errors (a few, right after initialization).

[Kenneth]

Can you check if starting the HFCLK may help? E.g. nrf_drv_clock_hfclk_request()/sd_clock_hfclk_request().

Do you have a logic analyzer trace of the serial incomming data? I just want to check the size of the packets, the delay between packets/bytes and baud rate.

Gasper said:

As for the errorSrc 0 thing, I found the error, not sure how I've missed it before: in libuarte_async.c in the handler for NRF_LIBUARTE_DRV_EVT_ERROR, you didn't actually copy the errorSrc.

Thanks, I will report it.

Best regards,
Kenneth 

[Gasper]

Enabling hfclk doesn't change anything. 

You can find a logic analyzer trace in the csv file: 8473.rx.tar.gz. I've truncated the trace at the beginning to where Rx started - the nrf_libuarte_async_enable call returned in the middle of the first 0x62 byte, which is probably the framing error reported at the beginning. The first full buffer is reported (NRF_LIBUARTE_ASYNC_EVT_RX_DATA) after ~2.826ms at timestamp 2.10230902. The log for this trace is:

<warning> app: Boot
<warning> app: Test TX started.
<info> app: Debug logging for UART over RTT started.
<error> app: NRF_LIBUARTE_ASYNC_EVT_ERROR errorSrc 4
<info> app: Rx 128@x20004B84
<error> app: RX: expected x65, got x89 instead
<error> app: RX: expected x8A, got x8D instead
<error> app: RX: expected x8E, got x91 instead
<error> app: RX: expected x92, got x95 instead
<error> app: RX: expected x96, got x99 instead
<error> app: RX: expected x9A, got x9D instead
<error> app: RX: expected x03, got xA1 instead
<error> app: RX: expected x07, got xA5 instead
<error> app: RX: expected x0B, got xA9 instead
<error> app: RX: expected x0F, got xAD instead
<error> app: RX: expected x13, got xB1 instead
<error> app: RX: expected x17, got xB5 instead
<error> app: RX: expected x1B, got xB9 instead
<error> app: RX: expected x1F, got xBD instead
<error> app: RX: expected x23, got xC1 instead
<error> app: RX: expected x27, got xC5 instead
<error> app: RX: expected x2B, got xC9 instead
<error> app: RX: expected x2F, got xCD instead
<error> app: RX: expected x33, got xD1 instead
<error> app: RX: expected x37, got xD5 instead
<error> app: RX: expected x3B, got xD9 instead
<error> app: RX: expected x3F, got xDD instead
<error> app: RX: expected x43, got xE1 instead
<error> app: RX: expected x47, got xE5 instead
<error> app: RX: expected x4B, got xE9 instead
<error> app: RX: expected x4F, got xED instead
<error> app: RX: expected x53, got xF1 instead
<error> app: RX: expected x57, got xF5 instead
<error> app: RX: expected x5B, got xF9 instead
<error> app: RX: expected x5F, got xFD instead
<error> app: RX: expected x63, got x81 instead
<error> app: Errors: 31 -> when got 128 @ x20004B84
<info> app: Rx 128@x20004C04

Tx started roughly 20us after Rx. Spacing between packets is roughly 10us. Baudrate is set in fw to 460800. Tx packet size is 155 bytes (increasing from 0x00 to 0x9A), Rx buffer size is 128 and the size mismatch is intentional as in the original project we have variable packet lengths. Since this is a data stream (for our use case as well), we don't particularly care that packet end isn't detected in this case, but we do need it (and it works fine) for a different mode of operation in our core project.