Re: xhci_hcd / ASMedia ASM4242: Bulk-OUT -EPROTO with Logitec 0789:0308 during DVD+RW recording

[Michal Pecio <michal.pecio@gmail.com>]

On Sat,  5 Sep 2026 12:10:11 +0900, wakasio wrote:
> Cluster 1, right at the very start of the cdrecord invocation
> (before any error is visible to userspace), ~45 seconds before the
> actual failure:
> 
>   Stalled endpoint for slot 1 ep 2
>   Hard-reset ep 2, slot 1

Seems unrelated.

> Cluster 2, at the exact moment cdrecord reported the write error
> (matches the timestamp of "write track data: error after 103088128
> bytes" in cdrecord's own log):
> 
>   Transfer error for slot 1 ep 3 on endpoint
>   Soft-reset ep 3, slot 1
>   Transfer error for slot 1 ep 3 on endpoint
>   Soft-reset ep 3, slot 1
>   Transfer error for slot 1 ep 3 on endpoint
>   Soft-reset ep 3, slot 1
>   Transfer error for slot 1 ep 3 on endpoint
>   Soft-reset ep 3, slot 1
>   Transfer error for slot 1 ep 3 on endpoint
>   Hard-reset ep 3, slot 1
>   usb 6-1: reset SuperSpeed USB device number 2 using xhci_hcd
>   xhci_hcd 0000:77:00.0: Stopped on No-op or Link TRB for slot 1 ep 2
> 
> So to answer your question directly: it is not constant background
> noise throughout the write. It's a single, tight burst of 5 "Transfer
> error" events on the same endpoint within about one second.

Short fraction of a second, I suppose. Timestamps would help.

4 is the number of retries without ep->err_count reset, so it seems
they all happened in the same URB, possibly in the same place.

Let's add more debug logging and see if it's some transient stupid
problem that we can wait out or plow through with more retries.

One more dynamic debug will be needed with this patch:

  echo 'func handle_tx_event +p' >/proc/dynamic_debug/control
  echo 'func process_bulk_intr_td +p' >/proc/dynamic_debug/control
  echo 'func xhci_reset_halted_ep +p' >/proc/dynamic_debug/control

--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2511,6 +2511,8 @@ static void process_bulk_intr_td(struct xhci_hcd *xhci, struct xhci_virt_ep *ep,
 
 	switch (trb_comp_code) {
 	case COMP_SUCCESS:
+		if (ep->err_count)
+			xhci_dbg(xhci, "clear err_count at %px\n", ep_trb);
 		ep->err_count = 0;
 		/* handle success with untransferred data as short packet */
 		if (ep_trb != td->end_trb || remaining) {
@@ -2522,6 +2524,8 @@ static void process_bulk_intr_td(struct xhci_hcd *xhci, struct xhci_virt_ep *ep,
 		td->status = 0;
 		break;
 	case COMP_SHORT_PACKET:
+		if (ep->err_count)
+			xhci_dbg(xhci, "clear err_count short at %px\n", ep_trb);
 		ep->err_count = 0;
 		td->status = 0;
 		break;
@@ -2534,9 +2538,10 @@ static void process_bulk_intr_td(struct xhci_hcd *xhci, struct xhci_virt_ep *ep,
 		goto finish_td;
 	case COMP_USB_TRANSACTION_ERROR:
 		if (xhci->quirks & XHCI_NO_SOFT_RETRY ||
-		    (ep->err_count++ > MAX_SOFT_RETRY) ||
+		    (ep->err_count++ > 10) ||
 		    le32_to_cpu(slot_ctx->tt_info) & TT_SLOT)
 			break;
+		udelay(5 << ep->err_count);
 
 		td->status = 0;
 
@@ -2706,8 +2711,8 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 		status = -EPROTO;
 		break;
 	case COMP_USB_TRANSACTION_ERROR:
-		xhci_dbg(xhci, "Transfer error for slot %u ep %u on endpoint\n",
-			 slot_id, ep_index);
+		xhci_dbg(xhci, "Transfer error for slot %u ep %u on endpoint at %px resid %u\n",
+			 slot_id, ep_index, ep_trb, EVENT_TRB_LEN(le32_to_cpu(event->transfer_len)));
 		status = -EPROTO;
 		break;
 	case COMP_BABBLE_DETECTED_ERROR: