Userspace enumeration hang while btusb tries to load firmware of removed device

Userspace enumeration hang while btusb tries to load firmware of removed device

[Benjamin Berg]

[-- Attachment #1.1: Type: text/plain, Size: 5143 bytes --]

Hi,

a user is seeing a hang in fprintd while enumerating devices which
appears to be caused by an interaction of:

* system is resuming from S3
* btusb starts loading firmware
* bluetooth device disappears (probably thinkpad_acpi rfkill)
* libusb enumerates USB devices (fprintd in this case)

When this happens, the firmware load fails after a timeout of 10s. It
appears that if userspace queries information about the root hub in
question during this time, it will hang until the btusb firmware load
has timed out.

Attaching the full kernel log, below an excerpt, you can see:
 * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
 * libusb enumeration retrieves information about the usb5 root hub,
   and blocks on this
 * At :14 there is a tx timeout on hci0
 * At :23 the firmware load finally fails
 * Then usb_disable_device happens
 * libusb/fprintd gets the usb5 HUB information and continues its
   enumeration

As I see it, there may be two issues:
1. userspace should not block due to the firmware load hanging
2. btusb should give up more quickly when the device disappears

Does anyone have a good idea about the possible cause or how we can fix
the problem?

Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857

Benjamin

[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: enable port 4 USB2 hardware LPM
...
[Mi Nov 3 11:55:12 2021] usb 5-4: udev 33, busnum 5, minor = 544
[Mi Nov 3 11:55:12 2021] usb 5-4: New USB device found, idVendor=8087, idProduct=0032, bcdDevice= 0.00
[Mi Nov 3 11:55:12 2021] usb 5-4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[Mi Nov 3 11:55:12 2021] usb 5-4: usb_probe_device
[Mi Nov 3 11:55:12 2021] usb 5-4: configuration #1 chosen from 1 choice
...
[Mi Nov 3 11:55:12 2021] usb 5-4: adding 5-4:1.0 (config #1, interface 0)
[Mi Nov 3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface
[Mi Nov 3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface - got id
[Mi Nov 3 11:55:12 2021] usb 5-4: adding 5-4:1.1 (config #1, interface 1)
[Mi Nov 3 11:55:12 2021] Generic FE-GE Realtek PHY r8169-0-200:00: attached PHY driver (mii_bus:phy_addr=r8169-0-200:00, irq=MAC)
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 64 bytes, 32 bytes untransferred
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Device revision is 0
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Secure boot is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: OTP lock is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: API lock is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Debug lock is disabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Bootloader timestamp 2019.40 buildtype 1 build 38
[Mi Nov 3 11:55:12 2021] psmouse serio1: synaptics: queried max coordinates: x [..5678], y [..4694]
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Found device firmware: intel/ibt-0041-0041.sfi
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
...
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x202a0
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
...
[Mi Nov 3 11:55:12 2021] usb 5-4: USB disconnect, device number 33
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
...
[Mi Nov 3 11:55:12 2021] usb 5-4: unregistering device
[Mi Nov 3 11:55:12 2021] usb 5-4: unregistering interface 5-4:1.0
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
...
[Mi Nov 3 11:55:14 2021] Bluetooth: hci0: command 0xfc09 tx timeout
...
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Intel reset sent to retry FW download
[Mi Nov 3 11:55:23 2021] usb 5-4: unregistering interface 5-4:1.1
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: disable port 4 USB2 hardware LPM
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: Set up evaluate context for LPM MEL change.
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: Successful evaluate context command
[Mi Nov 3 11:55:23 2021] usb 5-4: usb_disable_device nuking all URBs


[-- Attachment #1.2: resume-log.txt --]
[-- Type: text/plain, Size: 116085 bytes --]

[Mi Nov  3 11:55:09 2021] wlp3s0: deauthenticating from 50:60:28:5a:84:51 by local choice (Reason: 3=DEAUTH_LEAVING)
[Mi Nov  3 11:55:10 2021] PM: suspend entry (deep)
[Mi Nov  3 11:55:10 2021] Filesystems sync: 0.120 seconds
[Mi Nov  3 11:55:10 2021] Freezing user space processes ... (elapsed 0.003 seconds) done.
[Mi Nov  3 11:55:10 2021] OOM killer disabled.
[Mi Nov  3 11:55:10 2021] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[Mi Nov  3 11:55:10 2021] printk: Suspending console(s) (use no_console_suspend to debug)
[Mi Nov  3 11:55:10 2021] ehci-pci 0000:02:00.4: hcd_pci_runtime_resume: 0
[Mi Nov  3 11:55:10 2021] usb usb7: usb auto-resume
[Mi Nov  3 11:55:10 2021] ehci-pci 0000:02:00.4: resume root hub
[Mi Nov  3 11:55:10 2021] hub 7-0:1.0: hub_resume
[Mi Nov  3 11:55:10 2021] hub 7-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] usb usb7: bus suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] ehci-pci 0000:02:00.4: suspend root hub
[Mi Nov  3 11:55:10 2021] usb 3-3: usb suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Cancel URB 000000005aea3525, dev 3, ep 0x81, starting at offset 0x10cd3c6d0
[Mi Nov  3 11:55:10 2021] usb 5-3: usb suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: // Ding dong!
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: shutdown urb 000000005aea3525 ep1in-intr
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Stopped on Transfer TRB for slot 1 ep 2
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Removing canceled TD starting at 0x10cd3c6d0 (dma).
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Set TR Deq ptr 0x10cd3c6e0, cycle 1

[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: // Ding dong!
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Successful Set TR Deq Ptr cmd, deq = @10cd3c6e0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Giveback URB 000000005aea3525, len = 0, expected = 8, status = -115
[Mi Nov  3 11:55:10 2021] usb usb6: usb auto-resume
[Mi Nov  3 11:55:10 2021] hub 5-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] hub 6-0:1.0: hub_resume
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Get port status 6-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] usb usb5: bus suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: port 5-3 not suspended
[Mi Nov  3 11:55:10 2021] usb usb4: usb auto-resume
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Get port status 6-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] hub 3-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] hub 4-0:1.0: hub_resume
[Mi Nov  3 11:55:10 2021] hub 6-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Get port status 4-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Get port status 4-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 1 ep 6
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 1 ep 2
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 1 ep 1
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 1 ep 0
[Mi Nov  3 11:55:10 2021] hub 4-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] usb usb6: bus suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] usb usb4: bus suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] usb usb3: bus suspend, wakeup 0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: port 3-3 not suspended
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: // Ding dong!
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Stopped on No-op or Link TRB for slot 1 ep 6
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Stopped on No-op or Link TRB for slot 1 ep 3
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: Stopped on No-op or Link TRB for slot 1 ep 0
[Mi Nov  3 11:55:10 2021] usb usb1: root hub lost power or was reset
[Mi Nov  3 11:55:10 2021] usb usb2: root hub lost power or was reset
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Stop HCD
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Halt the HC
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Zeroing 64bit base registers, expecting fault
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: config port 6-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: config port 6-2 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: config port 5-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: config port 5-2 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: config port 4-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: config port 5-4 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: config port 4-2 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: xhci_suspend: stopping port polling.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: config port 3-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: config port 3-2 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: config port 3-4 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: xhci_suspend: stopping port polling.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.4: // Setting command ring address to 0x109d27001
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:07:00.3: // Setting command ring address to 0x100e55001
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Reset the HC
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Wait for controller to be ready for doorbell rings
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Disabling event ring interrupts
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: cleaning up memory
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed event ring
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed command ring
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed segment pool
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed device context pool
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed small stream array pool
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Freed medium stream array pool
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xhci_stop completed - status = 1
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Initialize the xhci_hcd
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xhci_init
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xHCI doesn't need link TRB QUIRK
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Supported page size register = 0x1
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Supported page size of 4K
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: HCD page size set to 4K
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // xHC can handle at most 32 device slots.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Setting Max device slots reg = 0x20.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Device context base array address = 0xfff98000 (DMA), 000000004997560d (virt)
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Allocated command ring at 00000000e8a08e52
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: First segment DMA is 0xfff99000
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Setting command ring address to 0x00000000fff99001
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Doorbell array is located at offset 0x800 from cap regs base addr
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Allocating event ring
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: TRB math tests passed.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Write ERST size = 1 to ir_set 0 (some bits preserved)
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Set ERST entries to point to event ring.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Set ERST base address for ir_set 0 = 0xfff97000
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Write event ring dequeue pointer, preserving EHB bit
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Wrote ERST address to ir_set 0.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Allocating 4 scratchpad buffers
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Ext Cap 00000000d74195d7, port offset = 1, count = 2, revision = 0x3
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Ext Cap 000000006773d3b5, port offset = 3, count = 2, revision = 0x2
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Found 2 USB 2.0 ports and 2 USB 3.0 ports.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Finished xhci_init
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Start the primary HCD
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xhci_run
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: ERST deq = 64'hffe41000
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Set the interrupt modulation register
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Enable interrupts, cmd = 0x4.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Enabling event ring interrupter 00000000f5985faa by writing 0x2 to irq_pending
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Finished xhci_run for USB2 roothub
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Start the secondary HCD
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: // Turn on HC, cmd = 0x5.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Finished xhci_run for USB3 roothub
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Port change event, 1-2, id 4, portsc: 0x202e1
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: resume root hub
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: handle_port_status: starting port polling.
[Mi Nov  3 11:55:10 2021] [drm] free PSP TMR buffer
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xhci_resume: starting port polling.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: hcd_pci_runtime_resume: 0
[Mi Nov  3 11:55:10 2021] usb usb2: usb auto-resume
[Mi Nov  3 11:55:10 2021] hub 2-0:1.0: hub_reset_resume
[Mi Nov  3 11:55:10 2021] hub 2-0:1.0: enabling power on all ports
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: set port power 2-1 ON, portsc: 0x2a0
[Mi Nov  3 11:55:10 2021] usb usb1: usb auto-resume
[Mi Nov  3 11:55:10 2021] hub 1-0:1.0: hub_reset_resume
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: set port power 2-2 ON, portsc: 0x2a0
[Mi Nov  3 11:55:10 2021] hub 1-0:1.0: enabling power on all ports
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: set port power 1-1 ON, portsc: 0x2a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: set port power 1-2 ON, portsc: 0x202e1
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Get port status 2-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Get port status 1-1 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Get port status 2-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: Get port status 1-2 read: 0x202e1, return 0x10101
[Mi Nov  3 11:55:10 2021] usb usb1-port2: status 0101 change 0001
[Mi Nov  3 11:55:10 2021] hub 2-0:1.0: hub_suspend
[Mi Nov  3 11:55:10 2021] xhci_hcd 0000:06:00.0: clear port2 connect change, portsc: 0x2e1
[Mi Nov  3 11:55:10 2021] usb usb2: bus suspend, wakeup 0
[Mi Nov  3 11:55:11 2021] hub 1-0:1.0: hub_suspend
[Mi Nov  3 11:55:11 2021] usb usb1: bus suspend, wakeup 0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: config port 2-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: config port 2-2 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: config port 1-1 wake bits, portsc: 0x2a0, write: 0x202a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_suspend: stopping port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Setting command ring address to 0xfff99001
[Mi Nov  3 11:55:11 2021] PM: suspend devices took 0.773 seconds
[Mi Nov  3 11:55:11 2021] ehci-pci 0000:02:00.4: wakeup: 1
[Mi Nov  3 11:55:11 2021] ACPI: EC: interrupt blocked
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: wakeup: 1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: wakeup: 1
[Mi Nov  3 11:55:11 2021] ehci-pci 0000:02:00.4: --> PCI D3hot
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: --> PCI D3hot
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: --> PCI D3hot
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: wakeup: 1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: --> PCI D3hot
[Mi Nov  3 11:55:11 2021] ACPI: PM: Preparing to enter system sleep state S3
[Mi Nov  3 11:55:11 2021] ACPI: EC: event blocked
[Mi Nov  3 11:55:11 2021] ACPI: EC: EC stopped
[Mi Nov  3 11:55:11 2021] ACPI: PM: Saving platform NVS memory
[Mi Nov  3 11:55:11 2021] Disabling non-boot CPUs ...
[Mi Nov  3 11:55:11 2021] smpboot: CPU 1 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 2 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 3 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 4 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 5 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 6 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 7 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 8 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 9 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 10 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 11 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 12 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 13 is now offline
[Mi Nov  3 11:55:11 2021] smpboot: CPU 14 is now offline
[Mi Nov  3 11:55:11 2021] Spectre V2 : Update user space SMT mitigation: STIBP off
[Mi Nov  3 11:55:11 2021] smpboot: CPU 15 is now offline
[Mi Nov  3 11:55:11 2021] ACPI: PM: Low-level resume complete
[Mi Nov  3 11:55:11 2021] ACPI: EC: EC started
[Mi Nov  3 11:55:11 2021] ACPI: PM: Restoring platform NVS memory
[Mi Nov  3 11:55:11 2021] LVT offset 0 assigned for vector 0x400
[Mi Nov  3 11:55:11 2021] Enabling non-boot CPUs ...
[Mi Nov  3 11:55:11 2021] x86: Booting SMP configuration:
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 1 APIC 0x1
[Mi Nov  3 11:55:11 2021] microcode: CPU1: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C001: Found 3 idle states
[Mi Nov  3 11:55:11 2021] Spectre V2 : Update user space SMT mitigation: STIBP always-on
[Mi Nov  3 11:55:11 2021] CPU1 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 2 APIC 0x2
[Mi Nov  3 11:55:11 2021] microcode: CPU2: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C002: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU2 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 3 APIC 0x3
[Mi Nov  3 11:55:11 2021] microcode: CPU3: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C003: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU3 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 4 APIC 0x4
[Mi Nov  3 11:55:11 2021] microcode: CPU4: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C004: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU4 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 5 APIC 0x5
[Mi Nov  3 11:55:11 2021] microcode: CPU5: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C005: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU5 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 6 APIC 0x6
[Mi Nov  3 11:55:11 2021] microcode: CPU6: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C006: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU6 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 7 APIC 0x7
[Mi Nov  3 11:55:11 2021] microcode: CPU7: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C007: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU7 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 8 APIC 0x8
[Mi Nov  3 11:55:11 2021] microcode: CPU8: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C008: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU8 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 9 APIC 0x9
[Mi Nov  3 11:55:11 2021] microcode: CPU9: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C009: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU9 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 10 APIC 0xa
[Mi Nov  3 11:55:11 2021] microcode: CPU10: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00A: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU10 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 11 APIC 0xb
[Mi Nov  3 11:55:11 2021] microcode: CPU11: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00B: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU11 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 12 APIC 0xc
[Mi Nov  3 11:55:11 2021] microcode: CPU12: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00C: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU12 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 13 APIC 0xd
[Mi Nov  3 11:55:11 2021] microcode: CPU13: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00D: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU13 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 14 APIC 0xe
[Mi Nov  3 11:55:11 2021] microcode: CPU14: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00E: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU14 is up
[Mi Nov  3 11:55:11 2021] smpboot: Booting Node 0 Processor 15 APIC 0xf
[Mi Nov  3 11:55:11 2021] microcode: CPU15: patch_level=0x0a50000c
[Mi Nov  3 11:55:11 2021] ACPI: \_SB_.PLTF.C00F: Found 3 idle states
[Mi Nov  3 11:55:11 2021] CPU15 is up
[Mi Nov  3 11:55:11 2021] ACPI: PM: Waking up from system sleep state S3
[Mi Nov  3 11:55:11 2021] ACPI: EC: interrupt unblocked
[Mi Nov  3 11:55:11 2021] ACPI: EC: event unblocked
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: // Setting command ring address to 0x100e55001
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: // Setting command ring address to 0x109d27001
[Mi Nov  3 11:55:11 2021] usb usb1: root hub lost power or was reset
[Mi Nov  3 11:55:11 2021] usb usb2: root hub lost power or was reset
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Stop HCD
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Halt the HC
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Zeroing 64bit base registers, expecting fault
[Mi Nov  3 11:55:11 2021] [drm] PCIE GART of 1024M enabled.
[Mi Nov  3 11:55:11 2021] [drm] PTB located at 0x000000F400900000
[Mi Nov  3 11:55:11 2021] [drm] PSP is resuming...
[Mi Nov  3 11:55:11 2021] usb usb7: root hub lost power or was reset
[Mi Nov  3 11:55:11 2021] ehci-pci 0000:02:00.4: reset command 0000002 (park)=0 ithresh=0 period=1024 Reset HALT
[Mi Nov  3 11:55:11 2021] ehci-pci 0000:02:00.4: MWI active
[Mi Nov  3 11:55:11 2021] usb usb7: usb resume
[Mi Nov  3 11:55:11 2021] ehci-pci 0000:02:00.4: resume root hub after power loss
[Mi Nov  3 11:55:11 2021] hub 7-0:1.0: hub_reset_resume
[Mi Nov  3 11:55:11 2021] hub 7-0:1.0: trying to enable port power on non-switchable hub
[Mi Nov  3 11:55:11 2021] [drm] reserve 0x400000 from 0xf4ff800000 for PSP TMR
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Reset the HC
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Wait for controller to be ready for doorbell rings
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Disabling event ring interrupts
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: cleaning up memory
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed event ring
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed command ring
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed segment pool
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed device context pool
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed small stream array pool
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Freed medium stream array pool
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_stop completed - status = 1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Initialize the xhci_hcd
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_init
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xHCI doesn't need link TRB QUIRK
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Supported page size register = 0x1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Supported page size of 4K
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: HCD page size set to 4K
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // xHC can handle at most 32 device slots.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Setting Max device slots reg = 0x20.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Device context base array address = 0xfffee000 (DMA), 000000009de03bc0 (virt)
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Allocated command ring at 00000000ca9bd29f
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: First segment DMA is 0xfff9a000
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Setting command ring address to 0x00000000fff9a001
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Doorbell array is located at offset 0x800 from cap regs base addr
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Allocating event ring
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: TRB math tests passed.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Write ERST size = 1 to ir_set 0 (some bits preserved)
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Set ERST entries to point to event ring.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Set ERST base address for ir_set 0 = 0xfff9f000
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Write event ring dequeue pointer, preserving EHB bit
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Wrote ERST address to ir_set 0.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Allocating 4 scratchpad buffers
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Ext Cap 00000000d74195d7, port offset = 1, count = 2, revision = 0x3
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Ext Cap 000000006773d3b5, port offset = 3, count = 2, revision = 0x2
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Found 2 USB 2.0 ports and 2 USB 3.0 ports.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Finished xhci_init
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Start the primary HCD
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_run
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: ERST deq = 64'hfff9e000
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Set the interrupt modulation register
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Enable interrupts, cmd = 0x4.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Enabling event ring interrupter 00000000f5985faa by writing 0x2 to irq_pending
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Finished xhci_run for USB2 roothub
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Start the secondary HCD
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: // Turn on HC, cmd = 0x5.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Finished xhci_run for USB3 roothub
[Mi Nov  3 11:55:11 2021] nvme nvme0: Shutdown timeout set to 8 seconds
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Port change event, 1-2, id 4, portsc: 0x202e1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: resume root hub
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: handle_port_status: starting port polling.
[Mi Nov  3 11:55:11 2021] nvme nvme0: 16/0/0 default/read/poll queues
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: RAS: optional ras ta ucode is not available
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: xhci_resume: starting port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: xhci_resume: starting port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] usb usb4: usb resume
[Mi Nov  3 11:55:11 2021] usb usb5: usb resume
[Mi Nov  3 11:55:11 2021] hub 4-0:1.0: hub_resume
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 4-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 4-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] usb usb6: usb resume
[Mi Nov  3 11:55:11 2021] usb usb3: usb resume
[Mi Nov  3 11:55:11 2021] hub 6-0:1.0: hub_resume
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 6-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 6-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: RAP: optional rap ta ucode is not available
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: SECUREDISPLAY: securedisplay ta ucode is not available
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: SMU is resuming...
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: dpm has been disabled
[Mi Nov  3 11:55:11 2021] amdgpu 0000:07:00.0: amdgpu: SMU is resumed successfully!
[Mi Nov  3 11:55:11 2021] [drm] kiq ring mec 2 pipe 1 q 0
[Mi Nov  3 11:55:11 2021] [drm] DMUB hardware initialized: version=0x01010019
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dsc_pg_control line:363
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x206e1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dsc_pg_control line:371
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dsc_pg_control line:379
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_resume: starting port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] usb usb1: usb resume
[Mi Nov  3 11:55:11 2021] usb usb2: usb resume
[Mi Nov  3 11:55:11 2021] hub 1-0:1.0: hub_reset_resume
[Mi Nov  3 11:55:11 2021] hub 1-0:1.0: enabling power on all ports
[Mi Nov  3 11:55:11 2021] hub 2-0:1.0: hub_reset_resume
[Mi Nov  3 11:55:11 2021] hub 2-0:1.0: enabling power on all ports
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: set port power 1-1 ON, portsc: 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: set port power 2-1 ON, portsc: 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: set port power 1-2 ON, portsc: 0x202e1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: set port power 2-2 ON, portsc: 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Set port 3-3 link state, portsc: 0x7e3, write 0x10601
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Set port 5-3 link state, portsc: 0x7e3, write 0x10601
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Port change event, 3-3, id 3, portsc: 0x603
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: handle_port_status: starting port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Port change event, 5-3, id 3, portsc: 0x603
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov  3 11:55:11 2021] hub 5-0:1.0: hub_resume
[Mi Nov  3 11:55:11 2021] hub 3-0:1.0: hub_resume
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 5-1 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 3-1 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 5-2 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 5-3 read: 0x603, return 0x103
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 3-2 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] usb usb5-port3: status 0103 change 0000
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x206e1, return 0x10101
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 3-3 read: 0x603, return 0x103
[Mi Nov  3 11:55:11 2021] usb usb5-port4: status 0101 change 0001
[Mi Nov  3 11:55:11 2021] usb usb3-port3: status 0103 change 0000
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.4: clear port4 connect change, portsc: 0x6e1
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 3-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:07:00.3: Get port status 3-3 read: 0x603, return 0x103
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Get port status 1-1 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Get port status 2-1 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Get port status 1-2 read: 0x202e1, return 0x10101
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: Get port status 2-2 read: 0x2a0, return 0x2a0
[Mi Nov  3 11:55:11 2021] usb usb1-port2: status 0101 change 0001
[Mi Nov  3 11:55:11 2021] xhci_hcd 0000:06:00.0: clear port2 connect change, portsc: 0x2e1
[Mi Nov  3 11:55:11 2021] usb 3-3: Waited 0ms for CONNECT
[Mi Nov  3 11:55:11 2021] usb 3-3: finish resume
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dpp_pg_control line:434
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_hubp_pg_control line:508
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dpp_pg_control line:442
[Mi Nov  3 11:55:11 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_hubp_pg_control line:516
[Mi Nov  3 11:55:12 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dpp_pg_control line:450
[Mi Nov  3 11:55:12 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_hubp_pg_control line:524
[Mi Nov  3 11:55:12 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_dpp_pg_control line:458
[Mi Nov  3 11:55:12 2021] [drm] REG_WAIT timeout 1us * 1000 tries - dcn20_hubp_pg_control line:532
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Get port status 5-3 read: 0x603, return 0x103
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Get port status 1-2 read: 0x2e1, return 0x101
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] usb 5-3: Waited 0ms for CONNECT
[Mi Nov  3 11:55:12 2021] usb 5-3: finish resume
[Mi Nov  3 11:55:12 2021] [drm] VCN decode and encode initialized successfully(under DPG Mode).
[Mi Nov  3 11:55:12 2021] [drm] JPEG decode initialized successfully.
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring gfx uses VM inv eng 0 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.0.0 uses VM inv eng 1 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.1.0 uses VM inv eng 4 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.2.0 uses VM inv eng 5 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.3.0 uses VM inv eng 6 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.0.1 uses VM inv eng 7 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.1.1 uses VM inv eng 8 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.2.1 uses VM inv eng 9 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring comp_1.3.1 uses VM inv eng 10 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring kiq_2.1.0 uses VM inv eng 11 on hub 0
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring sdma0 uses VM inv eng 0 on hub 1
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring vcn_dec uses VM inv eng 1 on hub 1
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring vcn_enc0 uses VM inv eng 4 on hub 1
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring vcn_enc1 uses VM inv eng 5 on hub 1
[Mi Nov  3 11:55:12 2021] amdgpu 0000:07:00.0: amdgpu: ring jpeg_dec uses VM inv eng 6 on hub 1
[Mi Nov  3 11:55:12 2021] usb 1-2: Waited 0ms for CONNECT
[Mi Nov  3 11:55:12 2021] usb 1-2: finish reset-resume
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: set port reset, actual port 1-2 status  = 0x331
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Port change event, 1-2, id 4, portsc: 0x200e03
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: handle_port_status: starting port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Get port status 1-2 read: 0x200e03, return 0x100503
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: clear port2 reset change, portsc: 0xe03
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: The device to be reset with slot ID 0 does not exist. Re-allocate the device
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Slot 1 output ctx = 0xfffff000 (dma)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Slot 1 input ctx = 0xffffe000 (dma)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Set slot id 1 dcbaa entry 00000000fa4cb34a to 0xfffff000
[Mi Nov  3 11:55:12 2021] usb 1-2: reset high-speed USB device number 2 using xhci_hcd
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Set root hub portnum to 4
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Set fake root hub portnum to 2
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: udev->tt = 0000000000000000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: udev->ttport = 0x0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Successful setup context command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Op regs DCBAA ptr = 0x000000fffee000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Slot ID 1 dcbaa entry @00000000fa4cb34a = 0x000000fffff000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Output Context DMA address = 0xfffff000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Internal device address = 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Waiting for status stage event
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: set port reset, actual port 1-2 status  = 0x331
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Port change event, 1-2, id 4, portsc: 0x200e03
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: handle_port_status: starting port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Get port status 1-2 read: 0x200e03, return 0x100503
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: clear port2 reset change, portsc: 0xe03
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Resetting device with slot ID 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Completed reset device command.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Can't reset device (slot ID 1) in default state
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Not freeing device rings.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Successful setup address command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Op regs DCBAA ptr = 0x000000fffee000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Slot ID 1 dcbaa entry @00000000fa4cb34a = 0x000000fffff000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Output Context DMA address = 0xfffff000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Internal device address = 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Waiting for status stage event
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_drop_endpoint called for udev 000000007b30bfe0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_drop_endpoint called for udev 000000007b30bfe0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: add ep 0x83, slot id 1, new drop flags = 0x0, new add flags = 0x80
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: add ep 0x85, slot id 1, new drop flags = 0x0, new add flags = 0x880
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_check_bandwidth called for udev 000000007b30bfe0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: Successful Endpoint Configure command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_check_bandwidth called for udev 000000007b30bfe0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_check_bandwidth called for udev 000000007b30bfe0
[Mi Nov  3 11:55:12 2021] PM: resume devices took 0.589 seconds
[Mi Nov  3 11:55:12 2021] OOM killer enabled.
[Mi Nov  3 11:55:12 2021] Restarting tasks ... 
[Mi Nov  3 11:55:12 2021] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] hub 7-0:1.0: state 7 ports 1 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] hub 5-0:1.0: state 7 ports 4 chg 0010 evt 0000
[Mi Nov  3 11:55:12 2021] hub 6-0:1.0: state 7 ports 2 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x6e1, return 0x101
[Mi Nov  3 11:55:12 2021] pci_bus 0000:01: Allocating resources
[Mi Nov  3 11:55:12 2021] pci_bus 0000:02: Allocating resources
[Mi Nov  3 11:55:12 2021] pci_bus 0000:03: Allocating resources
[Mi Nov  3 11:55:12 2021] pci_bus 0000:04: Allocating resources
[Mi Nov  3 11:55:12 2021] pci_bus 0000:05: Allocating resources
[Mi Nov  3 11:55:12 2021] pci_bus 0000:06: Allocating resources
[Mi Nov  3 11:55:12 2021] hub 3-0:1.0: state 7 ports 4 chg 0000 evt 0000
[Mi Nov  3 11:55:12 2021] pci_bus 0000:07: Allocating resources
[Mi Nov  3 11:55:12 2021] usb usb5-port4: status 0101, change 0000, 12 Mb/s
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Slot 2 output ctx = 0x10a7e8000 (dma)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Slot 2 input ctx = 0x1012fe000 (dma)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set slot id 2 dcbaa entry 00000000e1fe985f to 0x10a7e8000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: set port reset, actual port 5-4 status  = 0x6f1
[Mi Nov  3 11:55:12 2021] done.
[Mi Nov  3 11:55:12 2021] PM: suspend exit
[Mi Nov  3 11:55:12 2021] hub 7-0:1.0: hub_suspend
[Mi Nov  3 11:55:12 2021] usb usb7: bus auto-suspend, wakeup 1
[Mi Nov  3 11:55:12 2021] ehci-pci 0000:02:00.4: suspend root hub
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: set port remote wake mask, actual port 6-1 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.3: set port remote wake mask, actual port 4-1 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.3: set port remote wake mask, actual port 4-2 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] hub 4-0:1.0: hub_suspend
[Mi Nov  3 11:55:12 2021] usb usb4: bus auto-suspend, wakeup 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.3: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: set port remote wake mask, actual port 2-1 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: set port remote wake mask, actual port 2-2 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] hub 2-0:1.0: hub_suspend
[Mi Nov  3 11:55:12 2021] usb usb2: bus auto-suspend, wakeup 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: set port remote wake mask, actual port 6-2 status  = 0xe0002a0
[Mi Nov  3 11:55:12 2021] hub 6-0:1.0: hub_suspend
[Mi Nov  3 11:55:12 2021] usb usb6: bus auto-suspend, wakeup 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] ehci-pci 0000:02:00.4: hcd_pci_runtime_suspend: 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x200603
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x200603, return 0x100103
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: clear port4 reset change, portsc: 0x603
[Mi Nov  3 11:55:12 2021] usb 5-4: new full-speed USB device number 33 using xhci_hcd
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set root hub portnum to 4
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set fake root hub portnum to 4
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: udev->tt = 00000000a0d1e311
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: udev->ttport = 0x4
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful setup context command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Op regs DCBAA ptr = 0x00000109d26000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Slot ID 2 dcbaa entry @00000000e1fe985f = 0x0000010a7e8000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Output Context DMA address = 0x10a7e8000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Internal device address = 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Waiting for status stage event
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: set port reset, actual port 5-4 status  = 0x6f1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x200603
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x200603, return 0x100103
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: clear port4 reset change, portsc: 0x603
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Resetting device with slot ID 2
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Completed reset device command.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Can't reset device (slot ID 2) in default state
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Not freeing device rings.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful setup address command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Op regs DCBAA ptr = 0x00000109d26000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Slot ID 2 dcbaa entry @00000000e1fe985f = 0x0000010a7e8000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Output Context DMA address = 0x10a7e8000
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Internal device address = 2
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: enable port 4 USB2 hardware LPM
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set up evaluate context for LPM MEL change.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful evaluate context command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stalled endpoint for slot 2 ep 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7e90c0 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7e90f0, cycle 1

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7e90f0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 00000000d58d81a4, len = 0, expected = 10, status = -32
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stalled endpoint for slot 2 ep 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7e90f0 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7e9120, cycle 1

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7e9120
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 00000000d58d81a4, len = 0, expected = 10, status = -32
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stalled endpoint for slot 2 ep 0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7e9120 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7e9150, cycle 1

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7e9150
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 00000000d58d81a4, len = 0, expected = 10, status = -32
[Mi Nov  3 11:55:12 2021] usb 5-4: udev 33, busnum 5, minor = 544
[Mi Nov  3 11:55:12 2021] usb 5-4: New USB device found, idVendor=8087, idProduct=0032, bcdDevice= 0.00
[Mi Nov  3 11:55:12 2021] usb 5-4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[Mi Nov  3 11:55:12 2021] usb 5-4: usb_probe_device
[Mi Nov  3 11:55:12 2021] usb 5-4: configuration #1 chosen from 1 choice
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: add ep 0x81, slot id 2, new drop flags = 0x0, new add flags = 0x8
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: add ep 0x2, slot id 2, new drop flags = 0x0, new add flags = 0x18
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: add ep 0x82, slot id 2, new drop flags = 0x0, new add flags = 0x38
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: add ep 0x3, slot id 2, new drop flags = 0x0, new add flags = 0x78
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: add ep 0x83, slot id 2, new drop flags = 0x0, new add flags = 0xf8
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: xhci_check_bandwidth called for udev 00000000ededcc8b
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Endpoint Configure command
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 2 ep 2
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 2 ep 3
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stopped on No-op or Link TRB for slot 2 ep 4
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] usb 5-4: adding 5-4:1.0 (config #1, interface 0)
[Mi Nov  3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface
[Mi Nov  3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface - got id
[Mi Nov  3 11:55:12 2021] usb 5-4: adding 5-4:1.1 (config #1, interface 1)
[Mi Nov  3 11:55:12 2021] Generic FE-GE Realtek PHY r8169-0-200:00: attached PHY driver (mii_bus:phy_addr=r8169-0-200:00, irq=MAC)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 64 bytes, 32 bytes untransferred
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Device revision is 0
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Secure boot is enabled
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: OTP lock is enabled
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: API lock is enabled
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Debug lock is disabled
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Bootloader timestamp 2019.40 buildtype 1 build 38
[Mi Nov  3 11:55:12 2021] psmouse serio1: synaptics: queried max coordinates: x [..5678], y [..4694]
[Mi Nov  3 11:55:12 2021] Bluetooth: hci0: Found device firmware: intel/ibt-0041-0041.sfi
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] psmouse serio1: synaptics: queried min coordinates: x [1266..], y [1162..]
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] r8169 0000:02:00.0 enp2s0f0: Link is Down
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.3: ep 0x81 - asked for 8 bytes, 6 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] Generic FE-GE Realtek PHY r8169-0-500:00: attached PHY driver (mii_bus:phy_addr=r8169-0-500:00, irq=MAC)
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x202a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] hub 5-0:1.0: state 7 ports 4 chg 0000 evt 0010
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x202a0, return 0x10100
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: clear port4 connect change, portsc: 0x2a0
[Mi Nov  3 11:55:12 2021] usb usb5-port4: status 0100, change 0001, 12 Mb/s
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] usb 5-4: USB disconnect, device number 33
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] usb 5-4: unregistering device
[Mi Nov  3 11:55:12 2021] usb 5-4: unregistering interface 5-4:1.0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x109ffe090 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x109ffe0a0, cycle 0

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7fd090 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7fd0a0, cycle 0

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @109ffe0a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 00000000d63c3d0d, len = 0, expected = 252, status = -71
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7fd0a0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 000000007cefaadb, len = 0, expected = 1028, status = -71
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7fd0a0 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7fd0b0, cycle 0

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7fd0b0
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 00000000fd3cb3d4, len = 0, expected = 1028, status = -71
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Cancel URB 000000000c718231, dev 4, ep 0x81, starting at offset 0x10a7ed020
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: shutdown urb 000000000c718231 ep1in-intr
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Stopped on Transfer TRB for slot 2 ep 2
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x10a7ed020 (dma).
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x10a7ed030, cycle 1

[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @10a7ed030
[Mi Nov  3 11:55:12 2021] xhci_hcd 0000:07:00.4: Giveback URB 000000000c718231, len = 0, expected = 64, status = -115
[Mi Nov  3 11:55:12 2021] r8169 0000:05:00.0 enp5s0: Link is Down
[Mi Nov  3 11:55:13 2021] xhci_hcd 0000:07:00.4: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: // Ding dong!
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: Stopped on No-op or Link TRB for slot 1 ep 10
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: Stopped on No-op or Link TRB for slot 1 ep 6
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: Stopped on No-op or Link TRB for slot 1 ep 0
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: Set port 1-2 link state, portsc: 0xe03, write 0x10e61
[Mi Nov  3 11:55:14 2021] usb 1-2: usb auto-suspend, wakeup 0
[Mi Nov  3 11:55:14 2021] hub 1-0:1.0: hub_suspend
[Mi Nov  3 11:55:14 2021] usb usb1: bus auto-suspend, wakeup 1
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: xhci_hub_status_data: stopping port polling.
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: config port 2-1 wake bits, portsc: 0xa0002a0, write: 0xa0202a0
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: config port 2-2 wake bits, portsc: 0xa0002a0, write: 0xa0202a0
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: config port 1-1 wake bits, portsc: 0xa0002a0, write: 0xa0202a0
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: xhci_suspend: stopping port polling.
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: // Setting command ring address to 0xfff9a001
[Mi Nov  3 11:55:14 2021] xhci_hcd 0000:06:00.0: hcd_pci_runtime_suspend: 0
[Mi Nov  3 11:55:14 2021] Bluetooth: hci0: command 0xfc09 tx timeout
[Mi Nov  3 11:55:16 2021] wlp3s0: authenticate with 50:60:28:5a:84:51
[Mi Nov  3 11:55:16 2021] wlp3s0: send auth to 50:60:28:5a:84:51 (try 1/3)
[Mi Nov  3 11:55:16 2021] wlp3s0: authenticated
[Mi Nov  3 11:55:16 2021] wlp3s0: associate with 50:60:28:5a:84:51 (try 1/3)
[Mi Nov  3 11:55:16 2021] wlp3s0: RX AssocResp from 50:60:28:5a:84:51 (capab=0x1111 status=0 aid=4)
[Mi Nov  3 11:55:16 2021] wlp3s0: associated
[Mi Nov  3 11:55:16 2021] wlp3s0: Limiting TX power to 22 (23 - 1) dBm as advertised by 50:60:28:5a:84:51
[Mi Nov  3 11:55:16 2021] IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
[Mi Nov  3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
[Mi Nov  3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
[Mi Nov  3 11:55:23 2021] Bluetooth: hci0: Intel reset sent to retry FW download
[Mi Nov  3 11:55:23 2021] usb 5-4: unregistering interface 5-4:1.1
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: disable port 4 USB2 hardware LPM
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Set up evaluate context for LPM MEL change.
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Successful evaluate context command
[Mi Nov  3 11:55:23 2021] usb 5-4: usb_disable_device nuking all URBs
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_drop_endpoint called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: drop ep 0x81, slot id 2, new drop flags = 0x8, new add flags = 0x0
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_drop_endpoint called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: drop ep 0x2, slot id 2, new drop flags = 0x18, new add flags = 0x0
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_drop_endpoint called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: drop ep 0x82, slot id 2, new drop flags = 0x38, new add flags = 0x0
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_drop_endpoint called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: drop ep 0x3, slot id 2, new drop flags = 0x78, new add flags = 0x0
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_drop_endpoint called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: drop ep 0x83, slot id 2, new drop flags = 0xf8, new add flags = 0x0
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: xhci_check_bandwidth called for udev 00000000ededcc8b
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Successful Endpoint Configure command
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: endpoint disable with ep_state 0x40
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: endpoint disable with ep_state 0x40
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Get port status 5-4 read: 0x2a0, return 0x100
[Mi Nov  3 11:55:23 2021] usb usb5-port4: debounce total 100ms stable 100ms status 0x100
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 40 bytes, 2 bytes untransferred
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 266 bytes, 258 bytes untransferred
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: Waiting for status stage event
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 266 bytes, 258 bytes untransferred
[Mi Nov  3 11:55:23 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 266 bytes, 260 bytes untransferred
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Cancel URB 0000000034bc82ca, dev 3, ep 0x83, starting at offset 0x1012ffea0
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Stopped on Transfer TRB for slot 1 ep 6
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Removing canceled TD starting at 0x1012ffea0 (dma).
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Set TR Deq ptr 0x1012ffeb0, cycle 1

[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Successful Set TR Deq Ptr cmd, deq = @1012ffeb0
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: Giveback URB 0000000034bc82ca, len = 0, expected = 7, status = -115
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 266 bytes, 260 bytes untransferred
[Mi Nov  3 11:55:25 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 266 bytes, 260 bytes untransferred


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Alan Stern]

On Wed, Nov 03, 2021 at 03:55:31PM +0100, Benjamin Berg wrote:
> Hi,
> 
> a user is seeing a hang in fprintd while enumerating devices which
> appears to be caused by an interaction of:
> 
> * system is resuming from S3
> * btusb starts loading firmware
> * bluetooth device disappears (probably thinkpad_acpi rfkill)
> * libusb enumerates USB devices (fprintd in this case)
> 
> When this happens, the firmware load fails after a timeout of 10s. It
> appears that if userspace queries information about the root hub in
> question during this time, it will hang until the btusb firmware load
> has timed out.
> 
> Attaching the full kernel log, below an excerpt, you can see:
>  * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
>  * libusb enumeration retrieves information about the usb5 root hub,
>    and blocks on this
>  * At :14 there is a tx timeout on hci0
>  * At :23 the firmware load finally fails
>  * Then usb_disable_device happens
>  * libusb/fprintd gets the usb5 HUB information and continues its
>    enumeration
> 
> As I see it, there may be two issues:
> 1. userspace should not block due to the firmware load hanging
> 2. btusb should give up more quickly when the device disappears
> 
> Does anyone have a good idea about the possible cause or how we can fix
> the problem?
> 
> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857

I'm not familiar with the btusb driver, so someone on the 
linux-bluetooth mailing list would have a better idea about this. 
However, it does look as though btusb keeps the device locked during the 
entire 10-second period while it tries to send over the firmware, and it 
doesn't abort the procedure when it starts getting disconnection errors 
but instead persists until a timeout expires.  Keeping the device locked 
would certainly block lsusb.

In general, locking the device during a firmware upload seems like
the right thing to do -- you don't want extraneous transfers from
other processes messing up the firmware!  So overall, it appears that
the whole problem would be solved if the firmware transfer were
aborted as soon as the -ENODEV errors start appearing.

Alan Stern

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Marcel Holtmann]

Hi Alan,

>> a user is seeing a hang in fprintd while enumerating devices which
>> appears to be caused by an interaction of:
>> 
>> * system is resuming from S3
>> * btusb starts loading firmware
>> * bluetooth device disappears (probably thinkpad_acpi rfkill)
>> * libusb enumerates USB devices (fprintd in this case)
>> 
>> When this happens, the firmware load fails after a timeout of 10s. It
>> appears that if userspace queries information about the root hub in
>> question during this time, it will hang until the btusb firmware load
>> has timed out.
>> 
>> Attaching the full kernel log, below an excerpt, you can see:
>> * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
>> * libusb enumeration retrieves information about the usb5 root hub,
>>   and blocks on this
>> * At :14 there is a tx timeout on hci0
>> * At :23 the firmware load finally fails
>> * Then usb_disable_device happens
>> * libusb/fprintd gets the usb5 HUB information and continues its
>>   enumeration
>> 
>> As I see it, there may be two issues:
>> 1. userspace should not block due to the firmware load hanging
>> 2. btusb should give up more quickly when the device disappears
>> 
>> Does anyone have a good idea about the possible cause or how we can fix
>> the problem?
>> 
>> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
> 
> I'm not familiar with the btusb driver, so someone on the 
> linux-bluetooth mailing list would have a better idea about this. 
> However, it does look as though btusb keeps the device locked during the 
> entire 10-second period while it tries to send over the firmware, and it 
> doesn't abort the procedure when it starts getting disconnection errors 
> but instead persists until a timeout expires.  Keeping the device locked 
> would certainly block lsusb.
> 
> In general, locking the device during a firmware upload seems like
> the right thing to do -- you don't want extraneous transfers from
> other processes messing up the firmware!  So overall, it appears that
> the whole problem would be solved if the firmware transfer were
> aborted as soon as the -ENODEV errors start appearing.

the problem seems to be that we hitting HCI command timeout. So the firmware download is done via HCI commands. These commands are send to the transport driver btusb.c via hdev->send (as btusb_send_frame). This triggers the usb_submit_urb or queues them via data->deferred anchor. All this reports back the error properly except that nobody does anything with it.

See hci_send_frame() last portion:

        err = hdev->send(hdev, skb);                                             
        if (err < 0) {                                                           
                bt_dev_err(hdev, "sending frame failed (%d)", err);              
                kfree_skb(skb);                                                  
        }

And that is it. We are not checking for ENODEV or any error here. That means the failure of the HCI command gets only caught via the HCI command timeout. I don’t know how to do this yet, but you would have to look there to fail HCI command right away instead of waiting for the timeout.

Regards

Marcel

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Alan Stern]

On Wed, Nov 03, 2021 at 08:31:03PM +0100, Marcel Holtmann wrote:
> Hi Alan,
> 
> >> a user is seeing a hang in fprintd while enumerating devices which
> >> appears to be caused by an interaction of:
> >> 
> >> * system is resuming from S3
> >> * btusb starts loading firmware
> >> * bluetooth device disappears (probably thinkpad_acpi rfkill)
> >> * libusb enumerates USB devices (fprintd in this case)
> >> 
> >> When this happens, the firmware load fails after a timeout of 10s. It
> >> appears that if userspace queries information about the root hub in
> >> question during this time, it will hang until the btusb firmware load
> >> has timed out.
> >> 
> >> Attaching the full kernel log, below an excerpt, you can see:
> >> * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
> >> * libusb enumeration retrieves information about the usb5 root hub,
> >>   and blocks on this
> >> * At :14 there is a tx timeout on hci0
> >> * At :23 the firmware load finally fails
> >> * Then usb_disable_device happens
> >> * libusb/fprintd gets the usb5 HUB information and continues its
> >>   enumeration
> >> 
> >> As I see it, there may be two issues:
> >> 1. userspace should not block due to the firmware load hanging
> >> 2. btusb should give up more quickly when the device disappears
> >> 
> >> Does anyone have a good idea about the possible cause or how we can fix
> >> the problem?
> >> 
> >> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
> > 
> > I'm not familiar with the btusb driver, so someone on the 
> > linux-bluetooth mailing list would have a better idea about this. 
> > However, it does look as though btusb keeps the device locked during the 
> > entire 10-second period while it tries to send over the firmware, and it 
> > doesn't abort the procedure when it starts getting disconnection errors 
> > but instead persists until a timeout expires.  Keeping the device locked 
> > would certainly block lsusb.
> > 
> > In general, locking the device during a firmware upload seems like
> > the right thing to do -- you don't want extraneous transfers from
> > other processes messing up the firmware!  So overall, it appears that
> > the whole problem would be solved if the firmware transfer were
> > aborted as soon as the -ENODEV errors start appearing.
> 
> the problem seems to be that we hitting HCI command timeout. So the 
> firmware download is done via HCI commands. These commands are send to 
> the transport driver btusb.c via hdev->send (as btusb_send_frame). 
> This triggers the usb_submit_urb or queues them via data->deferred 
> anchor. All this reports back the error properly except that nobody 
> does anything with it.
> 
> See hci_send_frame() last portion:
> 
>         err = hdev->send(hdev, skb);
>         if (err < 0) {
>                 bt_dev_err(hdev, "sending frame failed (%d)", err);
>                 kfree_skb(skb);
>         }
> 
> And that is it. We are not checking for ENODEV or any error here. That 
> means the failure of the HCI command gets only caught via the HCI 
> command timeout. I don’t know how to do this yet, but you would have 
> to look there to fail HCI command right away instead of waiting for 
> the timeout.

I have no idea how all the different layers work here.  Clearly 
something has to signal hdev->req_wait_q after setting hdev->req_status 
to some appropriate value.  Can this be done in btusb.c, either when the 
URB is submitted or when it completes?  Or in hci_send_frame?

Alan Stern

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Benjamin Berg]

[-- Attachment #1: Type: text/plain, Size: 2655 bytes --]

Hi Marcel and Alan,

On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > I'm not familiar with the btusb driver, so someone on the 
> > linux-bluetooth mailing list would have a better idea about this. 
> > However, it does look as though btusb keeps the device locked during the 
> > entire 10-second period while it tries to send over the firmware, and it 
> > doesn't abort the procedure when it starts getting disconnection errors 
> > but instead persists until a timeout expires.  Keeping the device locked 
> > would certainly block lsusb.
> > 
> > In general, locking the device during a firmware upload seems like
> > the right thing to do -- you don't want extraneous transfers from
> > other processes messing up the firmware!  So overall, it appears that
> > the whole problem would be solved if the firmware transfer were
> > aborted as soon as the -ENODEV errors start appearing.
> 
> the problem seems to be that we hitting HCI command timeout. So the
> firmware download is done via HCI commands. These commands are send
> to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> This triggers the usb_submit_urb or queues them via data->deferred
> anchor. All this reports back the error properly except that nobody
> does anything with it.
> 
> See hci_send_frame() last portion:
> 
>         err = hdev->send(hdev, skb);                                             
>         if (err < 0) {                                                           
>                 bt_dev_err(hdev, "sending frame failed (%d)", err);              
>                 kfree_skb(skb);                                                  
>         }
> 
> And that is it. We are not checking for ENODEV or any error here.
> That means the failure of the HCI command gets only caught via the
> HCI command timeout. I don’t know how to do this yet, but you would
> have to look there to fail HCI command right away instead of waiting
> for the timeout.

Hmm, true, I don't see a "sending frame failed" error message during
the firmware download though. You are right that this codepath is
loosing the error, but this does not seem to be the scenario we are
running into while loading the firmware. This error only happens later
on from the btintel_reset_to_bootloader function.

What seems to happen in the posted log is that the URB is initially
submitted just fine and the transfer errors out afterwards.
Unfortunately, the btusb_tx_complete is only used for statistics
(stat.err_tx is increased) and has no further error handling that could
abort the firmware upload.

Benjamin

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Alan Stern]

On Thu, Nov 04, 2021 at 10:34:22AM +0100, Benjamin Berg wrote:
> Hi Marcel and Alan,
> 
> On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > > I'm not familiar with the btusb driver, so someone on the 
> > > linux-bluetooth mailing list would have a better idea about this. 
> > > However, it does look as though btusb keeps the device locked during the 
> > > entire 10-second period while it tries to send over the firmware, and it 
> > > doesn't abort the procedure when it starts getting disconnection errors 
> > > but instead persists until a timeout expires.  Keeping the device locked 
> > > would certainly block lsusb.
> > > 
> > > In general, locking the device during a firmware upload seems like
> > > the right thing to do -- you don't want extraneous transfers from
> > > other processes messing up the firmware!  So overall, it appears that
> > > the whole problem would be solved if the firmware transfer were
> > > aborted as soon as the -ENODEV errors start appearing.
> > 
> > the problem seems to be that we hitting HCI command timeout. So the
> > firmware download is done via HCI commands. These commands are send
> > to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> > This triggers the usb_submit_urb or queues them via data->deferred
> > anchor. All this reports back the error properly except that nobody
> > does anything with it.
> > 
> > See hci_send_frame() last portion:
> > 
> >         err = hdev->send(hdev, skb);                                             
> >         if (err < 0) {                                                           
> >                 bt_dev_err(hdev, "sending frame failed (%d)", err);              
> >                 kfree_skb(skb);                                                  
> >         }
> > 
> > And that is it. We are not checking for ENODEV or any error here.
> > That means the failure of the HCI command gets only caught via the
> > HCI command timeout. I don’t know how to do this yet, but you would
> > have to look there to fail HCI command right away instead of waiting
> > for the timeout.
> 
> Hmm, true, I don't see a "sending frame failed" error message during
> the firmware download though.

It is in the log you posted:

[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)

But this occurred after the timeout, so maybe you had in mind something 
occurring earlier.

>  You are right that this codepath is
> loosing the error, but this does not seem to be the scenario we are
> running into while loading the firmware. This error only happens later
> on from the btintel_reset_to_bootloader function.
> 
> What seems to happen in the posted log is that the URB is initially
> submitted just fine and the transfer errors out afterwards.
> Unfortunately, the btusb_tx_complete is only used for statistics
> (stat.err_tx is increased) and has no further error handling that could
> abort the firmware upload.

While detecting the errors during URB completion would be nice, it isn't 
necessary.  Things would work just as well if the disconnect error were 
detected during submission of the following URB.

Alan Stern

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Benjamin Berg]

[-- Attachment #1: Type: text/plain, Size: 3996 bytes --]

On Thu, 2021-11-04 at 09:28 -0400, Alan Stern wrote:
> On Thu, Nov 04, 2021 at 10:34:22AM +0100, Benjamin Berg wrote:
> > Hi Marcel and Alan,
> > 
> > On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > > > I'm not familiar with the btusb driver, so someone on the 
> > > > linux-bluetooth mailing list would have a better idea about this. 
> > > > However, it does look as though btusb keeps the device locked during the 
> > > > entire 10-second period while it tries to send over the firmware, and it 
> > > > doesn't abort the procedure when it starts getting disconnection errors 
> > > > but instead persists until a timeout expires.  Keeping the device locked 
> > > > would certainly block lsusb.
> > > > 
> > > > In general, locking the device during a firmware upload seems like
> > > > the right thing to do -- you don't want extraneous transfers from
> > > > other processes messing up the firmware!  So overall, it appears that
> > > > the whole problem would be solved if the firmware transfer were
> > > > aborted as soon as the -ENODEV errors start appearing.
> > > 
> > > the problem seems to be that we hitting HCI command timeout. So the
> > > firmware download is done via HCI commands. These commands are send
> > > to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> > > This triggers the usb_submit_urb or queues them via data->deferred
> > > anchor. All this reports back the error properly except that nobody
> > > does anything with it.
> > > 
> > > See hci_send_frame() last portion:
> > > 
> > >         err = hdev->send(hdev, skb);                                             
> > >         if (err < 0) {                                                           
> > >                 bt_dev_err(hdev, "sending frame failed (%d)", err);              
> > >                 kfree_skb(skb);                                                  
> > >         }
> > > 
> > > And that is it. We are not checking for ENODEV or any error here.
> > > That means the failure of the HCI command gets only caught via the
> > > HCI command timeout. I don’t know how to do this yet, but you would
> > > have to look there to fail HCI command right away instead of waiting
> > > for the timeout.
> > 
> > Hmm, true, I don't see a "sending frame failed" error message during
> > the firmware download though.
> 
> It is in the log you posted:
> 
> [Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
> [Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
> 
> But this occurred after the timeout, so maybe you had in mind something 
> occurring earlier.

Yep, that one happens when the driver tries to reset the device. We
need to catch the error earlier in order to avoid the 10s wait.

> >  You are right that this codepath is
> > loosing the error, but this does not seem to be the scenario we are
> > running into while loading the firmware. This error only happens later
> > on from the btintel_reset_to_bootloader function.
> > 
> > What seems to happen in the posted log is that the URB is initially
> > submitted just fine and the transfer errors out afterwards.
> > Unfortunately, the btusb_tx_complete is only used for statistics
> > (stat.err_tx is increased) and has no further error handling that could
> > abort the firmware upload.
> 
> While detecting the errors during URB completion would be nice, it isn't 
> necessary.  Things would work just as well if the disconnect error were 
> detected during submission of the following URB.

Ah, good point. The in-flight interrupt URB responsible of retrieving
the event from the device will fail. It should be sufficient to inject
a hardware error event at that point in order to fix this.

As such, a simple solution may be to call hci_reset_dev from inside
btusb_intr_complete and btusb_submit_intr_urb when the URB submission
fails (for "err != -EPERM").

Benjamin

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Userspace enumeration hang while btusb tries to load firmware of removed device

[Benjamin Berg]

[-- Attachment #1: Type: text/plain, Size: 1838 bytes --]

Hi,

On Wed, 2021-11-03 at 16:11 -0400, Alan Stern wrote:
> On Wed, Nov 03, 2021 at 08:31:03PM +0100, Marcel Holtmann wrote:
> > the problem seems to be that we hitting HCI command timeout. So the 
> > firmware download is done via HCI commands. These commands are send to 
> > the transport driver btusb.c via hdev->send (as btusb_send_frame). 
> > This triggers the usb_submit_urb or queues them via data->deferred 
> > anchor. All this reports back the error properly except that nobody 
> > does anything with it.
> > 
> > See hci_send_frame() last portion:
> > 
> >         err = hdev->send(hdev, skb);
> >         if (err < 0) {
> >                 bt_dev_err(hdev, "sending frame failed (%d)", err);
> >                 kfree_skb(skb);
> >         }
> > 
> > And that is it. We are not checking for ENODEV or any error here. That 
> > means the failure of the HCI command gets only caught via the HCI 
> > command timeout. I don’t know how to do this yet, but you would have 
> > to look there to fail HCI command right away instead of waiting for 
> > the timeout.
> 
> I have no idea how all the different layers work here.  Clearly 
> something has to signal hdev->req_wait_q after setting hdev->req_status 
> to some appropriate value.  Can this be done in btusb.c, either when the 
> URB is submitted or when it completes?  Or in hci_send_frame?

I submitted
  https://patchwork.kernel.org/project/bluetooth/list/?series=577565
for this now.

The patchset pretty much calls hci_req_sync_cancel to set req_status
and signal req_wait_q. Doing this and hooking it up in various location
appears to work reasonably well for the synchronous commands.

Benjamin

PS: The user now reported that TLP is blocking the rfkill switch after
resume. So an good workaround is to just not use TLP.

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]