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

[wakasio <scarabeeta@gmail.com>]

Hi Michal,

I applied your patch and reproduced the failure with all three debug
functions enabled. Result:

Cluster 1 (ep 2, at the very start of the write, unrelated as you
said): same as before, 4 Stall/Hard-reset pairs, spread over about
323 ms, roughly 22 seconds before the real failure.

Cluster 2 (ep 3, the real failure), with full timestamps this time:

  17:38:44.749474 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.749743 Soft-reset ep 3
  17:38:44.758367 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.758454 Soft-reset ep 3
  17:38:44.768370 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.768577 Soft-reset ep 3
  17:38:44.775052 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.775217 Soft-reset ep 3
  17:38:44.785047 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.785313 Soft-reset ep 3
  17:38:44.790469 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.790732 Soft-reset ep 3
  17:38:44.799187 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.799346 Soft-reset ep 3
  17:38:44.808558 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.808720 Soft-reset ep 3
  17:38:44.819176 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.819317 Soft-reset ep 3
  17:38:44.832378 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.832552 Soft-reset ep 3
  17:38:44.850677 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.850815 Soft-reset ep 3
  17:38:44.861706 Transfer error, ep 3, at ffffd52c40703f40, resid 23552
  17:38:44.861938 Hard-reset ep 3
  17:38:44.981704 usb 6-1: reset SuperSpeed USB device number 2
  17:38:44.998378 Stopped on No-op or Link TRB, slot 1 ep 2
  17:38:46.645044 clear err_count at ffffd52c40707000

It survived 11 soft-resets this time instead of 4, then hit the raised
limit and hard-reset on the 12th. The gap between retries grows from
about 9 ms near the start to about 18 ms near the end.

All 12 Transfer error events, the 11 soft-reset ones and the final
hard-reset one, show the exact same TRB address (ffffd52c40703f40)
and the exact same resid (23552).

About 1.8 seconds after the port reset, a different TRB address
(ffffd52c40707000) cleared err_count. cdrecord had already aborted on
the -EPROTO from the first failing URB by that point.

This time the failure also happened much earlier in the write than
last time, at about 12.9 MB instead of 64 MB or 103 MB. Still no
fixed offset.

I still have the full log if you want to see it, and I can also try
capturing usbmon at the same time as this dynamic debug next, if that
would help correlate the two.

Thanks,
wakasio