On Sat, Apr 18, 2020 at 02:01:14PM +0200, Patrick Wildt wrote:
> On Tue, Apr 14, 2020 at 06:42:53PM +0000, Mikolaj Kucharski wrote:
> > On Tue, Apr 14, 2020 at 11:06:00AM +0200, Patrick Wildt wrote:
> > > On Mon, Apr 13, 2020 at 09:36:04PM +0200, Mark Kettenis wrote:
> > > > Can you print the status (full 32 bits) of that particular QTD?
> > >
> > > Yeah, I wish I could see the status field for each sqtd in that
> > > chain.
> >
> > XXX #1# ehci_idone: len=4 actlen=4294951308, xf_actlen=0, status=0x8d00,
> > sqtd_count=3
> > XXX #2# ehci_idone: x_actlen=4294951304, sqtd_len=8, ehci_qtd_len=16000,
> > status=0xbe808d00, qtd_status=0xbe808d00, sqtd_count=1
> > XXX #2# ehci_idone: x_actlen=4294951308, sqtd_len=4, ehci_qtd_len=0,
> > status=0xc00, qtd_status=0xc00, sqtd_count=2
> > XXX #2# ehci_idone: x_actlen=4294951308, sqtd_len=0, ehci_qtd_len=0,
> > status=0x8d00, qtd_status=0x8d00, sqtd_count=3
> > panic: _dmamap_sync: ran off map!
>
> Thanks for the information! I'll try and see if I can find what's
> happening. But yeah, that's good information. This is a control
> transfers, which has 3 transfer descriptors.
>
> The three TDs should be: SETUP, DATA (because of len=4), and STATUS.
>
> As you can see, the middle one, DATA, has a len of 4, and the BYTES
> field in the status is 0, indicating that the transfer completed.
>
> Then we have STATUS, which has no len, looks just fine as well.
>
> But the first one, the SETUP, is weird. The len is fine, 8 bytes,
> but ehci_qtd_len looks completely off, the BYTES field also says
> "lots of bytes remaining". This is where we fuck up, I suppose.
>
> What's weird is that we actually account it, because we have this
> check:
>
> if (EHCI_QTD_GET_PID(status) != EHCI_QTD_PID_SETUP)
> actlen += sqtd->len - EHCI_QTD_GET_BYTES(status);
>
> But it looks like the status field on the SETUP descriptor does
> not say PID_SETUP, but PID_IN. Did the DMA controller change the
> bit? Or did someone else overwrite it?
>
> Patrick
I'm kinda stuck with this. I added KASSERT()s in places where I think
condtions should be checked and otherwise kernel should panic. Obviously
as I can trigger bogus condition I ended up with following ddb trace:
urtwn0: SCAN -> INIT
XXX S1 ehci_idone: actlen=4, sqtd_len=0, ehci_qtd_len=16000, status=0x3e808d00
XXX S2 ehci_idone: actlen=-15996, sqtd_len=0, ehci_qtd_len=16000,
status=0x3e808d00
panic: kernel diagnostic assertion "sqtd_len >= ehci_qtd_len" failed: file
"/home/mkucharski/src/sys/dev/usb/ehci.c", line 915
...
db_enter() at panic+0x14c
panic() at ehci_idone+0x264
ehci_isoc_idone() at ehci_softintr+0x158
ehci_softintr() at softintr_biglock_wrap+0x1c
softintr_biglock_wrap() at softintr_dispatch+0x9c
softintr_dispatch() at arm_do_pending_intr+0xa8
arm_do_pending_intr() at ampintc_irq_handler+0x178
This is retyped by hand from a glass console, be aware of typos.
I don't understand why ehci_idone() goes to ehci_isoc_idone() in above
ddb trace output.
Index: sys/dev/usb/ehci.c
===================================================================
RCS file: /cvs/src/sys/dev/usb/ehci.c,v
retrieving revision 1.210
diff -u -p -u -r1.210 ehci.c
--- sys/dev/usb/ehci.c 3 Apr 2020 20:11:47 -0000 1.210
+++ sys/dev/usb/ehci.c 1 Jun 2020 06:19:27 -0000
@@ -870,6 +870,7 @@ ehci_idone(struct usbd_xfer *xfer)
struct ehci_soft_qtd *sqtd;
u_int32_t status = 0, nstatus = 0;
int actlen, cerr;
+ u_int32_t sqtd_len, ehci_qtd_len;
#ifdef DIAGNOSTIC
{
@@ -899,8 +900,20 @@ ehci_idone(struct usbd_xfer *xfer)
if (sqtd->qtd.qtd_next == htole32(EHCI_LINK_TERMINATE) &&
EHCI_QTD_GET_BYTES(status) == 0)
status &= ~EHCI_QTD_HALTED;
- if (EHCI_QTD_GET_PID(status) != EHCI_QTD_PID_SETUP)
- actlen += sqtd->len - EHCI_QTD_GET_BYTES(status);
+ if (EHCI_QTD_GET_PID(status) != EHCI_QTD_PID_SETUP) {
+ sqtd_len = sqtd->len;
+ ehci_qtd_len = EHCI_QTD_GET_BYTES(status);
+ if (ehci_qtd_len > sqtd_len) {
+ printf("XXX S1 %s: actlen=%d, sqtd_len=%u,
ehci_qtd_len=%u, status=0x%x\n",
+ __func__, actlen, sqtd_len,
ehci_qtd_len, status);
+ }
+ actlen += sqtd_len - ehci_qtd_len;
+ if (ehci_qtd_len > sqtd_len) {
+ printf("XXX S2 %s: actlen=%d, sqtd_len=%u,
ehci_qtd_len=%u, status=0x%x\n",
+ __func__, actlen, sqtd_len,
ehci_qtd_len, status);
+ }
+ KASSERT(sqtd_len >= ehci_qtd_len);
+ }
}
cerr = EHCI_QTD_GET_CERR(status);
Index: sys/dev/usb/usbdi.c
===================================================================
RCS file: /cvs/src/sys/dev/usb/usbdi.c,v
retrieving revision 1.106
diff -u -p -u -r1.106 usbdi.c
--- sys/dev/usb/usbdi.c 3 Apr 2020 20:11:47 -0000 1.106
+++ sys/dev/usb/usbdi.c 1 Jun 2020 06:19:49 -0000
@@ -735,13 +735,12 @@ usb_transfer_complete(struct usbd_xfer *
if (polling)
pipe->running = 0;
-#ifdef DIAGNOSTIC
if (xfer->actlen > xfer->length) {
printf("%s: actlen > len %u > %u\n", __func__, xfer->actlen,
xfer->length);
+ KASSERT(xfer->actlen <= xfer->length);
xfer->actlen = xfer->length;
}
-#endif
if (usbd_xfer_isread(xfer) && xfer->actlen != 0 &&
(xfer->flags & USBD_NO_COPY) == 0)
--
Regards,
Mikolaj
