ESP32 UART DMA mis-sequencing with async_uart + async_rx_helper causes buffer overwrite and delayed data availability (Zephyr v4.3.0) #100955
Description
Describe the bug
When using UART with DMA on the ESP32S3 board in Zephyr v4.3.0, the DMA receive completion interrupt (uart_esp32_dma_rx_done) is triggered before the main UART ISR (uart_esp32_isr) that increments data->async.rx_counter. This ordering creates a race that leads to the DMA being reloaded at the last position of the provided RX buffer and exiting without properly processing the received data or requesting a new buffer.
Symptoms:
- If the incoming packet is larger than the RX buffer size, the last byte of the current buffer is overwritten by the first byte that should belong to the next buffer.
- Received data is only surfaced to higher layers when the timeout interrupt (uart_esp32_async_rx_timeout) occurs.
- The same application code tested on mimxrt1020_evk does not reproduce the issue.
This appears to be a sequencing/ordering problem between DMA completion and the async RX counter handling in the ESP32 driver’s interrupt path, specifically when async_uart is used together with async_rx_helper.
Expected Behavior
When the RX buffer is completely filled:
- The driver should process the buffer, increment rx_counter, and request or switch to a new buffer (or notify upper layers) without overwriting data.
- No byte should be lost or overwritten at buffer boundaries, even for packets larger than the buffer.
- Data should be made available immediately upon buffer completion, not only at timeout.
Observed Behavior
- uart_esp32_dma_rx_done fires before uart_esp32_isr increments data->async.rx_counter.
- DMA gets reloaded at the last index of the provided buffer.
- No immediate processing and no new buffer request is performed.
- If the packet exceeds the buffer size, the last byte of the buffer is overwritten by the first byte of the next packet.
- Data only becomes available when uart_esp32_async_rx_timeout occurs.
Some logs were added to the driver code so I could trace the code behavior.
static void uart_esp32_isr(void *arg)
{
const struct device *dev = (const struct device *)arg;
struct uart_esp32_data *data = dev->data;
uint32_t uart_intr_status = uart_hal_get_intsts_mask(&data->hal);
if (uart_intr_status == 0) {
LOG_INF("Spurious UART interrupt");
return;
}
uart_hal_clr_intsts_mask(&data->hal, uart_intr_status);
#if CONFIG_UART_INTERRUPT_DRIVEN
/* Verify if the callback has been registered */
if (data->irq_cb) {
data->irq_cb(dev, data->irq_cb_data);
}
#endif
#if CONFIG_UART_ASYNC_API
if (uart_intr_status & UART_INTR_RXFIFO_FULL) {
data->async.rx_counter++;
LOG_INF("Async RX FIFO FULL intr: rx_counter=%u", (unsigned)data->async.rx_counter);
uart_esp32_async_timer_start(&data->async.rx_timeout_work, data->async.rx_timeout);
}
else
{
LOG_INF("Async RX TIMEOUT intr: rx_counter=%u", (unsigned)data->async.rx_counter);
LOG_INF("uart_intr_status=0x%08x", (unsigned)uart_intr_status);
}
#endif
}
#endif
#if CONFIG_UART_ASYNC_API
static void IRAM_ATTR uart_esp32_dma_rx_done(const struct device *dma_dev, void *user_data,
uint32_t channel, int status)
{
const struct device *uart_dev = user_data;
const struct uart_esp32_config *config = uart_dev->config;
struct uart_esp32_data *data = uart_dev->data;
struct uart_event evt = {0};
unsigned int key = irq_lock();
LOG_INF("Async DMA RX DONE intr");
/* If the receive buffer is not complete we reload the DMA at current buffer position and
* let the timeout callback handle the notifications
*/
if (data->async.rx_counter != data->async.rx_len) {
dma_reload(config->dma_dev, config->rx_dma_channel, 0,
(uint32_t)data->async.rx_buf + data->async.rx_counter,
data->async.rx_len - data->async.rx_counter);
dma_start(config->dma_dev, config->rx_dma_channel);
data->uhci_dev->pkt_thres.thrs = data->async.rx_len - data->async.rx_counter;
irq_unlock(key);
LOG_INF("Async DMA Exiting");
return;
}
/*Notify RX_RDY*/
evt.type = UART_RX_RDY;
evt.data.rx.buf = data->async.rx_buf;
evt.data.rx.len = data->async.rx_counter - data->async.rx_offset;
evt.data.rx.offset = data->async.rx_offset;
if (data->async.cb && evt.data.rx.len) {
LOG_INF("Async RX RDY intr: len=%u offset=%u", (unsigned)evt.data.rx.len, (unsigned)evt.data.rx.offset);
data->async.cb(data->uart_dev, &evt, data->async.user_data);
}
data->async.rx_offset = 0;
data->async.rx_counter = 0;
/*Release current buffer*/
evt.type = UART_RX_BUF_RELEASED;
evt.data.rx_buf.buf = data->async.rx_buf;
if (data->async.cb) {
LOG_INF("Async RX BUF RELEASED intr");
data->async.cb(uart_dev, &evt, data->async.user_data);
}
/*Load next buffer and request another*/
data->async.rx_buf = data->async.rx_next_buf;
data->async.rx_len = data->async.rx_next_len;
data->async.rx_next_buf = NULL;
data->async.rx_next_len = 0U;
evt.type = UART_RX_BUF_REQUEST;
if (data->async.cb) {
LOG_INF("Async RX BUF REQUEST intr");
data->async.cb(uart_dev, &evt, data->async.user_data);
}
/*Notify RX_DISABLED when there is no buffer*/
if (!data->async.rx_buf) {
evt.type = UART_RX_DISABLED;
if (data->async.cb) {
LOG_INF("Async RX DISABLED intr");
data->async.cb(uart_dev, &evt, data->async.user_data);
}
} else {
/*Reload DMA with new buffer*/
dma_reload(config->dma_dev, config->rx_dma_channel, 0, (uint32_t)data->async.rx_buf,
data->async.rx_len);
dma_start(config->dma_dev, config->rx_dma_channel);
data->uhci_dev->pkt_thres.thrs = data->async.rx_len;
}
irq_unlock(key);
}
static void uart_esp32_async_rx_timeout(struct k_work *work)
{
struct k_work_delayable *dwork = k_work_delayable_from_work(work);
struct uart_esp32_async_data *async =
CONTAINER_OF(dwork, struct uart_esp32_async_data, rx_timeout_work);
struct uart_esp32_data *data = CONTAINER_OF(async, struct uart_esp32_data, async);
struct uart_event evt = {0};
unsigned int key = irq_lock();
LOG_INF("Async RX TIMEOUT intr: rx_counter=%u", (unsigned)data->async.rx_counter);
evt.type = UART_RX_RDY;
evt.data.rx.buf = data->async.rx_buf;
evt.data.rx.len = data->async.rx_counter - data->async.rx_offset;
evt.data.rx.offset = data->async.rx_offset;
if (data->async.cb && evt.data.rx.len) {
LOG_INF("Async Timeout RX RDY intr: len=%u offset=%u", (unsigned)evt.data.rx.len, (unsigned)evt.data.rx.offset);
data->async.cb(data->uart_dev, &evt, data->async.user_data);
}
data->async.rx_offset = data->async.rx_counter;
k_work_cancel_delayable(&data->async.rx_timeout_work);
irq_unlock(key);
}
Regression
- This is a regression.
Steps to reproduce
- Configure ESP32S3 UART0 with DMA enabled and use async_uart with async_rx_helper. Change console and shell-uart to usb_serial.
- Start a continuous RX session with a fixed RX buffer (e.g., 26 bytes).
- Send a test packet larger than the buffer (e.g., 27 bytes) at a sustained baud rate.
- Observe that data is not delivered until uart_esp32_async_rx_timeout triggers, and the last byte of the buffer is overwritten.
Relevant log output
Buffer size equals to received data
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x40376a54
pro cpu reset by JTAG
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fc91df0,len:0x4308
load:0x40374000,len:0xdddc
SHA-256 comparison failed:
Calculated: 27405d98dbfb4d25347679b0b38245f0ae81dbd090578442c27856b05dd0c043
Expected: 00000000e0de0000000000000000000000000000000000000000000000000000
Attempting to boot anyway...
entry 0x4037b9a4
I (71) soc_init: ESP Simple boot
I (71) soc_init: compile time Dec 11 2025 20:13:59
W (71) soc_init: Unicore bootloader
I (71) soc_init: chip revision: v0.2
I (74) flash_init: Boot SPI Speed : 80MHz
I (77) flash_init: SPI Mode : DIO
I (81) flash_init: SPI Flash Size : 16MB
I (85) boot: DRAM : lma=00000020h vma=3fc91df0h size=04308h ( 17160)
I (91) boot: IRAM : lma=00004330h vma=40374000h size=0dddch ( 56796)
I (97) boot: IROM : lma=00020000h vma=42000000h size=18128h ( 98600)
I (103) boot: DROM : lma=00040000h vma=3c020000h size=06468h ( 25704)
I (109) boot: libc heap size 298 kB.
I (112) spi_flash: detected chip: boya
I (116) spi_flash: flash io: dio
I (119) octal_psram: vendor id : 0x0d (AP)
I (123) octal_psram: dev id : 0x02 (generation 3)
I (128) octal_psram: density : 0x03 (64 Mbit)
I (132) octal_psram: good-die : 0x01 (Pass)
I (136) octal_psram: Latency : 0x01 (Fixed)
I (141) octal_psram: VCC : 0x01 (3V)
I (145) octal_psram: SRF : 0x01 (Fast Refresh)
I (150) octal_psram: BurstType : 0x01 (Hybrid Wrap)
I (155) octal_psram: BurstLen : 0x01 (32 Byte)
I (159) octal_psram: Readlatency : 0x02 (10 cycles@Fixed)
I (164) octal_psram: DriveStrength: 0x00 (1/1)
I (169) MSPI Timing: PSRAM timing tuning index: 4
I (173) esp_psram: Found 8MB PSRAM device
I (177) esp_psram: Speed: 80MHz
I (589) esp_psram: SPI SRAM memory test OK
[00:00:00.613,000] <inf> AppWatchdog: Watchdog initialized successfully
*** Booting Zephyr OS build v4.3.0 ***
[00:00:00.613,000] <inf> AppIoMngr: Pin hall configured successfully, with state high-z
[00:00:00.613,000] <inf> AppIoMngr: Pin door configured successfully, with state high-z
[00:00:00.613,000] <inf> AppIoMngr: Pin output1 configured successfully, with state low
[00:00:00.613,000] <inf> AppIoMngr: Pin output2 configured successfully, with state low
[00:00:00.614,000] <inf> AppAstpMngr: Thread addded to watchdog monitoring, id=0
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=1
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=2
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=3
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=4
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=5
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=6
[00:00:18.929,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=7
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=8
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=9
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=10
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=11
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=12
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=13
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=14
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=15
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=16
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=17
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=18
[00:00:18.930,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=19
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=20
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=21
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=22
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=23
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=24
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=25
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=26
[00:00:18.931,000] <inf> uart_esp32: Async DMA RX DONE intr
[00:00:18.931,000] <inf> uart_esp32: Async DMA Exiting
[00:00:18.931,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=27
[00:00:19.031,000] <inf> uart_esp32: Async RX TIMEOUT intr: rx_counter=27
[00:00:19.031,000] <inf> uart_esp32: Async Timeout RX RDY intr: len=27 offset=0
[00:00:19.031,000] <inf> AppAstpMngr: ASTP packet decoded
Buffer shorter than received data
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x40376a54
pro cpu reset by JTAG
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fc91df0,len:0x4308
load:0x40374000,len:0xdddc
SHA-256 comparison failed:
Calculated: 506125070ee4a07675c7cda1077d68b606104ee9576b40720a57b9dae5cfa607
Expected: 00000000e0de0000000000000000000000000000000000000000000000000000
Attempting to boot anyway...
entry 0x4037b9a4
I (71) soc_init: ESP Simple boot
I (71) soc_init: compile time Dec 11 2025 20:16:31
W (71) soc_init: Unicore bootloader
I (71) soc_init: chip revision: v0.2
I (74) flash_init: Boot SPI Speed : 80MHz
I (77) flash_init: SPI Mode : DIO
I (81) flash_init: SPI Flash Size : 16MB
I (85) boot: DRAM : lma=00000020h vma=3fc91df0h size=04308h ( 17160)
I (91) boot: IRAM : lma=00004330h vma=40374000h size=0dddch ( 56796)
I (97) boot: IROM : lma=00020000h vma=42000000h size=18128h ( 98600)
I (103) boot: DROM : lma=00040000h vma=3c020000h size=06468h ( 25704)
I (109) boot: libc heap size 298 kB.
I (112) spi_flash: detected chip: boya
I (116) spi_flash: flash io: dio
I (119) octal_psram: vendor id : 0x0d (AP)
I (123) octal_psram: dev id : 0x02 (generation 3)
I (128) octal_psram: density : 0x03 (64 Mbit)
I (132) octal_psram: good-die : 0x01 (Pass)
I (136) octal_psram: Latency : 0x01 (Fixed)
I (141) octal_psram: VCC : 0x01 (3V)
I (145) octal_psram: SRF : 0x01 (Fast Refresh)
I (150) octal_psram: BurstType : 0x01 (Hybrid Wrap)
I (155) octal_psram: BurstLen : 0x01 (32 Byte)
I (159) octal_psram: Readlatency : 0x02 (10 cycles@Fixed)
I (164) octal_psram: DriveStrength: 0x00 (1/1)
I (169) MSPI Timing: PSRAM timing tuning index: 4
I (173) esp_psram: Found 8MB PSRAM device
I (177) esp_psram: Speed: 80MHz
I (589) esp_psram: SPI SRAM memory test OK
[00:00:00.613,000] <inf> AppWatchdog: Watchdog initialized successfully
*** Booting Zephyr OS build v4.3.0 ***
[00:00:00.613,000] <inf> AppIoMngr: Pin hall configured successfully, with state high-z
[00:00:00.613,000] <inf> AppIoMngr: Pin door configured successfully, with state high-z
[00:00:00.613,000] <inf> AppIoMngr: Pin output1 configured successfully, with state low
[00:00:00.613,000] <inf> AppIoMngr: Pin output2 configured successfully, with state low
[00:00:00.614,000] <inf> AppAstpMngr: Thread addded to watchdog monitoring, id=0
[00:00:32.300,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=1
[00:00:32.300,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=2
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=3
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=4
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=5
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=6
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=7
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=8
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=9
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=10
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=11
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=12
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=13
[00:00:32.301,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=14
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=15
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=16
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=17
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=18
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=19
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=20
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=21
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=22
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=23
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=24
[00:00:32.302,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=25
[00:00:32.303,000] <inf> uart_esp32: Async DMA RX DONE intr
[00:00:32.303,000] <inf> uart_esp32: Async DMA Exiting
[00:00:32.303,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=26
[00:00:32.303,000] <inf> uart_esp32: Async DMA RX DONE intr
[00:00:32.303,000] <inf> uart_esp32: Async RX RDY intr: len=26 offset=0
[00:00:32.303,000] <inf> uart_esp32: Async RX BUF RELEASED intr
[00:00:32.303,000] <inf> uart_esp32: Async RX BUF REQUEST intr
[00:00:32.303,000] <inf> uart_esp32: Async RX FIFO FULL intr: rx_counter=1
[00:00:32.303,000] <err> AppAstpMngr: AstpBeginDecode failed: 9500 (packet len=26)
[00:00:32.403,000] <inf> uart_esp32: Async RX TIMEOUT intr: rx_counter=1
[00:00:32.403,000] <inf> uart_esp32: Async Timeout RX RDY intr: len=1 offset=0Impact
Functional Limitation – Some features not working as expected, but system usable.
Environment
- Zephyr version: v4.3.0
- Board: ESP32S3
- API/Modules: async_uart with async_rx_helper
- Comparison board: mimxrt1020_evk (same app code, issue not reproduced)
Additional Context
The esp32s3_devkitc_procpu.overlay is
/ {
chosen {
zephyr,console = &usb_serial;
zephyr,shell-uart = &usb_serial;
comm = &uart0;
};
};
&usb_serial {
status = "okay";
};
&uart0 {
status = "okay";
dmas = <&dma 0>, <&dma 1>;
dma-names = "rx", "tx";
};
&dma {
status = "okay";
};