[REGRESSION] usb: xhci port capability storage change broke fastboot android bootloader utility
#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
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
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
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
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?
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
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?
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
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.
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
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
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...
Greg applied it to his tree today: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git/commit/?h=usb...
Thanks Mathias
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...
Greg applied it to his tree today: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git/commit/?h=usb...
Thank you Matthias.
Regards, Salvatore
linux-stable-mirror@lists.linaro.org
-
Forest -
Greg KH -
Mathias Nyman -
Salvatore Bonaccorso