DWC2 race condition when handling EP0 with DMA mode enabled

[kubeqz]

Operating System

Linux

Commit SHA

81641e3

Board

Custom

Firmware

I can observe the following issue with EP0 on a custom SoC, with DWC2 configured with DMA mode enabled. This seems like a generic issue in the DWC2 port.

It's a simple CDC device, issue shows up very early when host fetches descriptors on EP0.

<start of the day, device boots up connected to the host>

DMA = 1
E0WP 8
USBD Bus Reset : Full Speed
E0DD
E0WP 8
USBD Setup Received 80 06 00 01 00 00 12 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes ...
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with 0 bytes ...

E0WS 0
E0FI 0 1
E0D 0 0
E0WP 8
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 00 with 0 bytes
USBD Suspend : Remote Wakeup = 0
USBD Bus Reset : Full Speed
E0DD
E0WP 8

USBD Setup Received 80 06 00 01 00 00 40 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes ...
USBD Resume
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with 0 bytes ...
E0WS 0
USBD Suspend : Remote Wakeup = 0
E0WP 8
E0FI 0 1
E0D 0 8
E0N
USBD Resume
USBD Xfer Complete on EP 00 with 65528 bytes
usbd_control_xfer_cb 161: ASSERT FAILED

As can be seen in the above log, I added some prints to track what happens

diff --git a/src/portable/synopsys/dwc2/dcd_dwc2.c b/src/portable/synopsys/dwc2/dcd_dwc2.c
@@ static void dma_setup_prepare(uint8_t rhport) {
-  dwc2->epout[0].doeptsiz = (1 << DOEPTSIZ_STUPCNT_Pos) | (1 << DOEPTSIZ_PKTCNT_Pos) | (8 << DOEPTSIZ_XFRSIZ_Pos);
+  dwc2->epout[0].doeptsiz = (1 << DOEPTSIZ_STUPCNT_Pos) | (1 << DOEPTSIZ_PKTCNT_Pos) | (8 << DOEPTSIZ_XFRSIZ_Pos);
+  TU_LOG(DWC2_DEBUG, "E0WP 8\r\n");
@@ static void edpt_schedule_packets(...) {
+  if (epnum == 0 && dir == TUSB_DIR_OUT) {
+    TU_LOG(DWC2_DEBUG, "E0WS %u\r\n", total_bytes);
+  }
@@ static void handle_epout_dma(...) {
+  TU_LOG(DWC2_DEBUG, "E0DD\r\n");
@@
+  TU_LOG(DWC2_DEBUG, "E0FI %u %u\r\n",
+         (unsigned) doepint_bm.setup_phase_done,
+         (unsigned) doepint_bm.xfer_complete);
+  TU_LOG(DWC2_DEBUG, "E0D %u %u\r\n", xfer->total_len, remain);
+  if (xfer->total_len == 0 && remain == 8) {
+    TU_LOG(DWC2_DEBUG, "E0N\r\n");
+  }
-  // workaround path (guard) removed temporarily for repro
-  // if (remain <= xfer->total_len) ...
-  xfer->total_len -= remain;

Here's what happens

• Status OUT is queued with length 0 (E0WS 0).
• Before that status completion is accounted, the driver re-primes EP0 OUT for next setup and writes TSIZ = 8 (E0WP 8).
• Completion handler then runs (E0FI 0 1) and reads remain from TSIZ as 8 (E0D 0 8).
• Accounting does 0 - 8 in unsigned arithmetic, which wraps to 65528.
• TinyUSB control logic expects status-stage xferred bytes to be 0, so it asserts.

This issue seem to depend on a timing in the system, if there are more interrupts/threads that could delay the USB interrupt / task processing the issue shows up more frequently.

I have a proposal of workaround / fix for that, but I'm not sure if that could cause issues in other cases.

diff --git a/src/portable/synopsys/dwc2/dcd_dwc2.c b/src/portable/synopsys/dwc2/dcd_dwc2.c
index 9a9c734..c69d4b2 100644
--- a/src/portable/synopsys/dwc2/dcd_dwc2.c
+++ b/src/portable/synopsys/dwc2/dcd_dwc2.c
@@ -1028,19 +1028,29 @@ static void handle_epout_dma(uint8_t rhport, uint8_t epnum, dwc2_doepint_t doepi
         dwc2_dep_t* epout = &dwc2->epout[epnum];
         xfer_ctl_t* xfer = XFER_CTL_BASE(epnum, TUSB_DIR_OUT);

-        // determine actual received bytes
-        const dwc2_ep_tsize_t tsiz = {.value = epout->tsiz};
-        const uint16_t remain = tsiz.xfer_size;
-        xfer->total_len -= remain;
-
-        // this is ZLP, so prepare EP0 for next setup
-        // TODO use status phase rx
-        if(epnum == 0 && xfer->total_len == 0) {
+        // For EP0 status ZLP (total_len == 0), skip TSIZ-based accounting.
+        // TSIZ may have been re-primed to 8 by another path, and the
+        // semantically correct transferred length for status stage is always 0.
+        if (epnum == 0 && xfer->total_len == 0) {
+          // Status OUT completion: no data transferred, re-prime for next setup.
           dma_setup_prepare(rhport);
+          dcd_event_xfer_complete(rhport, epnum, 0, XFER_RESULT_SUCCESS, true);
+        } else {
+          // Normal data OUT completion: compute actual received bytes from TSIZ.
+          const dwc2_ep_tsize_t tsiz = {.value = epout->tsiz};
+          const uint16_t remain = tsiz.xfer_size;
+          xfer->total_len -= remain;
+
+          // EP0 data OUT complete with no remaining: re-prime for next setup.
+          if (epnum == 0 && xfer->total_len == 0) {
+            dma_setup_prepare(rhport);
+          }
+
+          if (xfer->total_len != 0) {
+            dcd_dcache_invalidate(xfer->buffer, xfer->total_len);
+          }
+          dcd_event_xfer_complete(rhport, epnum, xfer->total_len, XFER_RESULT_SUCCESS, true);
         }
-
-        dcd_dcache_invalidate(xfer->buffer, xfer->total_len);
-        dcd_event_xfer_complete(rhport, epnum, xfer->total_len, XFER_RESULT_SUCCESS, true);
       }
     }
   }
@@ -1054,9 +1064,9 @@ static void handle_epin_dma(uint8_t rhport, uint8_t epnum, dwc2_diepint_t diepin
       // EP0 can only handle one packet. Schedule another packet to be transmitted.
       edpt_schedule_packets(rhport, epnum, TUSB_DIR_IN);
     } else {
-      if(epnum == 0) {
-        dma_setup_prepare(rhport);
-      }
+      // Note: do NOT call dma_setup_prepare() here for EP0.
+      // EP0 OUT re-prime must happen only after OUT completion accounting
+      // has consumed TSIZ; the OUT completion path handles this.
       dcd_event_xfer_complete(rhport, epnum | TUSB_DIR_IN_MASK, xfer->total_len, XFER_RESULT_SUCCESS, true);
     }
   }

Could you please comment on this ?

What happened ?

usbd_control_xfer_cb 161: ASSERT FAILED

How to reproduce ?

Just run the firmware, with host connected to the device.

Debug Log as txt file (LOG/CFG_TUSB_DEBUG=2)

DMA = 1
E0WP 8
USBD Bus Reset : Full Speed
E0DD
E0WP 8
USBD Setup Received 80 06 00 01 00 00 12 00
Get Descriptor Device
Queue EP 80 with 18 bytes ...
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 80 with 18 bytes
Queue EP 00 with 0 bytes ...

E0WS 0
E0FI 0 1
E0D 0 0
E0WP 8
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 00 with 0 bytes
USBD Suspend : Remote Wakeup = 0
USBD Bus Reset : Full Speed
E0DD
E0WP 8

USBD Setup Received 80 06 00 01 00 00 40 00
Get Descriptor Device
Queue EP 80 with 18 bytes ...
USBD Resume
USBD Suspend : Remote Wakeup = 0
USBD Resume
USBD Xfer Complete on EP 80 with 18 bytes
Queue EP 00 with 0 bytes ...
E0WS 0
USBD Suspend : Remote Wakeup = 0
E0WP 8
E0FI 0 1
E0D 0 8
E0N
USBD Resume
USBD Xfer Complete on EP 00 with 65528 bytes
usbd_control_xfer_cb 161: ASSERT FAILED

Screenshots

No response

I have checked existing issues, discussion and documentation

• I confirm I have checked existing issues, discussion and documentation.

[HiFiPhile]

#3634

[kubeqz]

I don't think it's the same issue as #3643, in fact I tried that branch and the issue I'm observing is still there.

[HiFiPhile]

You are right #3634 is different.

• Status OUT is queued with length 0 (E0WS 0).
• Before that status completion is accounted, the driver re-primes EP0 OUT for next setup and writes TSIZ = 8 (E0WP 8).

Could you do a more detailed tracing about how it happens ?

[HiFiPhile]

Please try 608b77d based on #3634

There was an race condition where dma_setup_prepare is called unconditionally, then DMA settings are modified again in edpt_schedule_packets.

Now it's only called if previous transfer is finished:

[kubeqz]

Please try 608b77d based on #3634

This one also doesn't fix the issue.

[HiFiPhile]

Could you provide something reproducible ? Custom SOC is not something we can help with (any bug specific to your implementation ??).

Status OUT is queued with length 0 (E0WS 0).
Before that status completion is accounted, the driver re-primes EP0 OUT for next setup and writes TSIZ = 8 (E0WP 8).

With 608b77d this won't happen unless I missed something. I think I got something, with 608b77d status ACK could be dropped if arrived at the same time as next SETUP, but won't cause TSIZ underflow.