Serial losing bytes (regression from 1.0.4)

[MitchBradley]

Our application - https://github.com/bdring/Grbl_Esp32 - works fine on v1.0.4, but loses Serial Rx bytes on every version after that, starting at 1.0.5-rc1. In developer testing, the loss of data typically occurs about 15 minutes into a 20 minute test run involving sending a 600KB GCode file sent via serial from third-party GCode sending programs that are very well tested. Multiple users have reported much quicker failures.

When we or our users compile against v1.0.4, the problems disappear. The problems appear when compiling against any variant of 1.0.5 or 1.0.6. It is the same with Arduino IDE and PlatformIO - if the Arduino ESP32 framework is v1.0.4, it works, and any later version fails.

The nature of the problem is a lost byte. In every instance that we have analyzed in depth, the lost byte is the newline at the end of a line.

I have isolated the cause of the problem to the rx portion of the patch in #3664 . The attempted fix to that patch - #3713 - does not solve the problem. The 3713 fix changes the failure mode, by eliminating the interchange of two characters at the expense of somewhat-less-frequent lost bytes.

The smallest fix that I have found is to simply revert this change from the 3664 patch:

-   return uxQueueMessagesWaiting(uart->queue);
+   return (uxQueueMessagesWaiting(uart->queue) + uart->dev->status.rxfifo_cnt) ;

That reversion suffices to make our application work reliably, but I do not believe that it is completely correct. I think that all of the code that uses uartRxFifoToQueue() should also be removed. Reaching around the ISR routine from uartRead() and uartPeek() - even when interrupts are disabled temporarily - is a recipe for obscure bugs, which we are experiencing. I think that the reverted return line has the effect of reducing the likelihood that uartRxFifoToQueue() is called, thus reducing, but probably not entirely eliminating, the possibility of lost data.

PR 3664 was intended to reduce Rx latency. I think a much better solution to that goal would be to make the FIFO and TOUT thresholds configurable, preserving the classic driver architecture where the ISR is the only writer to the queue.

I can produce a PR but I first wanted to document and explain the problem.

[MitchBradley]

I have identified a potential race condition in the #3664 / #3713 patch group. Consider the last line in uartAvailable(uart_t* uart):

    return (uxQueueMessagesWaiting(uart->queue) + uart->dev->status.rxfifo_cnt) ;

C does not specify which side of the + operator is evaluated first, hence the right hand side - the access to rxfifo_cnt - could occur first. Suppose that rxfifo contains 111 bytes and another byte arrives just after the fetch of rxfifo_cnt. An interrupt occurs, transferring 112 bytes to the queue. The interrupt returns and uxQueueMessagesWaiting() returns 112, so uartAvailable() returns 112+111 = 223, obviously wildly incorrect.

I looked at assembler output from a recent compilation. This situation is not actually occurring because the left hand side was evaluated first, but there is no guarantee that it could not occur. This illustrates the difficulty of ensuring correctness when device driver logic is duplicated in ISRs and foreground code.

[MitchBradley]

I made the problem go away - at least in our test setup - with this version of uartAvailable(), which disables interrupts during the "queue + fifo" computation:

uint32_t uartAvailable(uart_t* uart)
{
    if(uart == NULL || uart->queue == NULL) {
        return 0;
    }
    uint32_t intval = uart->dev->int_ena.val;
    uart->dev->int_ena.val = 0;
    uint32_t cnt = uxQueueMessagesWaiting(uart->queue) + uart->dev->status.rxfifo_cnt;
    uart->dev->int_ena.val = intval;
    return cnt ;
}

I do not like this solution, because it just patches over the underlying problem of bad design, but it does illustrate that some sort of race condition is occurring.

[MitchBradley]

The problem could be related to erratum 3.17 in https://espressif.com/sites/default/files/documentation/eco_and_workarounds_for_bugs_in_esp32_en.pdf

Unfortunately, the description of the problem is vague and does not specify the exact sequence of operations that cause the problem, nor does it describe the workaround precisely.

But we can infer that something bad happens when some kind of FIFO access is interrupted, which is consistent with the race condition mentioned above.

[Heshyo]

I don't know if it's the same problem as yours, but my code also works on 1.0.4 but not 1.0.5 nor 1.0.6 when it comes to Serial.

In 1.0.4, if I write 2 characters on the Serial to send to the board, then on the board the 2nd character is immediately available after reading the 1st character (ie Serial.available() == 1 right after reading the 1st character). With versions 1.0.5 and 1.0.6, I often have Serial.available() == 0 instead. I need to wait a bit before being able to read the next character.