Repository: esp-rs/esp-hal (rust)

Issue:
esp32s3: UART rx_fifo_count() produces garbage after RxError::FifoOverflowed.
## Bug description

A few reads after `RxError::FifoOverflowed`, reads from the UART starts to produce garbage.

It seems like the root cause is related to `status.rxfifo_cnt` being out of sync with 
`mem_rx_status.apb_rx_raddr` and `status.rx_waddr()`.

The strange thing is that it works fine to read data, if it is done fast enough? But then after waiting one second (after the TX-UART has stopped sending data), the registers has become out of sync.
See `56.758957 INFO  UART_0: Before reading garbage, fifo_cnt=(0, 512, 576)` in the less filtered log below, where fifo_cnt all of a sudden is out of sync with the pointers...

## To Reproduce

It should be possible to reproduce with the code I created to identify the problem, is expects an ESP32s3 board with one UART TX connected to all UART RX ports.

https://github.com/mattiasgronlund/esp32s3-uart-stability
CommitId: c09e61e3f7375b9640cd4bf3b1cef4197b6d04b1

This code relies on a small patch to for esp-hal to showcase the problem (Patch #1 below), and another small patch for esp-hal to showcase a prof-of-concept fix (Patch #2 below)

## Expected behavior
Running the test program and piping the defmt output for PROBLEM (grep -e PROBLEM), should creating something like:
```
42.937568 ERROR UART_0: PROBLEM FifoOverflowed
102.028365 ERROR UART_0: PROBLEM FifoOverflowed
```
## Actual behavior

In the actual behavior, one should look closer to the _FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 576 }_. information, where it can be seen that fifo_cnt is not in sync with apb_rx_raddr and rx_waddr.

Added more unfiltered logs at the end where one can see more exactly when they got out of sync...

Example:
```
55.458083 ERROR UART_0: PROBLEM FifoOverflowed
57.932251 ERROR UART_0: PROBLEM [0] 56.861510..57.867114 Δ1.005604s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 512 }, len=064 [] C0<00> [C1, C2, C3, C4, C5, C6, C7, C8, C9, CA, CB, CC, CD, CE, CF, D0, D1, D2, D3, D4, D5, D6, D7, D8, D9, DA, DB, DC, DD, DE, DF, E0, E1, E2, E3, E4, E5, E6, E7, E8, E9, EA, EB, EC, ED, EE, EF, F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF]
60.450043 ERROR UART_0: PROBLEM [0] 59.337644..60.370312 Δ1.032668s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 528, rx_waddr: 592 }, len=080 [] 40<00> [41, 42, 43, 44, 45, 46, 47, 48, 49, 4A, 4B, 4C, 4D, 4E, 4F, D0, D1, D2, D3, D4, D5, D6, D7, D8, D9, DA, DB, DC, DD, DE, DF, E0, E1, E2, E3, E4, E5, E6, E7, E8, E9, EA, EB, EC, ED, EE, EF, F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF, 00, 01, 02, 03, 04, 05, 06, 07, 08, 09, 0A, 0B, 0C, 0D, 0E, 0F]
62.936473 ERROR UART_0: PROBLEM [0] 61.864065..62.869529 Δ1.005464s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 528, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 592, rx_waddr: 512 }, len=064 [] D0<00> [D1, D2, D3, D4, D5, D6, D7, D8, D9, DA, DB, DC, DD, DE, DF, E0, E1, E2, E3, E4, E5, E6, E7, E8, E9, EA, EB, EC, ED, EE, EF, F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF, 00, 01, 02, 03, 04, 05, 06, 07, 08, 09, 0A, 0B, 0C, 0D, 0E, 0F]
```
I expect that after reception `RxError::FifoOverflowed` and as in the example:
- The writer has stopped writing
- The reader has read out all buffed data using read_buffered() until no more data is returned
The data later written by the writer is received unaltered by the receiver.

## Patches
### Patch #1
```
diff --git a/esp-hal/src/uart.rs b/esp-hal/src/uart.rs
index ff56451e..b73bb168 100644
--- a/esp-hal/src/uart.rs
+++ b/esp-hal/src/uart.rs
@@ -931,6 +931,17 @@ where
         fifo_cnt
     }
 
+    /// Debug output
+    #[allow(clippy::useless_conversion)]
+    pub fn rx_fifo_count_debug(&self) -> (u16, u16, u16) {
+        let fifo_cnt: u16 = self.regs().status().read().rxfifo_cnt().bits().into();
+
+        let status = self.regs().mem_rx_status().read();
+        let rd_addr = status.apb_rx_raddr().bits();
+        let wr_addr = status.rx_waddr().bits();
+        return (fifo_cnt, rd_addr, wr_addr)
+    }
+

     /// Disables all RX-related interrupts for this UART instance.
     ///
     /// This function clears and disables the `receive FIFO full` interrupt,
```

### Patch #2
```
diff --git a/esp-hal/src/uart.rs b/esp-hal/src/uart.rs
index ff56451e..d0d1a1a4 100644
--- a/esp-hal/src/uart.rs
+++ b/esp-hal/src/uart.rs
@@ -927,10 +927,38 @@ where
             }
         }
 
-        #[cfg(not(esp32))]
+        #[cfg(esp32s3)]
+        {
+            let status = self.regs().mem_rx_status().read();
+            let rd_addr = status.apb_rx_raddr().bits();
+            let wr_addr = status.rx_waddr().bits();
+
+            if wr_addr > rd_addr {
+                wr_addr - rd_addr
+            } else if wr_addr < rd_addr {
+                (wr_addr + Info::UART_FIFO_SIZE) - rd_addr
+            } else if fifo_cnt > 0 {
+                Info::UART_FIFO_SIZE
+            } else {
+                0
+            }
+        }
+
+        #[cfg(not(any(esp32, esp32s3)))]
         fifo_cnt
     }
 
+    /// Debug output
+    #[allow(clippy::useless_conversion)]
+    pub fn rx_fifo_count_debug(&self) -> (u16, u16, u16) {
+        let fifo_cnt: u16 = self.regs().status().read().rxfifo_cnt().bits().into();
+
+        let status = self.regs().mem_rx_status().read();
+        let rd_addr = status.apb_rx_raddr().bits();
+        let wr_addr = status.rx_waddr().bits();
+        return (fifo_cnt, rd_addr, wr_addr)
+    }
+
     /// Disables all RX-related interrupts for this UART instance.
     ///
     /// This function clears and disables the `receive FIFO full` interrupt,
```
## Environment

- Target device: esp32s3 (revision v0.1)
- Crate name and version: esp-hal    4d075751ae6cc697a15ca936a912351632a37c4c

## Less filtered logs

```
55.357734 INFO  UART_0: HISTORY [0] 54.180470..55.186348 Δ1.005878s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 576 }, len=064 [00..3F]
55.458040 INFO  UART_0: HISTORY [1] 55.186355..55.191930 Δ0.005575s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, len=064 [40..7F]
55.458083 ERROR UART_0: PROBLEM FifoOverflowed
55.558242 INFO  UART_0: FUTURE  [3] 55.257036..55.257061 Δ0.000025s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 577, rx_waddr: 577 }, len=000 []
55.658422 INFO  UART_0: FUTURE  [4] 55.257077..55.257105 Δ0.000028s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 577, rx_waddr: 577 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, len=096 [C0..80], [81..9F]
55.758558 INFO  UART_0: FUTURE  [5] 55.257121..55.257144 Δ0.000023s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 578, rx_waddr: 578 }, len=032 [A0..BF]
55.758626 INFO  UART_0: Sleeping 1.000s, before reading out garbage...
56.758957 INFO  UART_0: Before reading garbage, fifo_cnt=(0, 512, 576)
56.860942 INFO  UART_0: Read zero bytes of garbage, 11 times, hope this is enough. len=0 []
56.860994 INFO  UART_0: After reading garbage, fifo_cnt=(0, 512, 576)

...

56.861245 INFO  UART_TX: Start sending bytes in 1.000s...
57.861441 INFO  UART_TX: Write: [0..128], [00..7F]
57.861608 INFO  UART_TX: Sleep 0.010s
57.871690 INFO  UART_TX: Write: [0..192], [00..BF]
57.889328 INFO  UART_TX: Sleep 0.010s
57.899363 INFO  UART_TX: Write: [0..256], [00..FF]
57.921600 INFO  UART_TX: Sleep 0.010s
57.931626 INFO  UART_TX: Finished sending bytes, buffered flushed.

...

57.932251 ERROR UART_0: PROBLEM [0] 56.861510..57.867114 Δ1.005604s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 512 }, len=064 [] C0<00> [C1, C2, C3, C4, C5, C6, C7, C8, C9, CA, CB, CC, CD, CE, CF, D0, D1, D2, D3, D4, D5, D6, D7, D8, D9, DA, DB, DC, DD, DE, DF, E0,
 E1, E2, E3, E4, E5, E6, E7, E8, E9, EA, EB, EC, ED, EE, EF, F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF]
57.932483 INFO  UART_TX: SIG Signal TX not ready
57.932523 INFO  UART_TX: SIG Wait for RX ready
57.932542 INFO  UART_TX: SIG Signal TX not ready
57.932555 INFO  UART_TX: SIG Wait for RX ready
58.032458 INFO  UART_0: FUTURE  [1] 57.931989..57.932014 Δ0.000025s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, len=000 []
58.133996 INFO  UART_0: FUTURE  [2] 57.932030..57.932058 Δ0.000028s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 128, apb_rx_raddr: 512, rx_waddr: 516 }, len=096 [C0..80], [81..9F]
58.234136 INFO  UART_0: FUTURE  [3] 57.932074..57.932097 Δ0.000023s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 577, rx_waddr: 577 }, len=032 [A0..BF]
58.234188 INFO  UART_0: Sleeping 1.000s, before reading out garbage...
59.234257 INFO  UART_0: Before reading garbage, fifo_cnt=(0, 576, 512)
59.337212 INFO  UART_0: Read zero bytes of garbage, 11 times, hope this is enough. len=0 []
59.337248 INFO  UART_0: After reading garbage, fifo_cnt=(0, 576, 512)

...

59.337482 INFO  UART_TX: Start sending bytes in 1.000s...
60.363165 INFO  UART_TX: Write: [0..128], [00..7F]
60.374645 INFO  UART_TX: Sleep 0.010s
60.388090 INFO  UART_TX: Write: [0..192], [00..BF]
60.404959 INFO  UART_TX: Sleep 0.010s
60.415192 INFO  UART_TX: Write: [0..256], [00..FF]
60.438957 INFO  UART_TX: Sleep 0.010s
60.449234 INFO  UART_TX: Finished sending bytes, buffered flushed.

...

60.450043 ERROR UART_0: PROBLEM [0] 59.337644..60.370312 Δ1.032668s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 528, rx_waddr: 592 }, len=080 [] 40<00> [41, 42, 43, 44, 45, 46, 47, 48, 49, 4A, 4B, 4C, 4D, 4E, 4F, D0, D1, D2, D3, D4, D5, D6, D7, D8, D9, DA, DB, DC, DD, DE, DF, E0, E1, E2, E3, E4, E5, E6, E7, E8, E9, EA, EB, EC, ED, EE, EF, F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF, 00, 01, 02, 03, 04, 05, 06, 07, 08, 09, 0A, 0B, 0C, 0D, 0E, 0F]
60.450678 INFO  UART_TX: SIG Signal TX not ready
60.450695 INFO  UART_TX: SIG Wait for RX ready
60.450715 INFO  UART_TX: SIG Signal TX not ready
60.450728 INFO  UART_TX: SIG Wait for RX ready
60.553286 INFO  UART_0: FUTURE  [1] 60.449736..60.449780 Δ0.000044s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 576, rx_waddr: 576 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, len=000 []
60.653651 INFO  UART_0: FUTURE  [2] 60.449796..60.449832 Δ0.000036s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 128, apb_rx_raddr: 512, rx_waddr: 516 }, len=096 [D0..80], [81..AF]
60.755710 INFO  UART_0: FUTURE  [3] 60.449848..60.449880 Δ0.000032s before:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 512, rx_waddr: 512 }, after:FifoCnt { fifo_cnt: 0, apb_rx_raddr: 577, rx_waddr: 577 }, len=032 [B0..CF]
60.755787 INFO  UART_0: Sleeping 1.000s, before reading out garbage...
61.755912 INFO  UART_0: Before reading garbage, fifo_cnt=(0, 528, 576)
61.863452 INFO  UART_0: Read zero bytes of garbage, 11 times, hope this is enough. len=0 []
61.863534 INFO  UART_0: After reading garbage, fifo_cnt=(0, 528, 576)
```

Pull request description:
UART: clear RX FIFO on overflow
Closes #3168 (well at least I think this time)

The FIFO read/write pointers are independent from the FIFO count. They are in sync as long as the FIFO has not overflowed, but keep walking around after an overflow, while the FIFO count caps out at 128.

Applying the same algorithm as the ESP32 [errata](https://docs.espressif.com/projects/esp-chip-errata/en/latest/esp32/03-errata-description/esp32/uart-fifo-cnt-indicates-data-length-incorrectly.html) describes works for chips other than H2 and C6. On The H2 and C6, however, the FIFO read pointer stops moving once the FIFO is empty, so we can't end up with the pointers pointing at the same address, while also emptying the FIFO. For this reason, this PR simply resets the FIFO if an overflow is detected.

As it's really hard to deduce what bytes are correct in such a case, and in what order they arrived, this seems like a reasonable approach. esp-idf also immediately resets the RX FIFO on overflow, although it does so in an interrupt handler, so esp-idf probably ends up losing less data in the worst case.

Patch:
diff --git a/esp-hal/CHANGELOG.md b/esp-hal/CHANGELOG.md
index 4712e81c..3352aacd 100644
--- a/esp-hal/CHANGELOG.md
+++ b/esp-hal/CHANGELOG.md
@@ -15,6 +15,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 - Full-duplex SPI works when mixed with half-duplex SPI (#3176)
 - `Uart::flush_async` should no longer return prematurely (#3186)
+- Detecting a UART overflow now clears the RX FIFO. (#3190)
 - ESP32-S2: Fixed PSRAM initialization (#3196)
 
 ### Removed
diff --git a/esp-hal/src/uart.rs b/esp-hal/src/uart.rs
index caa99bca..6e4b92d8 100644
--- a/esp-hal/src/uart.rs
+++ b/esp-hal/src/uart.rs
@@ -73,9 +73,10 @@ use crate::{
 #[cfg_attr(feature = "defmt", derive(defmt::Format))]
 #[non_exhaustive]
 pub enum RxError {
-    /// The RX FIFO overflow happened.
+    /// An RX FIFO overflow happened.
     ///
-    /// This error occurs when RX FIFO is full and a new byte is received.
+    /// This error occurs when RX FIFO is full and a new byte is received. The
+    /// RX FIFO is then automatically reset by the driver.
     FifoOverflowed,
 
     /// A glitch was detected on the RX line.
@@ -832,6 +833,8 @@ where
     }
 
     /// Reads and clears errors set by received data.
+    ///
+    /// If a FIFO overflow is detected, the RX FIFO is reset.
     #[instability::unstable]
     pub fn check_for_errors(&mut self) -> Result<(), RxError> {
         let errors = RxEvent::FifoOvf
@@ -843,6 +846,9 @@ where
         let result = rx_event_check_for_error(events);
         if result.is_err() {
             self.uart.info().clear_rx_events(errors);
+            if events.contains(RxEvent::FifoOvf) {
+                self.uart.info().rxfifo_reset();
+            }
         }
         result
     }
@@ -910,31 +916,31 @@ where
         Ok(to_read)
     }
 
-    #[allow(clippy::useless_conversion)]
+    #[cfg(not(esp32))]
+    #[allow(clippy::unnecessary_cast)]
+    fn rx_fifo_count(&self) -> u16 {
+        self.regs().status().read().rxfifo_cnt().bits() as u16
+    }
+
+    #[cfg(esp32)]
     fn rx_fifo_count(&self) -> u16 {
-        let fifo_cnt: u16 = self.regs().status().read().rxfifo_cnt().bits().into();
+        let fifo_cnt = self.regs().status().read().rxfifo_cnt().bits();
 
         // Calculate the real count based on the FIFO read and write offset address:
         // https://docs.espressif.com/projects/esp-chip-errata/en/latest/esp32/03-errata-description/esp32/uart-fifo-cnt-indicates-data-length-incorrectly.html
-        #[cfg(esp32)]
-        {
-            let status = self.regs().mem_rx_status().read();
-            let rd_addr = status.mem_rx_rd_addr().bits();
-            let wr_addr = status.mem_rx_wr_addr().bits();
-
-            if wr_addr > rd_addr {
-                wr_addr - rd_addr
-            } else if wr_addr < rd_addr {
-                (wr_addr + Info::UART_FIFO_SIZE) - rd_addr
-            } else if fifo_cnt > 0 {
-                Info::UART_FIFO_SIZE
-            } else {
-                0
-            }
+        let status = self.regs().mem_rx_status().read();
+        let rd_addr: u16 = status.mem_rx_rd_addr().bits();
+        let wr_addr: u16 = status.mem_rx_wr_addr().bits();
+
+        if wr_addr > rd_addr {
+            wr_addr - rd_addr
+        } else if wr_addr < rd_addr {
+            (wr_addr + Info::UART_FIFO_SIZE) - rd_addr
+        } else if fifo_cnt > 0 {
+            Info::UART_FIFO_SIZE
+        } else {
+            0
         }
-
-        #[cfg(not(esp32))]
-        fifo_cnt
     }
 
     /// Disables all RX-related interrupts for this UART instance.
@@ -2002,8 +2008,15 @@ impl UartRx<'_, Async> {
                 events |= RxEvent::FifoTout;
             }
 
-            let event = UartRxFuture::new(self.uart.reborrow(), events).await;
-            rx_event_check_for_error(event)?;
+            let events = UartRxFuture::new(self.uart.reborrow(), events).await;
+
+            let result = rx_event_check_for_error(events);
+            if let Err(error) = result {
+                if error == RxError::FifoOverflowed {
+                    self.uart.info().rxfifo_reset();
+                }
+                return Err(error);
+            }
         }
 
         Ok(())


Test patch:
diff --git a/hil-test/Cargo.toml b/hil-test/Cargo.toml
index 3760091e..6e4a843f 100644
--- a/hil-test/Cargo.toml
+++ b/hil-test/Cargo.toml
@@ -221,6 +221,7 @@ embassy-sync       = "0.6.0"
 embassy-time       = "0.4.0"
 embedded-hal       = "1.0.0"
 embedded-io        = "0.6.1"
+embedded-io-async  = "0.6.1"
 embedded-can       = "0.4.1"
 embedded-hal-async = "1.0.0"
 embedded-hal-nb    = "1.0.0"
diff --git a/hil-test/tests/uart_tx_rx_async.rs b/hil-test/tests/uart_tx_rx_async.rs
index ec69aeca..c919942d 100644
--- a/hil-test/tests/uart_tx_rx_async.rs
+++ b/hil-test/tests/uart_tx_rx_async.rs
@@ -25,6 +25,7 @@ mod tests {
         select::{select, Either},
     };
     use embassy_time::{Duration, Timer};
+    use embedded_io_async::Write;
     use esp_hal::{
         timer::timg::TimerGroup,
         uart::{RxConfig, RxError},
@@ -129,6 +130,46 @@ mod tests {
         assert!(matches!(res, Err(RxError::FifoOverflowed)), "{:?}", res);
     }
 
+    #[test]
+    async fn flushing_after_overflow_remains_consistent(mut ctx: Context) {
+        let mut read = [0u8; 1];
+
+        ctx.tx.write_all(&[0; 350]).await.unwrap();
+        ctx.tx.flush_async().await.unwrap();
+
+        // The read is supposed to return an error because the FIFO is just 128 bytes
+        // long.
+        let res = ctx.rx.read_async(&mut read).await;
+        assert!(matches!(res, Err(RxError::FifoOverflowed)), "{:?}", res);
+
+        // Now we should be able to write and read back the same data.
+        for _ in 0..5 {
+            ctx.tx.write_all(&[1, 2, 3, 4]).await.unwrap();
+
+            let mut read = [0u8; 4];
+            ctx.rx.read_exact_async(&mut read).await.unwrap();
+
+            assert_eq!(&read, &[1, 2, 3, 4]);
+        }
+
+        // Can we still handle a full FIFO?
+        // Join two futures to ensure that `read_async` is called first, which should
+        // set up waiting for the FIFO full interrupt.
+        let mut read = [0u8; 128];
+        let read = async {
+            // This read should return as many bytes as the FIFO threshold, which is 120
+            // bytes by default.
+            let read_count = ctx.rx.read_async(&mut read).await.unwrap();
+            assert_eq!(read_count, 120);
+
+            ctx.rx.read_exact_async(&mut read[120..]).await.unwrap();
+            assert_eq!(&read, &[1; 128]);
+        };
+        let write = async { ctx.tx.write_all(&[1; 128]).await.unwrap() };
+
+        embassy_futures::join::join(read, write).await;
+    }
+
     #[test]
     async fn read_returns_with_partial_data_if_read_times_out(mut ctx: Context) {
         let mut data = [0u8; 16];