Re: usb: Error while assigning device slot ID

[Mathias Nyman]

On 12/10/25 10:31, Alexander Wilhelm wrote:
> > Flash driver appears as a Full-Speed device. Is this correct?
>
> Yes, that's right.
>
> > Does it work if you boot without the drive and then connect it later?
>
> If I do so, nothing happens and I see nothing in logread, too.
>
> [...]
> > Could you add xhci tracing, and dump the command and event rings after timeout?
>
> Sure, here are the commands and their respective output:
>
>      # tracer: nop
>      #
>      # entries-in-buffer/entries-written: 103/103   #P:4
>      #
>      #                                _-----=> irqs-off/BH-disabled
>      #                               / _----=> need-resched
>      #                              | / _---=> hardirq/softirq
>      #                              || / _--=> preempt-depth
>      #                              ||| / _-=> migrate-disable
>      #                              |||| /     delay
>      #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
>      #              | |         |   |||||     |         |
>              modprobe-20491   [001] .N...   242.678069: xhci_dbg_init: // Device context base array address = 0x0x00000000813f1000 (DMA), 000000006440d11f (virt)
>              modprobe-20491   [001] .N...   242.678079: xhci_ring_alloc: CMD 0000000099949093: enq 0x0000000086616000(0x0000000086616000) deq 0x0000000086616000(0x0000000086616000) segs 1 stream 0 bounce 0 cycle 1
>              modprobe-20491   [001] .N...   242.678085: xhci_dbg_init: Allocated command ring at 0000000099949093
>              modprobe-20491   [001] .N...   242.678090: xhci_dbg_init: First segment DMA is 0x0x0000000086616000
>              modprobe-20491   [001] .N...   242.678095: xhci_dbg_init: // Setting command ring address to 0x0000000086616001
>              modprobe-20491   [001] .N...   242.678101: xhci_dbg_init: // Doorbell array is located at offset 0x480 from cap regs base addr
>              modprobe-20491   [001] .N...   242.678106: xhci_dbg_init: Allocating primary event ring
>              modprobe-20491   [001] .N...   242.678111: xhci_ring_alloc: EVENT 0000000069cb484c: enq 0x000000009dd65000(0x000000009dd65000) deq 0x000000009dd65000(0x000000009dd65000) segs 2 stream 0 bounce 0 cycle 1
>              modprobe-20491   [001] .N...   242.678118: xhci_dbg_init: // Write event ring dequeue pointer, preserving EHB bit
>              modprobe-20491   [001] .N...   242.678199: xhci_dbg_init: xhci_run
>              modprobe-20491   [001] .N...   242.678204: xhci_dbg_init: ERST deq = 64'h9dd65000
>              modprobe-20491   [001] dN...   242.678318: xhci_dbg_init: // Turn on HC, cmd = 0x5.
>           kworker/1:1-54      [001] d....   242.695620: xhci_get_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
>           kworker/1:3-20526   [001] d....   242.699424: xhci_get_port_status: port-0: Powered Connected Disabled Link:Polling PortSpeed:1 Change: CSC Wake:
>           kworker/1:2-82      [001] d....   242.699445: xhci_get_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
>           kworker/1:0-21      [001] d....   242.775417: xhci_get_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
>           kworker/1:0-21      [001] d....   242.779413: xhci_get_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
>           kworker/1:0-21      [001] d....   242.783420: xhci_get_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
>           kworker/1:0-21      [001] d....   242.803419: xhci_get_port_status: port-0: Powered Connected Disabled Link:Polling PortSpeed:1 Change: Wake:
>           kworker/1:0-21      [001] d....   242.803448: xhci_queue_trb: CMD: Enable Slot Command: flags C
>           kworker/1:0-21      [001] d....   242.803449: xhci_inc_enq: CMD 0000000099949093: enq 0x0000000086616010(0x0000000086616000) deq 0x0000000086616000(0x0000000086616000) segs 1 stream 0 bounce 0 cycle 1
>           kworker/1:0-21      [001] d....   242.803455: xhci_ring_host_doorbell: Ring doorbell for Command Ring 0

Command ring is at 0x0000000086616000, crcr register is set correctly, cycle is set to 1
Event ring is at 0x000000009dd65000

Driver correctly writes the command to command ring at 0x0000000086616001

> even-ring/trbs:
>
>      0x000000009dd65000: type 'UNKNOWN' -> raw 00000000 00000000 00000000 00000000
>      0x000000009dd65010: type 'UNKNOWN' -> raw 00000000 00000000 00000000 00000000
>
> command-ring/trbs:
>
>      0x0000000086616000: Enable Slot Command: flags C
>      0x0000000086616010: type 'UNKNOWN' -> raw 00000000 00000000 00000000 00000000

> It seems like the TRBS output here is not very useful, is it?


It shows the enable slot command was correctly queued to the command ring at 0x86616000,
but xHC controller didn't process it at all as event ring is empty.

It behaves as if xHC isn't really running at all.
portsc registers can show port status (connect) even if xHC isn't running.

I guess next step would be to bisect this and find the offending commit

Thanks
Mathias