On Fri, Oct 18, 2019 at 11:37:01AM +0200, Martin Pieuchot wrote:
> The question here is how an `xfer' with a status of NORMAL_COMPLETION
> can be found in the pipe's queue?
I don't know yet.
Here is some output with usbdebug = 6.
The error handling starts at line "xhci0: txerr? code 4" and eventually
the code loops on the cancelled xfer as shown before.
Produced with the following diff and doing a manual write to usbdebug
with ddb before starting the print job (the system won't boot fast
enough with usbdebug set to 6).
Does this help?
diff b8f72638b63831677f92fc0c98e5d2d00058e226 /usr/src
blob - e2c8f1b97b22f57327768022bb12ae03f6c9cdc0
file + sys/dev/usb/usb.c
--- sys/dev/usb/usb.c
+++ sys/dev/usb/usb.c
@@ -66,10 +66,11 @@
#include <dev/usb/usb_mem.h>
#include <dev/usb/usbpcap.h>
+#define USB_DEBUG
#ifdef USB_DEBUG
#define DPRINTF(x) do { if (usbdebug) printf x; } while (0)
#define DPRINTFN(n,x) do { if (usbdebug>(n)) printf x; } while (0)
-int usbdebug = 0;
+int usbdebug = 5;
#if defined(UHCI_DEBUG) && NUHCI > 0
extern int uhcidebug;
#endif
blob - e51b4b31947a37ac3127fddef935ba2b4c326778
file + sys/dev/usb/usbdi.c
--- sys/dev/usb/usbdi.c
+++ sys/dev/usb/usbdi.c
@@ -45,6 +45,7 @@
#include <dev/usb/usbdivar.h>
#include <dev/usb/usb_mem.h>
+#define USB_DEBUG
#ifdef USB_DEBUG
#define DPRINTF(x) do { if (usbdebug) printf x; } while (0)
#define DPRINTFN(n,x) do { if (usbdebug>(n)) printf x; } while (0)
blob - f9d7eb3a4018dd5b628f0d866630f5732cf53593
file + sys/dev/usb/xhci.c
--- sys/dev/usb/xhci.c
+++ sys/dev/usb/xhci.c
@@ -41,6 +41,7 @@ struct cfdriver xhci_cd = {
NULL, "xhci", DV_DULL
};
+#define XHCI_DEBUG
#ifdef XHCI_DEBUG
#define DPRINTF(x) do { if (xhcidebug) printf x; } while(0)
#define DPRINTFN(n,x) do { if (xhcidebug>(n)) printf x; } while (0)
@@ -2176,6 +2177,7 @@ xhci_abort_xfer(struct usbd_xfer *xfer, usbd_status st
/* Transfer is already done. */
if (xfer->status != USBD_IN_PROGRESS) {
DPRINTF(("%s: already done \n", __func__));
+ usbd_dump_pipe(xfer->pipe);
return;
}
usbd_alloc_xfer() = 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da1e0, flags=2, pipe=0xffff800000dbc000,
running=0
usbd_dump_queue: pipe=0xffff800000dbc000
usb_insert_transfer: pipe=0xffff800000dbc000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000dbc000 xfer=0xfffffd811f8da1e0 status=0
actlen=1
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000dbc000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=19, pipe=0xffff800000e65000,
running=0
usbd_dump_queue: pipe=0xffff800000e65000
usb_insert_transfer: pipe=0xffff800000e65000 running=0 timeout=0
usb_transfer_complete: pipe=0xffff800000e65000 xfer=0xfffffd811f8da2d0 status=0
actlen=16384
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000e65000, xfer=0x0
usbd_alloc_xfer() = 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da1e0, flags=2, pipe=0xffff800000dbc000,
running=0
usbd_dump_queue: pipe=0xffff800000dbc000
usb_insert_transfer: pipe=0xffff800000dbc000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000dbc000 xfer=0xfffffd811f8da1e0 status=0
actlen=1
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000dbc000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=19, pipe=0xffff800000e65000,
running=0
usbd_dump_queue: pipe=0xffff800000e65000
usb_insert_transfer: pipe=0xffff800000e65000 running=0 timeout=0
usb_transfer_complete: pipe=0xffff800000e65000 xfer=0xfffffd811f8da2d0 status=0
actlen=16384
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000e65000, xfer=0x0
usbd_alloc_xfer() = 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da1e0, flags=2, pipe=0xffff800000dbc000,
running=0
usbd_dump_queue: pipe=0xffff800000dbc000
usb_insert_transfer: pipe=0xffff800000dbc000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000dbc000 xfer=0xfffffd811f8da1e0 status=0
actlen=1
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000dbc000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=19, pipe=0xffff800000e65000,
running=0
usbd_dump_queue: pipe=0xffff800000e65000
usb_insert_transfer: pipe=0xffff800000e65000 running=0 timeout=0
usb_transfer_complete: pipe=0xffff800000e65000 xfer=0xfffffd811f8da2d0 status=0
actlen=16384
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000e65000, xfer=0x0
usbd_alloc_xfer() = 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da1e0, flags=2, pipe=0xffff800000dbc000,
running=0
usbd_dump_queue: pipe=0xffff800000dbc000
usb_insert_transfer: pipe=0xffff800000dbc000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000dbc000 xfer=0xfffffd811f8da1e0 status=0
actlen=1
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000dbc000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da1e0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=19, pipe=0xffff800000e65000,
running=0
usbd_dump_queue: pipe=0xffff800000e65000
usb_insert_transfer: pipe=0xffff800000e65000 running=0 timeout=0
usb_transfer_complete: pipe=0xffff800000e65000 xfer=0xfffffd811f8da2d0 status=0
actlen=16384
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000e65000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da2d0
usb_transfer_complete: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0 status=0
actlen=23
usb_transfer_complete: repeat=0 new head=0x0
usbd_transfer: xfer=0xfffffd811f8da690, flags=4, pipe=0xffff800000e66000,
running=1
usbd_dump_queue: pipe=0xffff800000e66000
usb_insert_transfer: pipe=0xffff800000e66000 running=1 timeout=0
usbd_start_next: pipe=0xffff800000e66000, xfer=0xfffffd811f8da690
xhci0: txerr? code 4
usb_transfer_complete: pipe=0xffff800000e66000 xfer=0xfffffd811f8da690
status=13 actlen=26
usb_transfer_complete: repeat=0 new head=0x0
usbd_transfer: xfer=0xfffffd811f8da4b0, flags=4, pipe=0xffff800000e66000,
running=1
usbd_dump_queue: pipe=0xffff800000e66000
usb_insert_transfer: pipe=0xffff800000e66000 running=1 timeout=0
usb_transfer_complete: pipe=0xffff800000406000 xfer=0xfffffd811f8dac30 status=0
actlen=1
usb_transfer_complete: repeat=1 new head=0xfffffd811f8dac30
usb0: usb_needs_explore
usb_add_task: task=0xffff800000093e80 state=0 type=1
usb_explore: usb0
usbd_alloc_xfer() = 0xfffffd811f8da2d0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=2, pipe=0xffff800000405000,
running=0
usbd_dump_queue: pipe=0xffff800000405000
usb_insert_transfer: pipe=0xffff800000405000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000406000 xfer=0xfffffd811f8dac30 status=0
actlen=1
usb_transfer_complete: repeat=1 new head=0xfffffd811f8dac30
usb0: usb_needs_explore
usb_add_task: task=0xffff800000093e80 state=2 type=1
usb_transfer_complete: pipe=0xffff800000405000 xfer=0xfffffd811f8da2d0 status=0
actlen=4
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000405000, xfer=0x0
usb_transfer_complete: pipe=0xffff800000406000 xfer=0xfffffd811f8dac30 status=0
actlen=1
usb_transfer_complete: repeat=1 new head=0xfffffd811f8dac30
usb0: usb_needs_explore
usb_add_task: task=0xffff800000093e80 state=3 type=1
usbd_free_xfer: 0xfffffd811f8da2d0
usbd_alloc_xfer() = 0xfffffd811f8da2d0
usbd_transfer: xfer=0xfffffd811f8da2d0, flags=2, pipe=0xffff800000405000,
running=0
usbd_dump_queue: pipe=0xffff800000405000
usb_insert_transfer: pipe=0xffff800000405000 running=0 timeout=5000
usb_transfer_complete: pipe=0xffff800000406000 xfer=0xfffffd811f8dac30 status=0
actlen=1
usb_transfer_complete: repeat=1 new head=0xfffffd811f8dac30
usb0: usb_needs_explore
usb_add_task: task=0xffff800000093e80 state=3 type=1
usb_transfer_complete: pipe=0xffff800000405000 xfer=0xfffffd811f8da2d0 status=0
actlen=0
usb_transfer_complete: repeat=0 new head=0x0
usbd_start_next: pipe=0xffff800000405000, xfer=0x0
usbd_free_xfer: 0xfffffd811f8da2d0
usbd_abort_pipe: pipe=0xffff800000e65000
usbd_dump_queue: pipe=0xffff800000e65000
usbd_abort_pipe: pipe=0xffff800000e66000
usbd_dump_queue: pipe=0xffff800000e66000
xfer=0xfffffd811f8da4b0
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
xhci_abort_xfer: already done
usbd_dump_pipe: pipe=0xffff800000e66000
usbd_dump_iface: iface=0xffff800000e71680
device=0xffff800000d9d200 idesc=0xffff800000e325e9 index=0 altindex=0 priv=0x0
usbd_dump_device: dev=0xffff800000d9d200
bus=0xffff8000000cd000 default_pipe=0xffff800000dbc000
address=11 config=1 depth=4 speed=3 self_powered=1 power=98 langid=1033
usbd_dump_endpoint: endp=0xffff800000e325d0
edesc=0xffff800000e325f9 refcnt=1
bEndpointAddress=0x81
(usbd_dump_pipe:)
running=0 aborting=1
intrxfer=0x0, repeat=0, interval=-1
usbd_abort_pipe: pipe=0xffff800000e66000 xfer=0xfffffd811f8da4b0
(methods=0xffffffff81f16aa0)
xhci_abort_xfer: xfer=0xfffffd811f8da4b0 status=NORMAL_COMPLETION err=CANCELLED
actlen=23 len=64 idx=-1
