NetBSD Problem Report #56678

From reinoud@gorilla.13thmonkey.org  Sun Jan 30 14:28:41 2022
Return-Path: <reinoud@gorilla.13thmonkey.org>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits))
	(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 73A951A9239
	for <gnats-bugs@gnats.NetBSD.org>; Sun, 30 Jan 2022 14:28:41 +0000 (UTC)
Message-Id: <20220130142841.2D5932FF0934@gorilla.13thmonkey.org>
Date: Sun, 30 Jan 2022 15:28:41 +0100 (CET)
From: reinoud@13thmonkey.org
Reply-To: reinoud@13thmonkey.org
To: gnats-bugs@NetBSD.org
Subject: usbdevs stuck on usbxfer
X-Send-Pr-Version: 3.95

>Number:         56678
>Category:       kern
>Synopsis:       usbdevs stuck on usbxfer
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun Jan 30 14:30:00 +0000 2022
>Originator:     Reinoud Zandijk
>Release:        NetBSD 9.99.92
>Organization:

>Environment:


System: NetBSD gorilla.13thmonkey.org 9.99.92 NetBSD 9.99.92 (GENERIC) #0: Thu Dec 16 22:54:09 CET 2021 reinoud@gorilla.13thmonkey.org:/tmp/obj-clean/sys/arch/amd64/compile/GENERIC amd64
Architecture: x86_64
Machine: amd64
>Description:

I reinserted an USB harddisc I had inserted earlier and this time it failed to
show up in the dmesg. I issued an `usbdevs' command and it got stuck and
didn't unfreeze after a timeout.

> sudo usbdevs
Password:
addr 0: xHCI root hub, NetBSD
addr 0: xHCI root hub, NetBSD
 addr 1: ITE Device(8595), ITE Tech. Inc.
 addr 2: USB2.0 Hub, Genesys Logic
addr 0: xHCI root hub, NetBSD
addr 0: xHCI root hub, NetBSD
[ 2129583.0259428] load: 0.03  cmd: usbdevs 8614 [usbxfer] 0.02u 0.00s 0% 1648k

Using gdb on the /netbsd.gdb kernel with a kvm target to print info gave:

(gdb) print *((struct uhub_softc *)uhub_cd.cd_devs[7]->dv_private)->sc_hub->ud_pipe0
$1 = {up_iface = 0x0, up_dev = 0xffff807b6b4b3bc0, up_endpoint = 0xffff807b6b4b3bf8, up_running = 0 '\000', 
  up_aborting = 0 '\000', up_serialise = true, up_queue = {sqh_first = 0x0, sqh_last = 0xffff807b6b4b3d20}, 
  up_async_task = {next = {tqe_next = 0x0, tqe_prev = 0x0}, 
    fun = 0xffffffff80474c83 <usbd_clear_endpoint_stall_task>, arg = 0xffff807b6b4b3d00, queue = 2, flags = 128}, 
  up_intrxfer = 0x0, up_repeat = 0 '\000', up_interval = -1, up_flags = 0 '\000', up_callingxfer = 0x0, 
  up_callingcv = {cv_opaque = {0x0, 0xffffffff813bdd07}}, 
  up_methods = 0xffffffff8124f980 <xhci_device_ctrl_methods>}
(gdb)  print *((struct umass_softc *)umass_cd.cd_devs[0]->dv_private)->sc_udev->ud_pipe0
$2 = {up_iface = 0x0, up_dev = 0xffff807c31ccfe40, up_endpoint = 0xffff807c31ccfe78, up_running = 0 '\000', 
  up_aborting = 0 '\000', up_serialise = true, up_queue = {sqh_first = 0x0, sqh_last = 0xffff8083d506b9a0}, 
  up_async_task = {next = {tqe_next = 0x2600000033, tqe_prev = 0x2100000024}, 
    fun = 0xffffffff80474c83 <usbd_clear_endpoint_stall_task>, arg = 0xffff8083d506b980, queue = 2, flags = 128}, 
  up_intrxfer = 0x0, up_repeat = 0 '\000', up_interval = -1, up_flags = 0 '\000', up_callingxfer = 0x0, 
  up_callingcv = {cv_opaque = {0x0, 0xffffffff813bdd07}}, 
  up_methods = 0xffffffff8124f980 <xhci_device_ctrl_methods>}
(gdb) print *((struct umass_softc *)umass_cd.cd_devs[1]->dv_private)->sc_udev->ud_pipe0
$3 = {up_iface = 0x0, up_dev = 0xffff8086090c32c0, up_endpoint = 0xffff8086090c32f8, up_running = 1 '\001', 
  up_aborting = 0 '\000', up_serialise = true, up_queue = {sqh_first = 0xffff807b6b0ae2b8, 
    sqh_last = 0xffff807b6b0aed50}, up_async_task = {next = {tqe_next = 0x2800000031, tqe_prev = 0x270000002e}, 
    fun = 0xffffffff80474c83 <usbd_clear_endpoint_stall_task>, arg = 0xffff808962a63900, queue = 2, flags = 128}, 
  up_intrxfer = 0x0, up_repeat = 0 '\000', up_interval = -1, up_flags = 0 '\000', up_callingxfer = 0x0, 
  up_callingcv = {cv_opaque = {0x0, 0xffffffff813bdd07}}, 
  up_methods = 0xffffffff8124f980 <xhci_device_ctrl_methods>}
(gdb) print *((struct umass_softc *)umass_cd.cd_devs[1]->dv_private)->sc_udev->ud_pipe0->up_queue.sqh_first
$4 = {ux_pipe = 0xffff808962a63900, ux_priv = 0xffff8083f67ccc80, ux_buffer = 0x0, ux_cv = {cv_opaque = {0x0, 
      0xffffffff813bcee2}}, ux_length = 0, ux_actlen = 0, ux_flags = 0, ux_timeout = 15000, 
  ux_status = USBD_IN_PROGRESS, ux_callback = 0xffffffff8049405a <umass_bbb_state>, ux_done = 0 '\000', 
  ux_state = 158 '\236', ux_request = {bmRequestType = 2 '\002', bRequest = 1 '\001', wValue = "\000", 
    wIndex = "�", wLength = "\000"}, ux_frlengths = 0x0, ux_nframes = 0, 
  ux_methods = 0xffffffff8124f980 <xhci_device_ctrl_methods>, ux_bus = 0xffff807b6ad354f0, ux_dmabuf = {
    udma_block = 0x0, udma_offs = 0}, ux_buf = 0x0, ux_bufsize = 0, ux_rqflags = 1 '\001', ux_next = {
    sqe_next = 0xffff807b6b44b048}, ux_hcpriv = 0x0, ux_aborttask = {next = {tqe_next = 0x1, tqe_prev = 0x1}, 
    fun = 0xffffffff80473922 <usbd_xfer_timeout_task>, arg = 0xffff807b6b0ae2b8, queue = 2, flags = 128}, 
  ux_callout = {_c_store = {0xffffffff818a67e0 <callout_cpu0+160>, 0xffffffff818a67e0 <callout_cpu0+160>, 
      0xffffffff804739b7 <usbd_xfer_timeout>, 0xffff807b6b0ae2b8, 0xffffffff818a6740 <callout_cpu0>, 
      0x1000bfc378e, 0x11deeba1, 0x0, 0x0, 0x0}}, ux_timeout_set = true, ux_timeout_reset = true}
(gdb) print *((struct umass_softc *)umass_cd.cd_devs[1]->dv_private)->sc_udev->ud_pipe0->up_queue.sqh_first
$8 = {ux_pipe = 0xffff808962a63900, ux_priv = 0xffff8083f67ccc80, ux_buffer = 0x0, ux_cv = {cv_opaque = {0x0, 
      0xffffffff813bcee2}}, ux_length = 0, ux_actlen = 0, ux_flags = 0, ux_timeout = 15000, 
  ux_status = USBD_IN_PROGRESS, ux_callback = 0xffffffff8049405a <umass_bbb_state>, ux_done = 0 '\000', 
  ux_state = 158 '\236', ux_request = {bmRequestType = 2 '\002', bRequest = 1 '\001', wValue = "\000", 
    wIndex = "�", wLength = "\000"}, ux_frlengths = 0x0, ux_nframes = 0, 
  ux_methods = 0xffffffff8124f980 <xhci_device_ctrl_methods>, ux_bus = 0xffff807b6ad354f0, ux_dmabuf = {
    udma_block = 0x0, udma_offs = 0}, ux_buf = 0x0, ux_bufsize = 0, ux_rqflags = 1 '\001', ux_next = {
    sqe_next = 0xffff807b6b44b048}, ux_hcpriv = 0x0, ux_aborttask = {next = {tqe_next = 0x1, tqe_prev = 0x1}, 
    fun = 0xffffffff80473922 <usbd_xfer_timeout_task>, arg = 0xffff807b6b0ae2b8, queue = 2, flags = 128}, 
  ux_callout = {_c_store = {0xffffffff818a67e0 <callout_cpu0+160>, 0xffffffff818a67e0 <callout_cpu0+160>, 
      0xffffffff804739b7 <usbd_xfer_timeout>, 0xffff807b6b0ae2b8, 0xffffffff818a6740 <callout_cpu0>, 
      0x1000bfc378e, 0x11deeba1, 0x0, 0x0, 0x0}}, ux_timeout_set = true, ux_timeout_reset = true}
(gdb) print *((struct xhci_softc *)xhci_cd.cd_devs[1]->dv_private)
$9 = {sc_dev = 0xffff807b6acd6980, sc_child = 0xffff807b6acd6cc0, sc_child2 = 0xffff807b6ad4e040, sc_ios = 1040384, 
  sc_iot = 0xffffffff818440e0 <x86_mem>, sc_ioh = 18446649535508205568, sc_cbh = 18446649535508205568, sc_obh = 18446649535508205600, 
  sc_rbh = 18446649535508206784, sc_dbh = 18446649535508207072, sc_bus = {ub_hcpriv = 0xffff807b6ad35000, ub_revision = 6, ub_hctype = 0, ub_busnum = 0, 
    ub_methods = 0xffffffff8124fa00 <xhci_bus_methods>, ub_pipesize = 192, ub_usedma = true, ub_dmaflags = 0, 
    ub_dmatag = 0xffffffff81844e80 <pci_bus_dma64_tag>, ub_lock = 0xffff807b6ad35990, ub_roothub = 0xffff807b6b0a9740, ub_rhaddr = 0 '\000', 
    ub_rhconf = 1 '\001', ub_devices = {0x0, 0xffff807b6b0a9740, 0x0 <repeats 127 times>}, ub_needsexplore_cv = {cv_opaque = {0xffff807b6b0ed500, 
        0xffffffff813bcd1f}}, ub_needsexplore = 0 '\000', ub_usepolling = 0 '\000', ub_usbctl = 0xffff807b6acd6cc0, ub_stats = {uds_requests = {31, 0, 0, 
        0}}, ub_soft = 0x8d8}, sc_bus2 = {ub_hcpriv = 0xffff807b6ad35000, ub_revision = 4, ub_hctype = 0, ub_busnum = 0, 
    ub_methods = 0xffffffff8124fa00 <xhci_bus_methods>, ub_pipesize = 192, ub_usedma = true, ub_dmaflags = 0, 
    ub_dmatag = 0xffffffff81844e80 <pci_bus_dma64_tag>, ub_lock = 0xffff807b6ad35990, ub_roothub = 0xffff807b6b0a9c40, ub_rhaddr = 0 '\000', 
    ub_rhconf = 1 '\001', ub_devices = {0x0, 0xffff807b6b0a9c40, 0xffff807da860ee80, 0xffff80853e0f8100, 0xffff807b6b4b3bc0, 0xffff807c3688c880, 
      0xffff807c31ccfe40, 0xffff8086090c32c0, 0x0 <repeats 121 times>}, ub_needsexplore_cv = {cv_opaque = {0xffff807b6b0ed940, 0xffffffff813bcd1f}}, 
    ub_needsexplore = 0 '\000', ub_usepolling = 0 '\000', ub_usbctl = 0xffff807b6ad4e040, ub_stats = {uds_requests = {2414, 120, 283447, 1602874}}, 
    ub_soft = 0x900}, sc_lock = {u = {mtxa_owner = 0, s = {mtxs_dummy = 0 '\000', mtxs_ipl = {_ipl = 0 '\000'}, mtxs_lock = 0 '\000', 
        mtxs_unused = 0 '\000'}}}, sc_intr_lock = {u = {mtxa_owner = 1537, s = {mtxs_dummy = 1 '\001', mtxs_ipl = {_ipl = 6 '\006'}, 
        mtxs_lock = 0 '\000', mtxs_unused = 0 '\000'}}}, sc_xferpool = 0xffff807b6ad0d4c0, sc_pgsz = 4096, sc_ctxsz = 64, sc_maxslots = 64, 
  sc_maxintrs = 8, sc_maxspbuf = 2, sc_maxports = 10, sc_ctlrportbus = 0xffff808a66dda320 "?", sc_ctlrportmap = 0xffff807b6acc6300, sc_rhportmap = {
    0xffff807b6acc6380, 0xffff807b6acc6400}, sc_rhportcount = {4, 6}, sc_intrxfer = {0xffff807b6b0ae038, 0xffff807b6b0ae178}, 
  sc_slots = 0xffffaa0086d98000, sc_cr = 0xffff807b6acc6500, sc_er = 0xffff807b6acc6580, sc_eventst_dma = {udma_block = 0xffff807b6ad3e340, 
    udma_offs = 4032}, sc_dcbaa_dma = {udma_block = 0xffff807b6ad3e4c0, udma_offs = 0}, sc_spbufarray_dma = {udma_block = 0xffff807b6ad15b80, 
    udma_offs = 4032}, sc_spbuf_dma = 0xffff807b6acc6480, sc_cmdbusy_cv = {cv_opaque = {0x0, 0xffffffff813f5344}}, sc_command_cv = {cv_opaque = {0x0, 
      0xffffffff813f533c}}, sc_command_addr = 0, sc_result_trb = {trb_0 = 4327410576, trb_2 = 16777216, trb_3 = 83919873}, sc_resultpending = false, 
  sc_dying = false, sc_suspender = 0x0, sc_vendor_init = 0x0, sc_vendor_port_status = 0x0, sc_quirks = 0, sc_hcc = 41484261, sc_hcc2 = 63, sc_regs = {
    usbcmd = 0, dnctrl = 0, dcbaap = 0, config = 0, erstsz0 = 0, erstba0 = 0, erdp0 = 0, iman0 = 0, imod0 = 0}}
(gdb) print *((struct xhci_softc *)xhci_cd.cd_devs[1]->dv_private)->sc_cr
$10 = {xr_dma = {udma_block = 0xffff807b6ad3e040, udma_offs = 0}, xr_lock = {u = {mtxa_owner = 0, s = {mtxs_dummy = 0 '\000', mtxs_ipl = {
          _ipl = 0 '\000'}, mtxs_lock = 0 '\000', mtxs_unused = 0 '\000'}}}, xr_trb = 0xffffaa049c277000, xr_cookies = 0xffff807b6acff000, xr_ntrb = 256, 
  xr_ep = 186, xr_cs = 0, is_halted = false}
(gdb) print *((struct xhci_softc *)xhci_cd.cd_devs[1]->dv_private)->sc_er
$11 = {xr_dma = {udma_block = 0xffff807b6ad3e1c0, udma_offs = 0}, xr_lock = {u = {mtxa_owner = 0, s = {mtxs_dummy = 0 '\000', mtxs_ipl = {
          _ipl = 0 '\000'}, mtxs_lock = 0 '\000', mtxs_unused = 0 '\000'}}}, xr_trb = 0xffffaa049c278000, xr_cookies = 0xffff807b6ad00000, xr_ntrb = 256, 
  xr_ep = 10, xr_cs = 0, is_halted = false}


For completion, the USB setup of the machine is
> sudo drvctl -lt xhci0
usb0
  uhub0
usb1
  uhub1
    uhidev0
      uhid0
      uhid1
    uhub6
> sudo drvctl -lt xhci1
usb2
  uhub2
usb3
  uhub3
    uhub7
      uhub8
        uhidev1
          ums0
            wsmouse0
        uhidev2
          ukbd0
            wskbd0
        uhidev3
          ums1
            wsmouse1
          uhid2
          uhid3
    umass0
      atapibus0
        cd0
    umass1
      scsibus0
        sd0
> sudo drvctl -lt xhci2
usb4
  uhub4
usb5
  uhub5
> sudo drvctl -lt xhci3
drvctl: DRVLISTDEV: Device not configured
>


>How-To-Repeat:
Unknown

>Fix:
Unknown


>Unformatted:

Home	PR Database Search