[REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Forest]

#regzbot introduced: 63a1f8454962

Dear maintainer,

I think I have found a regression in kernels version 6.10 and newer,
including the latest mainline v6.13-rc4:

fastboot (the tool for communicating with Android bootloaders) now fails to
perform various operations over USB.

The problem manifests as an error when attempting to 'fastboot flash' an
image (e.g. a new kernel containing security updates) to a LineageOS phone.
It also manifests with simpler operations like reading a variable from the
bootloader. For example:

  fastboot getvar kernel

A typical error message when the failure occurs:

  getvar:kernel  FAILED (remote: 'GetVar Variable Not found')

I can reproduce this at will. It happens about 50% of the time when I
run the above getvar command, and almost all the time when I try to push
a new kernel to a device.

A git bisect reveals this:

63a1f8454962a64746a59441687dc2401290326c is the first bad commit
commit 63a1f8454962a64746a59441687dc2401290326c
Author: Mathias Nyman <mathias.nyman@linux.intel.com>
Date:   Mon Apr 29 17:02:28 2024 +0300
    xhci: stored cached port capability values in one place

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Mathias Nyman]

Hi

On 27.12.2024 23.59, Forest wrote:
> #regzbot introduced: 63a1f8454962
> 
> Dear maintainer,
> 
> I think I have found a regression in kernels version 6.10 and newer,
> including the latest mainline v6.13-rc4:
> 
> fastboot (the tool for communicating with Android bootloaders) now fails to
> perform various operations over USB.
> 
> The problem manifests as an error when attempting to 'fastboot flash' an
> image (e.g. a new kernel containing security updates) to a LineageOS phone.
> It also manifests with simpler operations like reading a variable from the
> bootloader. For example:
> 
>    fastboot getvar kernel
> 
> A typical error message when the failure occurs:
> 
>    getvar:kernel  FAILED (remote: 'GetVar Variable Not found')
> 
> I can reproduce this at will. It happens about 50% of the time when I
> run the above getvar command, and almost all the time when I try to push
> a new kernel to a device.
> 
> A git bisect reveals this:
> 
> 63a1f8454962a64746a59441687dc2401290326c is the first bad commit
> commit 63a1f8454962a64746a59441687dc2401290326c
> Author: Mathias Nyman <mathias.nyman@linux.intel.com>
> Date:   Mon Apr 29 17:02:28 2024 +0300
>      xhci: stored cached port capability values in one place

It's not clear to me why this patch would cause regression.

Could you enable xhci and usb core dynamic debug before connecting the
device, and then share dmesg after the issue is triggered.

dmesg of a working case would also be good to have for comparison.

mount -t debugfs none /sys/kernel/debug
echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control
echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
< Reproduce issue >
Send output of dmesg

Thanks
Mathias

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Forest]

On Thu, 2 Jan 2025 16:13:34 +0200, Mathias Nyman wrote:

>It's not clear to me why this patch would cause regression.
>
>Could you enable xhci and usb core dynamic debug before connecting the
>device, and then share dmesg after the issue is triggered.
>
>dmesg of a working case would also be good to have for comparison.

I booted kernel 9b780c845fb6 (the last good one), logged in to my desktop,
waited a couple of minutes to let things settle, and then ran 'fastboot
getvar kernel' twice with the android device in bootloader mode.
Here's the dmesg output:


[  178.056557] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  179.166570] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  179.738601] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  179.874603] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  195.331308] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x202e1
[  195.331313] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  195.331337] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0008
[  195.331343] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x202e1, return 0x10101
[  195.331354] xhci_hcd 0000:0c:00.0: clear port3 connect change, portsc: 0x2e1
[  195.331360] usb usb1-port3: status 0101, change 0001, 12 Mb/s
[  195.331363] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  195.359097] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  195.367107] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  195.403105] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  195.439107] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  195.475109] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  195.475119] usb usb1-port3: debounce total 100ms stable 100ms status 0x101
[  195.475124] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.475222] xhci_hcd 0000:0c:00.0: Slot 5 output ctx = 0x0x00000000fff58000 (dma)
[  195.475232] xhci_hcd 0000:0c:00.0: Slot 5 input ctx = 0x0x00000000fff4e000 (dma)
[  195.475240] xhci_hcd 0000:0c:00.0: Set slot id 5 dcbaa entry 0000000014c537d8 to 0xfff58000
[  195.475261] xhci_hcd 0000:0c:00.0: set port reset, actual port 1-3 status  = 0x2e1
[  195.543104] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x331, return 0x111
[  195.543113] usb usb1-port3: not reset yet, waiting 60ms
[  195.550132] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x200e03
[  195.550137] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  195.611110] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x200e03, return 0x100503
[  195.611123] xhci_hcd 0000:0c:00.0: clear port3 reset change, portsc: 0xe03
[  195.671106] usb 1-3: new high-speed USB device number 6 using xhci_hcd
[  195.671111] xhci_hcd 0000:0c:00.0: Slot ID 5: HW portnum 7, hcd portnum 2
[  195.671113] xhci_hcd 0000:0c:00.0: udev->tt = 0000000000000000
[  195.671115] xhci_hcd 0000:0c:00.0: udev->ttport = 0x0
[  195.671117] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.671624] xhci_hcd 0000:0c:00.0: Successful setup context command
[  195.671628] xhci_hcd 0000:0c:00.0: Op regs DCBAA ptr = 0x000000fffff000
[  195.671630] xhci_hcd 0000:0c:00.0: Slot ID 5 dcbaa entry @0000000014c537d8 = 0x000000fff58000
[  195.671633] xhci_hcd 0000:0c:00.0: Output Context DMA address = 0xfff58000
[  195.671634] xhci_hcd 0000:0c:00.0: Internal device address = 0
[  195.674197] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  195.676204] xhci_hcd 0000:0c:00.0: set port reset, actual port 1-3 status  = 0xe03
[  195.743113] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x331, return 0x111
[  195.743124] usb usb1-port3: not reset yet, waiting 60ms
[  195.751006] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x200e03
[  195.751011] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  195.811114] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x200e03, return 0x100503
[  195.811126] xhci_hcd 0000:0c:00.0: clear port3 reset change, portsc: 0xe03
[  195.855115] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  195.871114] xhci_hcd 0000:0c:00.0: Resetting device with slot ID 5
[  195.871119] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.871155] xhci_hcd 0000:0c:00.0: Completed reset device command.
[  195.871160] xhci_hcd 0000:0c:00.0: Can't reset device (slot ID 5) in default state
[  195.871162] xhci_hcd 0000:0c:00.0: Not freeing device rings.
[  195.871165] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.871940] xhci_hcd 0000:0c:00.0: Successful setup address command
[  195.871944] xhci_hcd 0000:0c:00.0: Op regs DCBAA ptr = 0x000000fffff000
[  195.871947] xhci_hcd 0000:0c:00.0: Slot ID 5 dcbaa entry @0000000014c537d8 = 0x000000fff58000
[  195.871949] xhci_hcd 0000:0c:00.0: Output Context DMA address = 0xfff58000
[  195.871951] xhci_hcd 0000:0c:00.0: Internal device address = 5
[  195.918200] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  195.920204] usb 1-3: default language 0x0409
[  195.923197] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  195.928197] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  195.933200] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  195.935211] usb 1-3: udev 6, busnum 1, minor = 5
[  195.935215] usb 1-3: New USB device found, idVendor=0fce, idProduct=0dde, bcdDevice= 1.00
[  195.935219] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  195.935222] usb 1-3: Product: Android
[  195.935224] usb 1-3: Manufacturer: Google
[  195.935226] usb 1-3: SerialNumber: BH905BAH9E
[  195.935427] usb 1-3: usb_probe_device
[  195.935430] usb 1-3: configuration #1 chosen from 1 choice
[  195.935439] xhci_hcd 0000:0c:00.0: add ep 0x81, slot id 5, new drop flags = 0x0, new add flags = 0x8
[  195.935447] xhci_hcd 0000:0c:00.0: add ep 0x1, slot id 5, new drop flags = 0x0, new add flags = 0xc
[  195.935449] xhci_hcd 0000:0c:00.0: xhci_check_bandwidth called for udev 00000000f4c62038
[  195.935452] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.938503] xhci_hcd 0000:0c:00.0: Successful Endpoint Configure command
[  195.938523] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.938614] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 5 ep 2
[  195.938705] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.943603] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.943686] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 5 ep 1
[  195.943764] xhci_hcd 0000:0c:00.0: // Ding dong!
[  195.951200] usb 1-3: adding 1-3:1.0 (config #1, interface 0)
[  195.954200] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  200.327212] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe63, return 0x507
[  200.327233] xhci_hcd 0000:0c:00.0: clear USB_PORT_FEAT_SUSPEND
[  200.327236] xhci_hcd 0000:0c:00.0: PORTSC 0e63
[  200.327239] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xe63, write 0x10fe1
[  200.375216] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xfe3, write 0x10e01
[  200.375236] usb 1-5: usb auto-resume
[  200.375486] xhci_hcd 0000:0c:00.0: Port change event, 1-5, id 10, portsc: 0x400e03
[  200.375491] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  200.375507] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0020
[  200.376723] xhci_hcd 0000:0c:00.0: underrun event on endpoint
[  200.376726] xhci_hcd 0000:0c:00.0: overrun event on endpoint
[  200.423215] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe03, return 0x40503
[  200.423230] xhci_hcd 0000:0c:00.0: clear port5 suspend/resume change, portsc: 0xe03
[  200.443209] usb 1-5: Waited 0ms for CONNECT
[  200.443213] usb 1-5: finish resume
[  200.447237] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe03, return 0x503
[  200.447933] xhci_hcd 0000:0c:00.0: ep 0x81 - asked for 256 bytes, 248 bytes untransferred
[  200.567210] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  201.814693] xhci_hcd 0000:0c:00.0: ep 0x81 - asked for 256 bytes, 248 bytes untransferred
[  204.209316] xhci_hcd 0000:0c:00.0: // Ding dong!
[  204.209404] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 20
[  204.209565] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 19
[  204.209721] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 6
[  204.209873] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 5
[  204.210027] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 4
[  204.210187] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 3
[  204.210342] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 2
[  204.210503] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 0
[  204.210600] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xe03, write 0x10e61
[  204.227291] usb 1-5: usb auto-suspend, wakeup 0


I then did the same with kernel 63a1f8454962 (the first bad one):


[  196.399094] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  197.103104] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  197.881108] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  198.021105] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  225.430197] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x202e1
[  225.430202] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  225.430226] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0008
[  225.430233] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x202e1, return 0x10101
[  225.430244] xhci_hcd 0000:0c:00.0: clear port3 connect change, portsc: 0x2e1
[  225.430250] usb usb1-port3: status 0101, change 0001, 12 Mb/s
[  225.430254] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  225.464705] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  225.500707] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  225.536707] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  225.572708] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x2e1, return 0x101
[  225.572719] usb usb1-port3: debounce total 100ms stable 100ms status 0x101
[  225.572724] xhci_hcd 0000:0c:00.0: // Ding dong!
[  225.572826] xhci_hcd 0000:0c:00.0: Slot 5 output ctx = 0x0x00000000fff5e000 (dma)
[  225.572838] xhci_hcd 0000:0c:00.0: Slot 5 input ctx = 0x0x00000000fff54000 (dma)
[  225.572846] xhci_hcd 0000:0c:00.0: Set slot id 5 dcbaa entry 000000003fadcb3f to 0xfff5e000
[  225.572888] xhci_hcd 0000:0c:00.0: set port reset, actual port 1-3 status  = 0x2e1
[  225.616706] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  225.640709] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x331, return 0x111
[  225.640720] usb usb1-port3: not reset yet, waiting 60ms
[  225.647922] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x200e03
[  225.647927] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  225.708710] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x200e03, return 0x100503
[  225.708723] xhci_hcd 0000:0c:00.0: clear port3 reset change, portsc: 0xe03
[  225.768711] usb 1-3: new high-speed USB device number 6 using xhci_hcd
[  225.768716] xhci_hcd 0000:0c:00.0: Slot ID 5: HW portnum 7, hcd portnum 2
[  225.768718] xhci_hcd 0000:0c:00.0: udev->tt = 0000000000000000
[  225.768720] xhci_hcd 0000:0c:00.0: udev->ttport = 0x0
[  225.768722] xhci_hcd 0000:0c:00.0: // Ding dong!
[  225.769231] xhci_hcd 0000:0c:00.0: Successful setup context command
[  225.769236] xhci_hcd 0000:0c:00.0: Op regs DCBAA ptr = 0x000000fffff000
[  225.769239] xhci_hcd 0000:0c:00.0: Slot ID 5 dcbaa entry @000000003fadcb3f = 0x000000fff5e000
[  225.769241] xhci_hcd 0000:0c:00.0: Output Context DMA address = 0xfff5e000
[  225.769243] xhci_hcd 0000:0c:00.0: Internal device address = 0
[  225.771743] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  225.773750] xhci_hcd 0000:0c:00.0: set port reset, actual port 1-3 status  = 0xe03
[  225.840714] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x331, return 0x111
[  225.840726] usb usb1-port3: not reset yet, waiting 60ms
[  225.848802] xhci_hcd 0000:0c:00.0: Port change event, 1-3, id 8, portsc: 0x200e03
[  225.848807] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  225.908732] xhci_hcd 0000:0c:00.0: Get port status 1-3 read: 0x200e03, return 0x100503
[  225.908744] xhci_hcd 0000:0c:00.0: clear port3 reset change, portsc: 0xe03
[  225.968714] xhci_hcd 0000:0c:00.0: Resetting device with slot ID 5
[  225.968718] xhci_hcd 0000:0c:00.0: // Ding dong!
[  225.968757] xhci_hcd 0000:0c:00.0: Completed reset device command.
[  225.968762] xhci_hcd 0000:0c:00.0: Can't reset device (slot ID 5) in default state
[  225.968764] xhci_hcd 0000:0c:00.0: Not freeing device rings.
[  225.968767] xhci_hcd 0000:0c:00.0: // Ding dong!
[  225.969479] xhci_hcd 0000:0c:00.0: Successful setup address command
[  225.969483] xhci_hcd 0000:0c:00.0: Op regs DCBAA ptr = 0x000000fffff000
[  225.969485] xhci_hcd 0000:0c:00.0: Slot ID 5 dcbaa entry @000000003fadcb3f = 0x000000fff5e000
[  225.969488] xhci_hcd 0000:0c:00.0: Output Context DMA address = 0xfff5e000
[  225.969490] xhci_hcd 0000:0c:00.0: Internal device address = 5
[  226.002756] xhci_hcd 0000:0c:00.0: enable port 3 USB2 hardware LPM
[  226.002765] xhci_hcd 0000:0c:00.0: Set up evaluate context for LPM MEL change.
[  226.002769] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.003125] xhci_hcd 0000:0c:00.0: Successful evaluate context command
[  226.015745] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  226.017754] usb 1-3: default language 0x0409
[  226.020737] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  226.025742] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  226.030745] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  226.032754] usb 1-3: udev 6, busnum 1, minor = 5
[  226.032759] usb 1-3: New USB device found, idVendor=0fce, idProduct=0dde, bcdDevice= 1.00
[  226.032761] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  226.032763] usb 1-3: Product: Android
[  226.032765] usb 1-3: Manufacturer: Google
[  226.032766] usb 1-3: SerialNumber: BH905BAH9E
[  226.032972] usb 1-3: usb_probe_device
[  226.032974] usb 1-3: configuration #1 chosen from 1 choice
[  226.032983] xhci_hcd 0000:0c:00.0: add ep 0x81, slot id 5, new drop flags = 0x0, new add flags = 0x8
[  226.032990] xhci_hcd 0000:0c:00.0: add ep 0x1, slot id 5, new drop flags = 0x0, new add flags = 0xc
[  226.032993] xhci_hcd 0000:0c:00.0: xhci_check_bandwidth called for udev 00000000f07964e8
[  226.032996] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.036041] xhci_hcd 0000:0c:00.0: Successful Endpoint Configure command
[  226.036058] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.036142] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 5 ep 2
[  226.036227] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.041132] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.041222] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 5 ep 1
[  226.041311] xhci_hcd 0000:0c:00.0: // Ding dong!
[  226.048744] usb 1-3: adding 1-3:1.0 (config #1, interface 0)
[  226.051745] xhci_hcd 0000:0c:00.0: Waiting for status stage event
[  226.112724] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  229.214292] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  229.358289] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  234.642446] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe63, return 0x507
[  234.642466] xhci_hcd 0000:0c:00.0: clear USB_PORT_FEAT_SUSPEND
[  234.642468] xhci_hcd 0000:0c:00.0: PORTSC 0e63
[  234.642470] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xe63, write 0x10fe1
[  234.688896] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xfe3, write 0x10e01
[  234.688933] usb 1-5: usb auto-resume
[  234.689161] xhci_hcd 0000:0c:00.0: Port change event, 1-5, id 10, portsc: 0x400e03
[  234.689166] xhci_hcd 0000:0c:00.0: handle_port_status: starting usb1 port polling.
[  234.689189] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0020
[  234.690282] xhci_hcd 0000:0c:00.0: underrun event on endpoint
[  234.690285] xhci_hcd 0000:0c:00.0: overrun event on endpoint
[  234.736898] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe03, return 0x40503
[  234.736914] xhci_hcd 0000:0c:00.0: clear port5 suspend/resume change, portsc: 0xe03
[  234.756897] usb 1-5: Waited 0ms for CONNECT
[  234.756901] usb 1-5: finish resume
[  234.761806] xhci_hcd 0000:0c:00.0: Get port status 1-5 read: 0xe03, return 0x503
[  234.762810] xhci_hcd 0000:0c:00.0: ep 0x81 - asked for 256 bytes, 248 bytes untransferred
[  234.792899] xhci_hcd 0000:0c:00.0: xhci_hub_status_data: stopping usb1 port polling
[  236.353577] xhci_hcd 0000:0c:00.0: ep 0x81 - asked for 256 bytes, 237 bytes untransferred
[  238.852825] xhci_hcd 0000:0c:00.0: // Ding dong!
[  238.852917] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 20
[  238.853081] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 19
[  238.853229] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 6
[  238.853388] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 5
[  238.853541] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 4
[  238.853698] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 3
[  238.853854] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 2
[  238.854015] xhci_hcd 0000:0c:00.0: Stopped on No-op or Link TRB for slot 1 ep 0
[  238.854113] xhci_hcd 0000:0c:00.0: Set port 1-5 link state, portsc: 0xe03, write 0x10e61
[  238.872988] usb 1-5: usb auto-suspend, wakeup 0
[  240.855359] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred
[  241.009359] xhci_hcd 0000:0c:00.0: ep 0x82 - asked for 32 bytes, 26 bytes untransferred

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Mathias Nyman]

On 6.1.2025 1.42, Forest wrote:
> On Thu, 2 Jan 2025 16:13:34 +0200, Mathias Nyman wrote:
> 
>> It's not clear to me why this patch would cause regression.
>>
>> Could you enable xhci and usb core dynamic debug before connecting the
>> device, and then share dmesg after the issue is triggered.
>>
>> dmesg of a working case would also be good to have for comparison.
> 
> I booted kernel 9b780c845fb6 (the last good one), logged in to my desktop,
> waited a couple of minutes to let things settle, and then ran 'fastboot
> getvar kernel' twice with the android device in bootloader mode.
> Here's the dmesg output:

Thanks for the logs.
  
Looks like we enable USB2 Link Power Management (LPM) in the failing case
> 
> [  226.002756] xhci_hcd 0000:0c:00.0: enable port 3 USB2 hardware LPM
> [  226.002765] xhci_hcd 0000:0c:00.0: Set up evaluate context for LPM MEL change.

Does disabling USB2 hardware LPM for the device make it work again?

Adding USB_QUIRK_NO_LPM quirk "k" for your device vid:pid should do it.
i.e. add "usbcore.quirks=0fce:0dde:k" parameter to your kernel cmdline.

Or alternatively disable usb2 lpm  during runtime via sysfs
(after enumeration, assuming device is "1-3" as in the log):
# echo 0 > /sys/bus/usb/devices/1-3/power/usb2_hardware_lpm

If those work then we need to figure out if we incorrectly try to enable
USB2 hardware LPM, or if device just can't handle LPM even if it claims
to be LPM capable.

Host hardware LPM capability can be checked from xhci reg-ext-protocol
fields from debugfs.
cat /sys/kernel/debug/usb/xhci/0000:0c:00.0/reg-ext-protocol:*
(please print content of _all_ reg_ext_protocol* files, LPM capability is
bit 19 of EXTCAP_PORTINFO)

Device USB2 LPM capability can be checked from the devices BOS descriptor,
visible (as sudo/root) with lsusb -v -d 0fce:0dde

Thanks
Mathias

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Forest]

On Tue, 7 Jan 2025 14:29:35 +0200, Mathias Nyman wrote:

>Does disabling USB2 hardware LPM for the device make it work again?
>
>Adding USB_QUIRK_NO_LPM quirk "k" for your device vid:pid should do it.
>i.e. add "usbcore.quirks=0fce:0dde:k" parameter to your kernel cmdline.

That fixed my test case on Debian kernel 6.12.8-amd64, which is among those
that have been failing.

>Or alternatively disable usb2 lpm  during runtime via sysfs
>(after enumeration, assuming device is "1-3" as in the log):
># echo 0 > /sys/bus/usb/devices/1-3/power/usb2_hardware_lpm

That did not fix it. Maybe it's too late once the device is connected and
enumerated?

>If those work then we need to figure out if we incorrectly try to enable
>USB2 hardware LPM, or if device just can't handle LPM even if it claims
>to be LPM capable.
>
>Host hardware LPM capability can be checked from xhci reg-ext-protocol
>fields from debugfs.
>cat /sys/kernel/debug/usb/xhci/0000:0c:00.0/reg-ext-protocol:*
>(please print content of _all_ reg_ext_protocol* files, LPM capability is
>bit 19 of EXTCAP_PORTINFO)

# cd /sys/kernel/debug/usb/xhci/0000:0c:00.0/
# grep . reg-ext-protocol:*
reg-ext-protocol:00:EXTCAP_REVISION = 0x03200802
reg-ext-protocol:00:EXTCAP_NAME = 0x20425355
reg-ext-protocol:00:EXTCAP_PORTINFO = 0x40000101
reg-ext-protocol:00:EXTCAP_PORTTYPE = 0x00000000
reg-ext-protocol:00:EXTCAP_MANTISSA1 = 0x00050134
reg-ext-protocol:00:EXTCAP_MANTISSA2 = 0x000a4135
reg-ext-protocol:00:EXTCAP_MANTISSA3 = 0x000a4136
reg-ext-protocol:00:EXTCAP_MANTISSA4 = 0x00144137
reg-ext-protocol:01:EXTCAP_REVISION = 0x03100802
reg-ext-protocol:01:EXTCAP_NAME = 0x20425355
reg-ext-protocol:01:EXTCAP_PORTINFO = 0x20000402
reg-ext-protocol:01:EXTCAP_PORTTYPE = 0x00000000
reg-ext-protocol:01:EXTCAP_MANTISSA1 = 0x00050134
reg-ext-protocol:01:EXTCAP_MANTISSA2 = 0x000a4135
reg-ext-protocol:02:EXTCAP_REVISION = 0x02000802
reg-ext-protocol:02:EXTCAP_NAME = 0x20425355
reg-ext-protocol:02:EXTCAP_PORTINFO = 0x00190c06
reg-ext-protocol:02:EXTCAP_PORTTYPE = 0x00000000

# grep EXTCAP_PORTINFO reg-ext-protocol:*
reg-ext-protocol:00:EXTCAP_PORTINFO = 0x40000101
reg-ext-protocol:01:EXTCAP_PORTINFO = 0x20000402
reg-ext-protocol:02:EXTCAP_PORTINFO = 0x00190c06

>>> bool(0x40000101 & 1 << 19)
False
>>> bool(0x20000402 & 1 << 19)
False
>>> bool(0x00190c06 & 1 << 19)
True

>Device USB2 LPM capability can be checked from the devices BOS descriptor,
>visible (as sudo/root) with lsusb -v -d 0fce:0dde

# lsusb -v -d 0fce:0dde |grep -B 5 LPM
  USB 2.0 Extension Device Capability:
    bLength                 7
    bDescriptorType        16
    bDevCapabilityType      2
    bmAttributes   0x00000006
      BESL Link Power Management (LPM) Supported

I think that says the device claims support for LPM, yes?

Maybe relevant: The failing test and lsusb were both run with the device in
fastboot mode, which allows talking to the bootloader. Is it possible that a
device would support LPM in normal operating modes, but not in bootloader
mode, yet present the same capabilities data structure in both modes?

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Mathias Nyman]

On 11.1.2025 2.00, Forest wrote:
> On Tue, 7 Jan 2025 14:29:35 +0200, Mathias Nyman wrote:
> 
>> Does disabling USB2 hardware LPM for the device make it work again?
>>
>> Adding USB_QUIRK_NO_LPM quirk "k" for your device vid:pid should do it.
>> i.e. add "usbcore.quirks=0fce:0dde:k" parameter to your kernel cmdline.
> 
> That fixed my test case on Debian kernel 6.12.8-amd64, which is among those
> that have been failing.
> 
> # grep EXTCAP_PORTINFO reg-ext-protocol:*
> reg-ext-protocol:00:EXTCAP_PORTINFO = 0x40000101
> reg-ext-protocol:01:EXTCAP_PORTINFO = 0x20000402
> reg-ext-protocol:02:EXTCAP_PORTINFO = 0x00190c06
> 
>>>> bool(0x40000101 & 1 << 19)
> False
>>>> bool(0x20000402 & 1 << 19)
> False
>>>> bool(0x00190c06 & 1 << 19)
> True
> 
>> Device USB2 LPM capability can be checked from the devices BOS descriptor,
>> visible (as sudo/root) with lsusb -v -d 0fce:0dde
> 
> # lsusb -v -d 0fce:0dde |grep -B 5 LPM
>    USB 2.0 Extension Device Capability:
>      bLength                 7
>      bDescriptorType        16
>      bDevCapabilityType      2
>      bmAttributes   0x00000006
>        BESL Link Power Management (LPM) Supported
> 
> I think that says the device claims support for LPM, yes?

Yes. Looks like both the device and host support USB2 LPM

I think I see what is going on.

Before commit 63a1f8454962a64746a59441687 the xhci driver apparently failed
to detect xHC USB2 LPM support if USB 3 ports were listed before USB 2 ports
in the "supported protocol capabilities.

Now that we correctly detect LPM support and enable it, it turns out the
device does not work well with USB 2 LPM enabled.

I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
Let me know if you want to submit it yourself, otherwise I can do it.

Thanks
Mathias

Additional debugging details:

We incorrectly compared usb device port numbers with xHC hardware port
numbers when checking for USB2 port capabilities.

xHC hardware has one long array of ports, including all USB 2 and USB 3 ports.
In your case host lists three sets of supported protocol capabilities:

One USB 3.2 port as the fist port at offset 1:
   reg-ext-protocol:00:EXTCAP_REVISION = 0x03200802
   reg-ext-protocol:00:EXTCAP_PORTINFO = 0x40000101

Four USB 3.1 ports starting at offset 2
   reg-ext-protocol:01:EXTCAP_REVISION = 0x03100802
   reg-ext-protocol:01:EXTCAP_PORTINFO = 0x20000402

Ten USB 2.0 ports stating at offset 6, supporting LPM
   reg-ext-protocol:02:EXTCAP_REVISION = 0x02000802
   reg-ext-protocol:02:EXTCAP_PORTINFO = 0x00190c06

Most xHC hosts used to list their USB 2.0 ports first, meaning there
was no offset difference between usb device port number and xHC port
number for USB 2.0 ports.

Usb device port numbers start from 1 on that hub, in your case it was "3"

xhci driver then checked that usb device with port number "3" does not match
the LPM supported USB 2 port range from 6 to 16 (10 LPM capabale USB 2
ports starting at offset 6).

-Mathias

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Forest]

On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:

>I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
>Let me know if you want to submit it yourself, otherwise I can do it.

Thank you.

I have prepared a patch against 6.13-rc7. This regression also affects the
stable branch, but I don't know the patch policy for stable. To which lists
should I send the patch?

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Greg KH]

On Tue, Jan 14, 2025 at 05:38:54PM -0800, Forest wrote:
> On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:
> 
> >I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
> >Let me know if you want to submit it yourself, otherwise I can do it.
> 
> Thank you.
> 
> I have prepared a patch against 6.13-rc7. This regression also affects the
> stable branch, but I don't know the patch policy for stable. To which lists
> should I send the patch?

Please read:
    https://www.kernel.org/doc/html/latest/process/stable-kernel-rules.html
for how to do this properly.

(hint, get it into Linus's tree first before worrying about stable
backports.)

thanks,

greg k-h

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Forest]

On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:

>I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
>Let me know if you want to submit it yourself, otherwise I can do it.

It looks like I can't contribute a patch after all, due to an issue with my
Signed-off-by signature.

So, can you take care of the quirk patch for this device?

Thank you.

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Mathias Nyman]

On 24.1.2025 21.44, Forest wrote:
> On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:
> 
>> I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
>> Let me know if you want to submit it yourself, otherwise I can do it.
> 
> It looks like I can't contribute a patch after all, due to an issue with my
> Signed-off-by signature.
> 
> So, can you take care of the quirk patch for this device?
> 
> Thank you.

Sure, I'll send it after rc1 is out next week

Thanks
Mathias

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Salvatore Bonaccorso]

Hi Mathias,

On Wed, Jan 29, 2025 at 01:01:58PM +0200, Mathias Nyman wrote:
> On 24.1.2025 21.44, Forest wrote:
> > On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:
> > 
> > > I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
> > > Let me know if you want to submit it yourself, otherwise I can do it.
> > 
> > It looks like I can't contribute a patch after all, due to an issue with my
> > Signed-off-by signature.
> > 
> > So, can you take care of the quirk patch for this device?
> > 
> > Thank you.
> 
> Sure, I'll send it after rc1 is out next week

Not something superurgent, but wanted to ask is that still on your
radaar? I stumpled over it while looking at the current open bugs
reported in Debian, reminding me of https://bugs.debian.org/1091517

Thanks for your work!

Regards,
Salvatore

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Mathias Nyman]

On 13.2.2025 22.24, Salvatore Bonaccorso wrote:
> Hi Mathias,
> 
> On Wed, Jan 29, 2025 at 01:01:58PM +0200, Mathias Nyman wrote:
>> On 24.1.2025 21.44, Forest wrote:
>>> On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:
>>>
>>>> I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
>>>> Let me know if you want to submit it yourself, otherwise I can do it.
>>>
>>> It looks like I can't contribute a patch after all, due to an issue with my
>>> Signed-off-by signature.
>>>
>>> So, can you take care of the quirk patch for this device?
>>>
>>> Thank you.
>>
>> Sure, I'll send it after rc1 is out next week
> 
> Not something superurgent, but wanted to ask is that still on your
> radaar? I stumpled over it while looking at the current open bugs
> reported in Debian, reminding me of https://bugs.debian.org/1091517

Yes, patch was here:
https://lore.kernel.org/linux-usb/20250206151836.51742-1-mathias.nyman@linux.intel.com/

Greg applied it to his tree today:
https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git/commit/?h=usb-linus&id=159daf1258227f44b26b5d38f4aa8f37b8cca663

Thanks
Mathias

Re: [REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility

[Salvatore Bonaccorso]

Hi,

On Fri, Feb 14, 2025 at 02:29:29PM +0200, Mathias Nyman wrote:
> On 13.2.2025 22.24, Salvatore Bonaccorso wrote:
> > Hi Mathias,
> > 
> > On Wed, Jan 29, 2025 at 01:01:58PM +0200, Mathias Nyman wrote:
> > > On 24.1.2025 21.44, Forest wrote:
> > > > On Mon, 13 Jan 2025 17:05:09 +0200, Mathias Nyman wrote:
> > > > 
> > > > > I'd recommend a patch that permanently adds USB_QUIRK_NO_LPM for this device.
> > > > > Let me know if you want to submit it yourself, otherwise I can do it.
> > > > 
> > > > It looks like I can't contribute a patch after all, due to an issue with my
> > > > Signed-off-by signature.
> > > > 
> > > > So, can you take care of the quirk patch for this device?
> > > > 
> > > > Thank you.
> > > 
> > > Sure, I'll send it after rc1 is out next week
> > 
> > Not something superurgent, but wanted to ask is that still on your
> > radaar? I stumpled over it while looking at the current open bugs
> > reported in Debian, reminding me of https://bugs.debian.org/1091517
> 
> Yes, patch was here:
> https://lore.kernel.org/linux-usb/20250206151836.51742-1-mathias.nyman@linux.intel.com/
> 
> Greg applied it to his tree today:
> https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git/commit/?h=usb-linus&id=159daf1258227f44b26b5d38f4aa8f37b8cca663

Thank you Matthias.

Regards,
Salvatore