Hello folks,
The $subject patch causes a regression on my HP EliteBook laptop with a
built-in USB bluetooth adapter. About 50% of the time, a suspend/resume
cycle will cause the bluetooth adapter to stop working.
The dmesg log below shows two suspend/resume cycles. At time 63.928 you can
see the bluetooth adapter being successfully resumed, and at time 140.969
you can see it fail. After reverting the patch, the bluetooth adapter
resumes 100% of the time.
I also included below a lsusb -v of the bluetooth adapter. Is there any
other debugging info you'd like me to send?
This is with Linus's tree as of yesterday, but the misbehavior goes back
to 5.5-rc1.
[ 49.249536] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 59.300552] PM: suspend entry (deep)
[ 59.305440] Filesystems sync: 0.004 seconds
[ 59.305859] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 59.307450] OOM killer disabled.
[ 59.307451] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 59.308604] printk: Suspending console(s) (use no_console_suspend to debug)
[ 59.343478] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 59.344508] sd 0:0:0:0: [sda] Stopping disk
[ 59.424472] e1000e: EEE TX LPI TIMER: 00000011
[ 59.852914] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 59.876708] [drm] PCIE gen 2 link speeds already enabled
[ 59.886714] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 59.886808] radeon 0000:03:00.0: WB enabled
[ 59.886810] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 59.886810] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 59.886811] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 59.886812] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 59.886813] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 59.887627] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 59.988072] radeon 0000:03:00.0: failed VCE resume (-110).
[ 60.220341] [drm] ring test on 0 succeeded in 1 usecs
[ 60.220346] [drm] ring test on 1 succeeded in 1 usecs
[ 60.220351] [drm] ring test on 2 succeeded in 1 usecs
[ 60.220359] [drm] ring test on 3 succeeded in 5 usecs
[ 60.220367] [drm] ring test on 4 succeeded in 5 usecs
[ 60.396050] [drm] ring test on 5 succeeded in 2 usecs
[ 60.396056] [drm] UVD initialized successfully.
[ 60.396117] [drm] ib test on ring 0 succeeded in 0 usecs
[ 60.396179] [drm] ib test on ring 1 succeeded in 0 usecs
[ 60.396225] [drm] ib test on ring 2 succeeded in 0 usecs
[ 60.396267] [drm] ib test on ring 3 succeeded in 0 usecs
[ 60.396321] [drm] ib test on ring 4 succeeded in 0 usecs
[ 61.075516] [drm] ib test on ring 5 succeeded
[ 61.987920] ACPI: EC: interrupt blocked
[ 62.031807] ACPI: Preparing to enter system sleep state S3
[ 62.034281] ACPI: EC: event blocked
[ 62.034282] ACPI: EC: EC stopped
[ 62.034282] PM: Saving platform NVS memory
[ 62.034294] Disabling non-boot CPUs ...
[ 62.034559] IRQ 42: no longer affine to CPU1
[ 62.034562] IRQ 43: no longer affine to CPU1
[ 62.034566] IRQ 45: no longer affine to CPU1
[ 62.034569] IRQ 46: no longer affine to CPU1
[ 62.034573] IRQ 51: no longer affine to CPU1
[ 62.035897] smpboot: CPU 1 is now offline
[ 62.036390] IRQ 53: no longer affine to CPU2
[ 62.037397] smpboot: CPU 2 is now offline
[ 62.037937] IRQ 1: no longer affine to CPU3
[ 62.037940] IRQ 8: no longer affine to CPU3
[ 62.037942] IRQ 9: no longer affine to CPU3
[ 62.037944] IRQ 12: no longer affine to CPU3
[ 62.038958] smpboot: CPU 3 is now offline
[ 62.040172] ACPI: Low-level resume complete
[ 62.040270] ACPI: EC: EC started
[ 62.040271] PM: Restoring platform NVS memory
[ 62.047040] Enabling non-boot CPUs ...
[ 62.047141] x86: Booting SMP configuration:
[ 62.047144] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 62.049459] CPU1 is up
[ 62.049539] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 62.055736] CPU2 is up
[ 62.055797] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 62.057475] CPU3 is up
[ 62.060610] ACPI: Waking up from system sleep state S3
[ 62.202438] ACPI: EC: interrupt unblocked
[ 62.313530] ACPI: EC: event unblocked
[ 62.324891] sd 0:0:0:0: [sda] Starting disk
[ 62.327013] [drm] PCIE gen 2 link speeds already enabled
[ 62.337552] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 62.337645] radeon 0000:03:00.0: WB enabled
[ 62.337647] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 62.337648] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 62.337648] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 62.337649] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 62.337650] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 62.338447] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 62.439210] radeon 0000:03:00.0: failed VCE resume (-110).
[ 62.609068] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 62.635003] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 62.643521] ata1.00: supports DRM functions and may not be fully accessible
[ 62.673227] [drm] ring test on 0 succeeded in 1 usecs
[ 62.673232] [drm] ring test on 1 succeeded in 1 usecs
[ 62.673237] [drm] ring test on 2 succeeded in 1 usecs
[ 62.673246] [drm] ring test on 3 succeeded in 5 usecs
[ 62.673253] [drm] ring test on 4 succeeded in 5 usecs
[ 62.692012] ata1.00: ATA Identify Device Log not supported
[ 62.692013] ata1.00: Security Log not supported
[ 62.740856] ata1.00: supports DRM functions and may not be fully accessible
[ 62.789506] ata1.00: ATA Identify Device Log not supported
[ 62.789506] ata1.00: Security Log not supported
[ 62.789509] ata1.00: configured for UDMA/100
[ 62.837092] usb 2-3.2: reset full-speed USB device number 4 using xhci_hcd
[ 62.849223] [drm] ring test on 5 succeeded in 2 usecs
[ 62.849228] [drm] UVD initialized successfully.
[ 62.849290] [drm] ib test on ring 0 succeeded in 0 usecs
[ 62.849355] [drm] ib test on ring 1 succeeded in 0 usecs
[ 62.849414] [drm] ib test on ring 2 succeeded in 0 usecs
[ 62.849461] [drm] ib test on ring 3 succeeded in 0 usecs
[ 62.849514] [drm] ib test on ring 4 succeeded in 0 usecs
[ 63.509106] [drm] ib test on ring 5 succeeded
[ 63.901356] tpm tpm0: tpm_try_transmit: send(): error -5
[ 63.906084] acpi LNXPOWER:02: Turning OFF
[ 63.906128] acpi LNXPOWER:01: Turning OFF
[ 63.906162] OOM killer enabled.
[ 63.906163] Restarting tasks ...
[ 63.906304] acpi PNP0501:00: Still not present
[ 63.910752] done.
[ 63.928642] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 63.928646] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 63.985337] PM: suspend exit
[ 64.035638] Bluetooth: hci0: unexpected event for opcode 0xfc2f
[ 64.051657] Bluetooth: hci0: Intel firmware patch completed and activated
[ 64.161465] e1000e: enp0s25 NIC Link is Down
[ 65.270730] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 65.305008] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 68.471403] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 68.471457] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 71.144846] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 71.149124] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 71.153318] wlo1: authenticated
[ 71.157026] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 71.160772] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=8)
[ 71.162365] wlo1: associated
[ 71.197208] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 91.717987] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 101.816553] PM: suspend entry (deep)
[ 101.824280] Filesystems sync: 0.007 seconds
[ 101.825027] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 101.827550] OOM killer disabled.
[ 101.827551] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 101.828853] printk: Suspending console(s) (use no_console_suspend to debug)
[ 101.846588] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 101.848562] sd 0:0:0:0: [sda] Stopping disk
[ 101.924487] e1000e: EEE TX LPI TIMER: 00000011
[ 102.351199] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 102.381284] [drm] PCIE gen 2 link speeds already enabled
[ 102.391857] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 102.391949] radeon 0000:03:00.0: WB enabled
[ 102.391951] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 102.391952] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 102.391953] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 102.391954] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 102.391955] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 102.392748] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 102.493200] radeon 0000:03:00.0: failed VCE resume (-110).
[ 102.725824] [drm] ring test on 0 succeeded in 1 usecs
[ 102.725829] [drm] ring test on 1 succeeded in 1 usecs
[ 102.725834] [drm] ring test on 2 succeeded in 1 usecs
[ 102.725843] [drm] ring test on 3 succeeded in 5 usecs
[ 102.725850] [drm] ring test on 4 succeeded in 5 usecs
[ 102.901533] [drm] ring test on 5 succeeded in 2 usecs
[ 102.901539] [drm] UVD initialized successfully.
[ 102.901591] [drm] ib test on ring 0 succeeded in 0 usecs
[ 102.901639] [drm] ib test on ring 1 succeeded in 0 usecs
[ 102.901685] [drm] ib test on ring 2 succeeded in 0 usecs
[ 102.901731] [drm] ib test on ring 3 succeeded in 0 usecs
[ 102.901775] [drm] ib test on ring 4 succeeded in 0 usecs
[ 103.574715] [drm] ib test on ring 5 succeeded
[ 104.487327] ACPI: EC: interrupt blocked
[ 104.531372] ACPI: Preparing to enter system sleep state S3
[ 104.533713] ACPI: EC: event blocked
[ 104.533715] ACPI: EC: EC stopped
[ 104.533716] PM: Saving platform NVS memory
[ 104.533733] Disabling non-boot CPUs ...
[ 104.534232] irq_migrate_all_off_this_cpu: 5 callbacks suppressed
[ 104.534235] IRQ 42: no longer affine to CPU1
[ 104.534242] IRQ 43: no longer affine to CPU1
[ 104.534248] IRQ 45: no longer affine to CPU1
[ 104.534254] IRQ 46: no longer affine to CPU1
[ 104.534261] IRQ 51: no longer affine to CPU1
[ 104.534267] IRQ 53: no longer affine to CPU1
[ 104.535329] smpboot: CPU 1 is now offline
[ 104.536804] IRQ 50: no longer affine to CPU2
[ 104.537830] smpboot: CPU 2 is now offline
[ 104.539148] IRQ 1: no longer affine to CPU3
[ 104.539155] IRQ 8: no longer affine to CPU3
[ 104.539159] IRQ 9: no longer affine to CPU3
[ 104.540198] smpboot: CPU 3 is now offline
[ 104.542275] ACPI: Low-level resume complete
[ 104.542381] ACPI: EC: EC started
[ 104.542382] PM: Restoring platform NVS memory
[ 104.549151] Enabling non-boot CPUs ...
[ 104.549249] x86: Booting SMP configuration:
[ 104.549251] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 104.551570] CPU1 is up
[ 104.551649] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 104.557873] CPU2 is up
[ 104.557929] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 104.559629] CPU3 is up
[ 104.563164] ACPI: Waking up from system sleep state S3
[ 104.704499] ACPI: EC: interrupt unblocked
[ 104.819510] ACPI: EC: event unblocked
[ 104.821054] sd 0:0:0:0: [sda] Starting disk
[ 104.834807] [drm] PCIE gen 2 link speeds already enabled
[ 104.844955] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 104.845047] radeon 0000:03:00.0: WB enabled
[ 104.845049] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 104.845050] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 104.845051] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 104.845051] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 104.845052] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 104.845862] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 104.946633] radeon 0000:03:00.0: failed VCE resume (-110).
[ 105.108858] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 105.138782] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 105.143952] ata1.00: supports DRM functions and may not be fully accessible
[ 105.180609] [drm] ring test on 0 succeeded in 1 usecs
[ 105.180614] [drm] ring test on 1 succeeded in 1 usecs
[ 105.180619] [drm] ring test on 2 succeeded in 1 usecs
[ 105.180628] [drm] ring test on 3 succeeded in 5 usecs
[ 105.180636] [drm] ring test on 4 succeeded in 5 usecs
[ 105.192464] ata1.00: ATA Identify Device Log not supported
[ 105.192465] ata1.00: Security Log not supported
[ 105.241291] ata1.00: supports DRM functions and may not be fully accessible
[ 105.289943] ata1.00: ATA Identify Device Log not supported
[ 105.289944] ata1.00: Security Log not supported
[ 105.289946] ata1.00: configured for UDMA/100
[ 105.336859] usb 2-3.2: reset full-speed USB device number 4 using xhci_hcd
[ 105.356681] [drm] ring test on 5 succeeded in 2 usecs
[ 105.356702] [drm] UVD initialized successfully.
[ 105.356758] [drm] ib test on ring 0 succeeded in 0 usecs
[ 105.356806] [drm] ib test on ring 1 succeeded in 0 usecs
[ 105.356852] [drm] ib test on ring 2 succeeded in 0 usecs
[ 105.356897] [drm] ib test on ring 3 succeeded in 0 usecs
[ 105.356942] [drm] ib test on ring 4 succeeded in 0 usecs
[ 106.008881] [drm] ib test on ring 5 succeeded
[ 106.405496] tpm tpm0: tpm_try_transmit: send(): error -5
[ 106.416521] acpi LNXPOWER:02: Turning OFF
[ 106.416586] acpi LNXPOWER:01: Turning OFF
[ 106.416620] OOM killer enabled.
[ 106.416621] Restarting tasks ...
[ 106.416828] acpi PNP0501:00: Still not present
[ 106.421567] done.
[ 106.432428] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 106.432463] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 106.506279] PM: suspend exit
[ 106.541419] Bluetooth: hci0: unexpected event for opcode 0xfc2f
[ 106.557442] Bluetooth: hci0: Intel firmware patch completed and activated
[ 106.665277] e1000e: enp0s25 NIC Link is Down
[ 107.773702] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 107.810799] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 111.003589] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 111.003640] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 113.751328] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 113.755612] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 113.760228] wlo1: authenticated
[ 113.761391] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 113.767745] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=8)
[ 113.774043] wlo1: associated
[ 113.792918] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 126.321068] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 136.367748] PM: suspend entry (deep)
[ 136.377378] Filesystems sync: 0.009 seconds
[ 136.378191] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 136.381154] OOM killer disabled.
[ 136.381155] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 136.382553] printk: Suspending console(s) (use no_console_suspend to debug)
[ 136.411098] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 136.412116] sd 0:0:0:0: [sda] Stopping disk
[ 136.477379] e1000e: EEE TX LPI TIMER: 00000011
[ 136.883799] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 136.909481] [drm] PCIE gen 2 link speeds already enabled
[ 136.920054] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 136.920147] radeon 0000:03:00.0: WB enabled
[ 136.920148] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 136.920149] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 136.920150] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 136.920151] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 136.920152] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 136.920945] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 137.021396] radeon 0000:03:00.0: failed VCE resume (-110).
[ 137.254078] [drm] ring test on 0 succeeded in 1 usecs
[ 137.254083] [drm] ring test on 1 succeeded in 1 usecs
[ 137.254088] [drm] ring test on 2 succeeded in 1 usecs
[ 137.254097] [drm] ring test on 3 succeeded in 5 usecs
[ 137.254105] [drm] ring test on 4 succeeded in 5 usecs
[ 137.429787] [drm] ring test on 5 succeeded in 2 usecs
[ 137.429792] [drm] UVD initialized successfully.
[ 137.429843] [drm] ib test on ring 0 succeeded in 0 usecs
[ 137.429889] [drm] ib test on ring 1 succeeded in 0 usecs
[ 137.429934] [drm] ib test on ring 2 succeeded in 0 usecs
[ 137.429977] [drm] ib test on ring 3 succeeded in 0 usecs
[ 137.430021] [drm] ib test on ring 4 succeeded in 0 usecs
[ 138.107123] [drm] ib test on ring 5 succeeded
[ 139.027561] ACPI: EC: interrupt blocked
[ 139.067824] ACPI: Preparing to enter system sleep state S3
[ 139.070169] ACPI: EC: event blocked
[ 139.070170] ACPI: EC: EC stopped
[ 139.070172] PM: Saving platform NVS memory
[ 139.070190] Disabling non-boot CPUs ...
[ 139.070688] irq_migrate_all_off_this_cpu: 5 callbacks suppressed
[ 139.070691] IRQ 42: no longer affine to CPU1
[ 139.070698] IRQ 43: no longer affine to CPU1
[ 139.070705] IRQ 45: no longer affine to CPU1
[ 139.070713] IRQ 50: no longer affine to CPU1
[ 139.070719] IRQ 51: no longer affine to CPU1
[ 139.072626] smpboot: CPU 1 is now offline
[ 139.073667] IRQ 53: no longer affine to CPU2
[ 139.074689] smpboot: CPU 2 is now offline
[ 139.076006] IRQ 1: no longer affine to CPU3
[ 139.076013] IRQ 8: no longer affine to CPU3
[ 139.076017] IRQ 9: no longer affine to CPU3
[ 139.076022] IRQ 12: no longer affine to CPU3
[ 139.077062] smpboot: CPU 3 is now offline
[ 139.079093] ACPI: Low-level resume complete
[ 139.079199] ACPI: EC: EC started
[ 139.079201] PM: Restoring platform NVS memory
[ 139.086013] Enabling non-boot CPUs ...
[ 139.086111] x86: Booting SMP configuration:
[ 139.086114] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 139.088429] CPU1 is up
[ 139.088507] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 139.094759] CPU2 is up
[ 139.094820] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 139.096582] CPU3 is up
[ 139.100117] ACPI: Waking up from system sleep state S3
[ 139.240985] ACPI: EC: interrupt unblocked
[ 139.354665] ACPI: EC: event unblocked
[ 139.358374] sd 0:0:0:0: [sda] Starting disk
[ 139.370787] [drm] PCIE gen 2 link speeds already enabled
[ 139.380867] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 139.380960] radeon 0000:03:00.0: WB enabled
[ 139.380961] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 139.380962] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 139.380963] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 139.380964] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 139.380965] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 139.381803] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 139.482569] radeon 0000:03:00.0: failed VCE resume (-110).
[ 139.645301] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 139.675546] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 139.682220] ata1.00: supports DRM functions and may not be fully accessible
[ 139.716719] [drm] ring test on 0 succeeded in 1 usecs
[ 139.716724] [drm] ring test on 1 succeeded in 1 usecs
[ 139.716729] [drm] ring test on 2 succeeded in 1 usecs
[ 139.716738] [drm] ring test on 3 succeeded in 5 usecs
[ 139.716746] [drm] ring test on 4 succeeded in 5 usecs
[ 139.730748] ata1.00: ATA Identify Device Log not supported
[ 139.730749] ata1.00: Security Log not supported
[ 139.779570] ata1.00: supports DRM functions and may not be fully accessible
[ 139.828221] ata1.00: ATA Identify Device Log not supported
[ 139.828222] ata1.00: Security Log not supported
[ 139.828224] ata1.00: configured for UDMA/100
[ 139.873303] usb 2-3.2: reset full-speed USB device number 4 using xhci_hcd
[ 139.892715] [drm] ring test on 5 succeeded in 2 usecs
[ 139.892721] [drm] UVD initialized successfully.
[ 139.892785] [drm] ib test on ring 0 succeeded in 0 usecs
[ 139.892850] [drm] ib test on ring 1 succeeded in 0 usecs
[ 139.892926] [drm] ib test on ring 2 succeeded in 0 usecs
[ 139.892980] [drm] ib test on ring 3 succeeded in 0 usecs
[ 139.893023] [drm] ib test on ring 4 succeeded in 0 usecs
[ 140.573268] [drm] ib test on ring 5 succeeded
[ 140.941885] tpm tpm0: tpm_try_transmit: send(): error -5
[ 140.952149] acpi LNXPOWER:02: Turning OFF
[ 140.952214] acpi LNXPOWER:01: Turning OFF
[ 140.952256] OOM killer enabled.
[ 140.952257] Restarting tasks ...
[ 140.952433] acpi PNP0501:00: Still not present
[ 140.953050] done.
[ 140.969200] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 140.969204] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 140.971196] Bluetooth: hci0: sending Intel patch command (0xfc8e) failed (-16)
[ 140.977133] usb 2-3.2: USB disconnect, device number 4
[ 141.034495] PM: suspend exit
[ 141.193736] e1000e: enp0s25 NIC Link is Down
[ 142.320662] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 142.354225] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 142.973317] Bluetooth: hci0: Exiting manufacturer mode failed (-110)
[ 142.973321] Bluetooth: hci0: command 0xfc11 tx timeout
[ 143.261354] usb 2-3.2: new full-speed USB device number 8 using xhci_hcd
[ 143.363390] usb 2-3.2: New USB device found, idVendor=8087, idProduct=07dc, bcdDevice= 0.01
[ 143.363394] usb 2-3.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 143.372219] Bluetooth: hci0: unexpected event for opcode 0xfc11
[ 145.405426] Bluetooth: hci0: command 0xfc05 tx timeout
[ 145.405431] Bluetooth: hci0: Reading Intel version information failed (-110)
[ 145.535740] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 145.535782] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 147.421518] Bluetooth: hci0: command 0x0c03 tx timeout
[ 148.122192] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 148.125506] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 148.128140] wlo1: authenticated
[ 148.129567] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 148.134895] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=8)
[ 148.136495] wlo1: associated
[ 148.172360] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 155.517826] Bluetooth: hci0: sending initial HCI reset command failed (-110)
Bus 002 Device 004: ID 8087:07dc Intel Corp.
Couldn't open device, some information will be missing
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 224 Wireless
bDeviceSubClass 1 Radio Frequency
bDeviceProtocol 1 Bluetooth
bMaxPacketSize0 64
idVendor 0x8087 Intel Corp.
idProduct 0x07dc
bcdDevice 0.01
iManufacturer 0
iProduct 0
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 177
bNumInterfaces 2
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 3
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x02 EP 2 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0000 1x 0 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0000 1x 0 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 1
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0009 1x 9 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0009 1x 9 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 2
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0011 1x 17 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0011 1x 17 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 3
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0019 1x 25 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0019 1x 25 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 4
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0021 1x 33 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0021 1x 33 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 5
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0031 1x 49 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0031 1x 49 bytes
bInterval 1
Thanks,
Paul
I reported this regression last week (see
https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
but I got no response to my email. Today I have retested with 5.5-rc7
and verified that the problem still exists. So I am resending with a
different subject line to see if anyone responds.
The $subject patch causes a regression on my HP EliteBook laptop with a
built-in USB bluetooth adapter. About 50% of the time, a suspend/resume
cycle will cause the bluetooth adapter to stop working.
The dmesg log below shows two suspend/resume cycles. At time 63.928 you can
see the bluetooth adapter being successfully resumed, and at time 140.969
you can see it fail. After reverting the patch, the bluetooth adapter
resumes 100% of the time.
I also included below a lsusb -v of the bluetooth adapter. Is there any
other debugging info you'd like me to send?
This misbehavior goes back at least to 5.5-rc1.
[ 49.249536] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 59.300552] PM: suspend entry (deep)
[ 59.305440] Filesystems sync: 0.004 seconds
[ 59.305859] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 59.307450] OOM killer disabled.
[ 59.307451] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 59.308604] printk: Suspending console(s) (use no_console_suspend to debug)
[ 59.343478] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 59.344508] sd 0:0:0:0: [sda] Stopping disk
[ 59.424472] e1000e: EEE TX LPI TIMER: 00000011
[ 59.852914] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 59.876708] [drm] PCIE gen 2 link speeds already enabled
[ 59.886714] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 59.886808] radeon 0000:03:00.0: WB enabled
[ 59.886810] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 59.886810] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 59.886811] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 59.886812] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 59.886813] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 59.887627] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 59.988072] radeon 0000:03:00.0: failed VCE resume (-110).
[ 60.220341] [drm] ring test on 0 succeeded in 1 usecs
[ 60.220346] [drm] ring test on 1 succeeded in 1 usecs
[ 60.220351] [drm] ring test on 2 succeeded in 1 usecs
[ 60.220359] [drm] ring test on 3 succeeded in 5 usecs
[ 60.220367] [drm] ring test on 4 succeeded in 5 usecs
[ 60.396050] [drm] ring test on 5 succeeded in 2 usecs
[ 60.396056] [drm] UVD initialized successfully.
[ 60.396117] [drm] ib test on ring 0 succeeded in 0 usecs
[ 60.396179] [drm] ib test on ring 1 succeeded in 0 usecs
[ 60.396225] [drm] ib test on ring 2 succeeded in 0 usecs
[ 60.396267] [drm] ib test on ring 3 succeeded in 0 usecs
[ 60.396321] [drm] ib test on ring 4 succeeded in 0 usecs
[ 61.075516] [drm] ib test on ring 5 succeeded
[ 61.987920] ACPI: EC: interrupt blocked
[ 62.031807] ACPI: Preparing to enter system sleep state S3
[ 62.034281] ACPI: EC: event blocked
[ 62.034282] ACPI: EC: EC stopped
[ 62.034282] PM: Saving platform NVS memory
[ 62.034294] Disabling non-boot CPUs ...
[ 62.034559] IRQ 42: no longer affine to CPU1
[ 62.034562] IRQ 43: no longer affine to CPU1
[ 62.034566] IRQ 45: no longer affine to CPU1
[ 62.034569] IRQ 46: no longer affine to CPU1
[ 62.034573] IRQ 51: no longer affine to CPU1
[ 62.035897] smpboot: CPU 1 is now offline
[ 62.036390] IRQ 53: no longer affine to CPU2
[ 62.037397] smpboot: CPU 2 is now offline
[ 62.037937] IRQ 1: no longer affine to CPU3
[ 62.037940] IRQ 8: no longer affine to CPU3
[ 62.037942] IRQ 9: no longer affine to CPU3
[ 62.037944] IRQ 12: no longer affine to CPU3
[ 62.038958] smpboot: CPU 3 is now offline
[ 62.040172] ACPI: Low-level resume complete
[ 62.040270] ACPI: EC: EC started
[ 62.040271] PM: Restoring platform NVS memory
[ 62.047040] Enabling non-boot CPUs ...
[ 62.047141] x86: Booting SMP configuration:
[ 62.047144] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 62.049459] CPU1 is up
[ 62.049539] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 62.055736] CPU2 is up
[ 62.055797] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 62.057475] CPU3 is up
[ 62.060610] ACPI: Waking up from system sleep state S3
[ 62.202438] ACPI: EC: interrupt unblocked
[ 62.313530] ACPI: EC: event unblocked
[ 62.324891] sd 0:0:0:0: [sda] Starting disk
[ 62.327013] [drm] PCIE gen 2 link speeds already enabled
[ 62.337552] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 62.337645] radeon 0000:03:00.0: WB enabled
[ 62.337647] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 62.337648] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 62.337648] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 62.337649] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 62.337650] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 62.338447] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 62.439210] radeon 0000:03:00.0: failed VCE resume (-110).
[ 62.609068] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 62.635003] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 62.643521] ata1.00: supports DRM functions and may not be fully accessible
[ 62.673227] [drm] ring test on 0 succeeded in 1 usecs
[ 62.673232] [drm] ring test on 1 succeeded in 1 usecs
[ 62.673237] [drm] ring test on 2 succeeded in 1 usecs
[ 62.673246] [drm] ring test on 3 succeeded in 5 usecs
[ 62.673253] [drm] ring test on 4 succeeded in 5 usecs
[ 62.692012] ata1.00: ATA Identify Device Log not supported
[ 62.692013] ata1.00: Security Log not supported
[ 62.740856] ata1.00: supports DRM functions and may not be fully accessible
[ 62.789506] ata1.00: ATA Identify Device Log not supported
[ 62.789506] ata1.00: Security Log not supported
[ 62.789509] ata1.00: configured for UDMA/100
[ 62.837092] usb 2-3.2: reset full-speed USB device number 4 using xhci_hcd
[ 62.849223] [drm] ring test on 5 succeeded in 2 usecs
[ 62.849228] [drm] UVD initialized successfully.
[ 62.849290] [drm] ib test on ring 0 succeeded in 0 usecs
[ 62.849355] [drm] ib test on ring 1 succeeded in 0 usecs
[ 62.849414] [drm] ib test on ring 2 succeeded in 0 usecs
[ 62.849461] [drm] ib test on ring 3 succeeded in 0 usecs
[ 62.849514] [drm] ib test on ring 4 succeeded in 0 usecs
[ 63.509106] [drm] ib test on ring 5 succeeded
[ 63.901356] tpm tpm0: tpm_try_transmit: send(): error -5
[ 63.906084] acpi LNXPOWER:02: Turning OFF
[ 63.906128] acpi LNXPOWER:01: Turning OFF
[ 63.906162] OOM killer enabled.
[ 63.906163] Restarting tasks ...
[ 63.906304] acpi PNP0501:00: Still not present
[ 63.910752] done.
[ 63.928642] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 63.928646] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 63.985337] PM: suspend exit
[ 64.035638] Bluetooth: hci0: unexpected event for opcode 0xfc2f
[ 64.051657] Bluetooth: hci0: Intel firmware patch completed and activated
[ 64.161465] e1000e: enp0s25 NIC Link is Down
[ 65.270730] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 65.305008] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 68.471403] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 68.471457] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 71.144846] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 71.149124] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 71.153318] wlo1: authenticated
[ 71.157026] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 71.160772] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=8)
[ 71.162365] wlo1: associated
[ 71.197208] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 126.321068] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 136.367748] PM: suspend entry (deep)
[ 136.377378] Filesystems sync: 0.009 seconds
[ 136.378191] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 136.381154] OOM killer disabled.
[ 136.381155] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 136.382553] printk: Suspending console(s) (use no_console_suspend to debug)
[ 136.411098] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 136.412116] sd 0:0:0:0: [sda] Stopping disk
[ 136.477379] e1000e: EEE TX LPI TIMER: 00000011
[ 136.883799] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 136.909481] [drm] PCIE gen 2 link speeds already enabled
[ 136.920054] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 136.920147] radeon 0000:03:00.0: WB enabled
[ 136.920148] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 136.920149] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 136.920150] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 136.920151] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 136.920152] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 136.920945] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 137.021396] radeon 0000:03:00.0: failed VCE resume (-110).
[ 137.254078] [drm] ring test on 0 succeeded in 1 usecs
[ 137.254083] [drm] ring test on 1 succeeded in 1 usecs
[ 137.254088] [drm] ring test on 2 succeeded in 1 usecs
[ 137.254097] [drm] ring test on 3 succeeded in 5 usecs
[ 137.254105] [drm] ring test on 4 succeeded in 5 usecs
[ 137.429787] [drm] ring test on 5 succeeded in 2 usecs
[ 137.429792] [drm] UVD initialized successfully.
[ 137.429843] [drm] ib test on ring 0 succeeded in 0 usecs
[ 137.429889] [drm] ib test on ring 1 succeeded in 0 usecs
[ 137.429934] [drm] ib test on ring 2 succeeded in 0 usecs
[ 137.429977] [drm] ib test on ring 3 succeeded in 0 usecs
[ 137.430021] [drm] ib test on ring 4 succeeded in 0 usecs
[ 138.107123] [drm] ib test on ring 5 succeeded
[ 139.027561] ACPI: EC: interrupt blocked
[ 139.067824] ACPI: Preparing to enter system sleep state S3
[ 139.070169] ACPI: EC: event blocked
[ 139.070170] ACPI: EC: EC stopped
[ 139.070172] PM: Saving platform NVS memory
[ 139.070190] Disabling non-boot CPUs ...
[ 139.070688] irq_migrate_all_off_this_cpu: 5 callbacks suppressed
[ 139.070691] IRQ 42: no longer affine to CPU1
[ 139.070698] IRQ 43: no longer affine to CPU1
[ 139.070705] IRQ 45: no longer affine to CPU1
[ 139.070713] IRQ 50: no longer affine to CPU1
[ 139.070719] IRQ 51: no longer affine to CPU1
[ 139.072626] smpboot: CPU 1 is now offline
[ 139.073667] IRQ 53: no longer affine to CPU2
[ 139.074689] smpboot: CPU 2 is now offline
[ 139.076006] IRQ 1: no longer affine to CPU3
[ 139.076013] IRQ 8: no longer affine to CPU3
[ 139.076017] IRQ 9: no longer affine to CPU3
[ 139.076022] IRQ 12: no longer affine to CPU3
[ 139.077062] smpboot: CPU 3 is now offline
[ 139.079093] ACPI: Low-level resume complete
[ 139.079199] ACPI: EC: EC started
[ 139.079201] PM: Restoring platform NVS memory
[ 139.086013] Enabling non-boot CPUs ...
[ 139.086111] x86: Booting SMP configuration:
[ 139.086114] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 139.088429] CPU1 is up
[ 139.088507] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 139.094759] CPU2 is up
[ 139.094820] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 139.096582] CPU3 is up
[ 139.100117] ACPI: Waking up from system sleep state S3
[ 139.240985] ACPI: EC: interrupt unblocked
[ 139.354665] ACPI: EC: event unblocked
[ 139.358374] sd 0:0:0:0: [sda] Starting disk
[ 139.370787] [drm] PCIE gen 2 link speeds already enabled
[ 139.380867] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 139.380960] radeon 0000:03:00.0: WB enabled
[ 139.380961] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x000000000c629f9f
[ 139.380962] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x00000000dee9b232
[ 139.380963] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x00000000eddb39fc
[ 139.380964] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000004e1d27c
[ 139.380965] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x0000000043709b8a
[ 139.381803] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000fa6308aa
[ 139.482569] radeon 0000:03:00.0: failed VCE resume (-110).
[ 139.645301] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 139.675546] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 139.682220] ata1.00: supports DRM functions and may not be fully accessible
[ 139.716719] [drm] ring test on 0 succeeded in 1 usecs
[ 139.716724] [drm] ring test on 1 succeeded in 1 usecs
[ 139.716729] [drm] ring test on 2 succeeded in 1 usecs
[ 139.716738] [drm] ring test on 3 succeeded in 5 usecs
[ 139.716746] [drm] ring test on 4 succeeded in 5 usecs
[ 139.730748] ata1.00: ATA Identify Device Log not supported
[ 139.730749] ata1.00: Security Log not supported
[ 139.779570] ata1.00: supports DRM functions and may not be fully accessible
[ 139.828221] ata1.00: ATA Identify Device Log not supported
[ 139.828222] ata1.00: Security Log not supported
[ 139.828224] ata1.00: configured for UDMA/100
[ 139.873303] usb 2-3.2: reset full-speed USB device number 4 using xhci_hcd
[ 139.892715] [drm] ring test on 5 succeeded in 2 usecs
[ 139.892721] [drm] UVD initialized successfully.
[ 139.892785] [drm] ib test on ring 0 succeeded in 0 usecs
[ 139.892850] [drm] ib test on ring 1 succeeded in 0 usecs
[ 139.892926] [drm] ib test on ring 2 succeeded in 0 usecs
[ 139.892980] [drm] ib test on ring 3 succeeded in 0 usecs
[ 139.893023] [drm] ib test on ring 4 succeeded in 0 usecs
[ 140.573268] [drm] ib test on ring 5 succeeded
[ 140.941885] tpm tpm0: tpm_try_transmit: send(): error -5
[ 140.952149] acpi LNXPOWER:02: Turning OFF
[ 140.952214] acpi LNXPOWER:01: Turning OFF
[ 140.952256] OOM killer enabled.
[ 140.952257] Restarting tasks ...
[ 140.952433] acpi PNP0501:00: Still not present
[ 140.953050] done.
[ 140.969200] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 140.969204] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 140.971196] Bluetooth: hci0: sending Intel patch command (0xfc8e) failed (-16)
[ 140.977133] usb 2-3.2: USB disconnect, device number 4
[ 141.034495] PM: suspend exit
[ 141.193736] e1000e: enp0s25 NIC Link is Down
[ 142.320662] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 142.354225] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 142.973317] Bluetooth: hci0: Exiting manufacturer mode failed (-110)
[ 142.973321] Bluetooth: hci0: command 0xfc11 tx timeout
[ 143.261354] usb 2-3.2: new full-speed USB device number 8 using xhci_hcd
[ 143.363390] usb 2-3.2: New USB device found, idVendor=8087, idProduct=07dc, bcdDevice= 0.01
[ 143.363394] usb 2-3.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 143.372219] Bluetooth: hci0: unexpected event for opcode 0xfc11
[ 145.405426] Bluetooth: hci0: command 0xfc05 tx timeout
[ 145.405431] Bluetooth: hci0: Reading Intel version information failed (-110)
[ 145.535740] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 145.535782] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 147.421518] Bluetooth: hci0: command 0x0c03 tx timeout
[ 148.122192] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 148.125506] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 148.128140] wlo1: authenticated
[ 148.129567] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 148.134895] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=8)
[ 148.136495] wlo1: associated
[ 148.172360] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 155.517826] Bluetooth: hci0: sending initial HCI reset command failed (-110)
Bus 002 Device 004: ID 8087:07dc Intel Corp.
Couldn't open device, some information will be missing
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 224 Wireless
bDeviceSubClass 1 Radio Frequency
bDeviceProtocol 1 Bluetooth
bMaxPacketSize0 64
idVendor 0x8087 Intel Corp.
idProduct 0x07dc
bcdDevice 0.01
iManufacturer 0
iProduct 0
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 177
bNumInterfaces 2
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 100mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 3
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x02 EP 2 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0000 1x 0 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0000 1x 0 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 1
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0009 1x 9 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0009 1x 9 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 2
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0011 1x 17 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0011 1x 17 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 3
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0019 1x 25 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0019 1x 25 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 4
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0021 1x 33 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0021 1x 33 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 5
bNumEndpoints 2
bInterfaceClass 224 Wireless
bInterfaceSubClass 1 Radio Frequency
bInterfaceProtocol 1 Bluetooth
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0031 1x 49 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 1
Transfer Type Isochronous
Synch Type None
Usage Type Data
wMaxPacketSize 0x0031 1x 49 bytes
bInterval 1
Thanks,
Paul
On Sun, 19 Jan 2020, Paul Zimmerman wrote:
> I reported this regression last week (see
> https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
> but I got no response to my email. Today I have retested with 5.5-rc7
> and verified that the problem still exists. So I am resending with a
> different subject line to see if anyone responds.
>
> The $subject patch causes a regression on my HP EliteBook laptop with a
> built-in USB bluetooth adapter. About 50% of the time, a suspend/resume
> cycle will cause the bluetooth adapter to stop working.
>
> The dmesg log below shows two suspend/resume cycles. At time 63.928 you can
> see the bluetooth adapter being successfully resumed, and at time 140.969
> you can see it fail. After reverting the patch, the bluetooth adapter
> resumes 100% of the time.
>
> I also included below a lsusb -v of the bluetooth adapter. Is there any
> other debugging info you'd like me to send?
It looks like your dmesg log was made without enabling debugging
messages in usbcore. Can you collect another log with debugging
messages turned on?
echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
Also, it might not hurt to collect and post a usbmon trace for a bad
suspend-resume cycle.
Alan Stern
On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern <[email protected]> wrote:
> On Sun, 19 Jan 2020, Paul Zimmerman wrote:
>
> > I reported this regression last week (see
> > https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
> > but I got no response to my email. Today I have retested with
> > 5.5-rc7 and verified that the problem still exists. So I am
> > resending with a different subject line to see if anyone responds.
> >
> > The $subject patch causes a regression on my HP EliteBook laptop
> > with a built-in USB bluetooth adapter. About 50% of the time, a
> > suspend/resume cycle will cause the bluetooth adapter to stop
> > working.
> >
> > The dmesg log below shows two suspend/resume cycles. At time 63.928
> > you can see the bluetooth adapter being successfully resumed, and
> > at time 140.969 you can see it fail. After reverting the patch, the
> > bluetooth adapter resumes 100% of the time.
> >
> > I also included below a lsusb -v of the bluetooth adapter. Is there
> > any other debugging info you'd like me to send?
>
> It looks like your dmesg log was made without enabling debugging
> messages in usbcore. Can you collect another log with debugging
> messages turned on?
>
> echo 'module usbcore =p'
> >/sys/kernel/debug/dynamic_debug/control
>
> Also, it might not hurt to collect and post a usbmon trace for a bad
> suspend-resume cycle.
Hi Alan,
Thanks for responding. The new dmesg log and the usbmon trace are below.
The dmesg shows a good suspend/resume followed by a bad one. The
bluetooth device is usb 2-3.2 I believe. The usbmon trace is only for
the failed suspend/resume case.
[ 1235.712529] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 1245.764338] PM: suspend entry (deep)
[ 1245.774056] Filesystems sync: 0.009 seconds
[ 1245.774884] Freezing user space processes ... (elapsed 0.003 seconds) done.
[ 1245.778388] OOM killer disabled.
[ 1245.778390] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 1245.779934] printk: Suspending console(s) (use no_console_suspend to debug)
[ 1245.780920] usb 2-5: usb suspend, wakeup 0
[ 1245.780947] usb usb3: usb auto-resume
[ 1245.780968] hub 3-0:1.0: hub_resume
[ 1245.781038] usb usb3-port3: status 0263 change 0000
[ 1245.781062] usb usb1: usb auto-resume
[ 1245.781086] hub 1-0:1.0: hub_resume
[ 1245.781111] usb usb1-port1: status 0507 change 0000
[ 1245.781219] usb 1-1: usb auto-resume
[ 1245.795011] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 1245.796132] sd 0:0:0:0: [sda] Stopping disk
[ 1245.806970] usb 3-3: usb auto-resume
[ 1245.827005] usb 2-3: usb auto-resume
[ 1245.847092] usb 1-1: Waited 0ms for CONNECT
[ 1245.847100] usb 1-1: finish resume
[ 1245.847368] hub 1-1:1.0: hub_resume
[ 1245.848381] hub 1-1:1.0: hub_suspend
[ 1245.850120] usb 1-1: usb suspend, wakeup 0
[ 1245.850153] hub 1-0:1.0: hub_suspend
[ 1245.850197] usb usb1: bus suspend, wakeup 0
[ 1245.873393] e1000e: EEE TX LPI TIMER: 00000011
[ 1245.874977] usb 3-3: Waited 0ms for CONNECT
[ 1245.874983] usb 3-3: finish resume
[ 1245.875803] hub 3-3:1.0: hub_resume
[ 1245.876840] hub 3-3:1.0: hub_suspend
[ 1245.898946] usb 2-3: Waited 0ms for CONNECT
[ 1245.898949] usb 2-3: finish resume
[ 1245.899039] hub 2-3:1.0: hub_resume
[ 1245.899127] usb 2-3-port2: status 0101 change 0000
[ 1245.899194] hub 2-3:1.0: hub_suspend
[ 1245.899236] usb 2-3: usb suspend, wakeup 0
[ 1245.899246] hub 2-0:1.0: hub_suspend
[ 1245.899260] usb usb2: bus suspend, wakeup 0
[ 1245.902913] usb 3-3: usb suspend, wakeup 0
[ 1245.923026] hub 3-0:1.0: hub_suspend
[ 1245.923076] usb usb3: bus suspend, wakeup 0
[ 1246.280222] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 1246.309024] [drm] PCIE gen 2 link speeds already enabled
[ 1246.319037] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 1246.319133] radeon 0000:03:00.0: WB enabled
[ 1246.319135] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x0000000067be349a
[ 1246.319136] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x0000000057315ff0
[ 1246.319137] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x000000001e461818
[ 1246.319138] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000058e3f68e
[ 1246.319139] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x000000004beb9f61
[ 1246.319932] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000a33a1135
[ 1246.420369] radeon 0000:03:00.0: failed VCE resume (-110).
[ 1246.652894] [drm] ring test on 0 succeeded in 1 usecs
[ 1246.652899] [drm] ring test on 1 succeeded in 1 usecs
[ 1246.652904] [drm] ring test on 2 succeeded in 1 usecs
[ 1246.652913] [drm] ring test on 3 succeeded in 5 usecs
[ 1246.652921] [drm] ring test on 4 succeeded in 5 usecs
[ 1246.828587] [drm] ring test on 5 succeeded in 2 usecs
[ 1246.828592] [drm] UVD initialized successfully.
[ 1246.828652] [drm] ib test on ring 0 succeeded in 0 usecs
[ 1246.828716] [drm] ib test on ring 1 succeeded in 0 usecs
[ 1246.828773] [drm] ib test on ring 2 succeeded in 0 usecs
[ 1246.828822] [drm] ib test on ring 3 succeeded in 0 usecs
[ 1246.828875] [drm] ib test on ring 4 succeeded in 0 usecs
[ 1247.503113] [drm] ib test on ring 5 succeeded
[ 1248.415476] ACPI: EC: interrupt blocked
[ 1248.419491] ehci-pci 0000:00:1d.0: wakeup: 1
[ 1248.419739] xhci_hcd 0000:00:14.0: wakeup: 1
[ 1248.439187] ehci-pci 0000:00:1d.0: --> PCI D3hot
[ 1248.439911] xhci_hcd 0000:00:14.0: --> PCI D3hot
[ 1248.459698] ACPI: Preparing to enter system sleep state S3
[ 1248.462575] ACPI: EC: event blocked
[ 1248.462576] ACPI: EC: EC stopped
[ 1248.462577] PM: Saving platform NVS memory
[ 1248.462595] Disabling non-boot CPUs ...
[ 1248.463112] irq_migrate_all_off_this_cpu: 5 callbacks suppressed
[ 1248.463115] IRQ 42: no longer affine to CPU1
[ 1248.463122] IRQ 43: no longer affine to CPU1
[ 1248.463129] IRQ 45: no longer affine to CPU1
[ 1248.463135] IRQ 46: no longer affine to CPU1
[ 1248.463142] IRQ 50: no longer affine to CPU1
[ 1248.463147] IRQ 51: no longer affine to CPU1
[ 1248.464200] smpboot: CPU 1 is now offline
[ 1248.465679] IRQ 53: no longer affine to CPU2
[ 1248.467608] smpboot: CPU 2 is now offline
[ 1248.468470] IRQ 1: no longer affine to CPU3
[ 1248.468476] IRQ 8: no longer affine to CPU3
[ 1248.468480] IRQ 9: no longer affine to CPU3
[ 1248.469542] smpboot: CPU 3 is now offline
[ 1248.471041] ACPI: Low-level resume complete
[ 1248.471147] ACPI: EC: EC started
[ 1248.471148] PM: Restoring platform NVS memory
[ 1248.477905] Enabling non-boot CPUs ...
[ 1248.478010] x86: Booting SMP configuration:
[ 1248.478012] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 1248.480324] CPU1 is up
[ 1248.480405] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 1248.486595] CPU2 is up
[ 1248.486653] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 1248.488352] CPU3 is up
[ 1248.491870] ACPI: Waking up from system sleep state S3
[ 1248.633481] ACPI: EC: interrupt unblocked
[ 1248.746351] ACPI: EC: event unblocked
[ 1248.746891] usb usb2: usb resume
[ 1248.747065] usb usb3: usb resume
[ 1248.747083] hub 3-0:1.0: hub_resume
[ 1248.747149] usb usb3-port3: status 0263 change 0000
[ 1248.749813] usb usb1: usb resume
[ 1248.750514] sd 0:0:0:0: [sda] Starting disk
[ 1248.761789] [drm] PCIE gen 2 link speeds already enabled
[ 1248.771990] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 1248.772082] radeon 0000:03:00.0: WB enabled
[ 1248.772084] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x0000000067be349a
[ 1248.772085] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x0000000057315ff0
[ 1248.772085] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x000000001e461818
[ 1248.772086] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000058e3f68e
[ 1248.772087] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x000000004beb9f61
[ 1248.772907] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000a33a1135
[ 1248.780678] usb 3-3: usb resume
[ 1248.803705] hub 2-0:1.0: hub_resume
[ 1248.803731] usb usb2-port3: status 0503 change 0000
[ 1248.803742] usb usb2-port5: status 0101 change 0001
[ 1248.803764] usb usb2-port8: status 0101 change 0001
[ 1248.811674] hub 1-0:1.0: hub_resume
[ 1248.811684] usb usb1-port1: status 0503 change 0000
[ 1248.811714] usb 1-1: Waited 0ms for CONNECT
[ 1248.811715] usb 1-1: finish resume
[ 1248.811856] hub 1-1:1.0: hub_resume
[ 1248.848681] usb 3-3: Waited 0ms for CONNECT
[ 1248.848682] usb 3-3: finish resume
[ 1248.849265] hub 3-3:1.0: hub_resume
[ 1248.873684] radeon 0000:03:00.0: failed VCE resume (-110).
[ 1248.908694] usb 2-3: Waited 0ms for CONNECT
[ 1248.908696] usb 2-3: finish resume
[ 1248.908701] usb 2-5: Waited 0ms for CONNECT
[ 1248.908703] usb 2-5: finish reset-resume
[ 1248.908729] hub 2-3:1.0: hub_resume
[ 1248.908817] usb 2-3-port2: status 0101 change 0001
[ 1249.036846] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 1249.063115] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 1249.064338] ata1.00: supports DRM functions and may not be fully accessible
[ 1249.109274] [drm] ring test on 0 succeeded in 1 usecs
[ 1249.109279] [drm] ring test on 1 succeeded in 1 usecs
[ 1249.109284] [drm] ring test on 2 succeeded in 1 usecs
[ 1249.109293] [drm] ring test on 3 succeeded in 5 usecs
[ 1249.109301] [drm] ring test on 4 succeeded in 5 usecs
[ 1249.112864] ata1.00: ATA Identify Device Log not supported
[ 1249.112864] ata1.00: Security Log not supported
[ 1249.161705] ata1.00: supports DRM functions and may not be fully accessible
[ 1249.184676] usb 2-5: ep0 maxpacket = 8
[ 1249.210351] ata1.00: ATA Identify Device Log not supported
[ 1249.210352] ata1.00: Security Log not supported
[ 1249.210355] ata1.00: configured for UDMA/100
[ 1249.285285] [drm] ring test on 5 succeeded in 1 usecs
[ 1249.285290] [drm] UVD initialized successfully.
[ 1249.285346] [drm] ib test on ring 0 succeeded in 0 usecs
[ 1249.285395] [drm] ib test on ring 1 succeeded in 0 usecs
[ 1249.285443] [drm] ib test on ring 2 succeeded in 0 usecs
[ 1249.285487] [drm] ib test on ring 3 succeeded in 0 usecs
[ 1249.285543] [drm] ib test on ring 4 succeeded in 0 usecs
[ 1249.936824] [drm] ib test on ring 5 succeeded
[ 1250.341517] tpm tpm0: tpm_try_transmit: send(): error -5
[ 1250.352206] acpi LNXPOWER:02: Turning OFF
[ 1250.352269] acpi LNXPOWER:01: Turning OFF
[ 1250.352307] OOM killer enabled.
[ 1250.352308] Restarting tasks ...
[ 1250.352431] hub 3-0:1.0: state 7 ports 4 chg 0000 evt 0008
[ 1250.352433] hub 2-3:1.0: state 7 ports 4 chg 0004 evt 0000
[ 1250.352453] hub 1-0:1.0: state 7 ports 3 chg 0000 evt 0000
[ 1250.352457] hub 2-0:1.0: state 7 ports 9 chg 0120 evt 0008
[ 1250.352465] hub 3-3:1.0: state 7 ports 4 chg 0000 evt 0000
[ 1250.352474] acpi PNP0501:00: Still not present
[ 1250.352644] hub 1-1:1.0: state 7 ports 8 chg 0120 evt 0000
[ 1250.353658] usb usb2-port5: status 0103, change 0000, 12 Mb/s
[ 1250.354135] done.
[ 1250.354599] usb 2-3-port2: status 0101, change 0000, 12 Mb/s
[ 1250.356441] hub 3-3:1.0: hub_suspend
[ 1250.356474] usb usb2-port8: status 0101, change 0000, 12 Mb/s
[ 1250.361270] usb 1-1-port5: status 0100, change 0000, 12 Mb/s
[ 1250.361464] usb 1-1-port8: status 0100, change 0000, 12 Mb/s
[ 1250.361472] hub 1-1:1.0: hub_suspend
[ 1250.363749] usb 1-1: usb auto-suspend, wakeup 1
[ 1250.380707] hub 1-0:1.0: hub_suspend
[ 1250.380716] usb usb1: bus auto-suspend, wakeup 1
[ 1250.392694] usb 3-3: usb auto-suspend, wakeup 1
[ 1250.412743] hub 3-0:1.0: hub_suspend
[ 1250.412754] usb usb3: bus auto-suspend, wakeup 1
[ 1250.432698] usb 2-3.2: new full-speed USB device number 20 using xhci_hcd
[ 1250.438289] PM: suspend exit
[ 1250.537993] usb 2-3.2: udev 20, busnum 2, minor = 147
[ 1250.537995] usb 2-3.2: New USB device found, idVendor=8087, idProduct=07dc, bcdDevice= 0.01
[ 1250.537996] usb 2-3.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1250.538084] usb 2-3.2: usb_probe_device
[ 1250.538087] usb 2-3.2: configuration #1 chosen from 1 choice
[ 1250.545229] usb 2-3.2: adding 2-3.2:1.0 (config #1, interface 0)
[ 1250.545277] btusb 2-3.2:1.0: usb_probe_interface
[ 1250.545280] btusb 2-3.2:1.0: usb_probe_interface - got id
[ 1250.546873] usb 2-3.2: adding 2-3.2:1.1 (config #1, interface 1)
[ 1250.558249] Bluetooth: hci0: read Intel version: 370710018002030d00
[ 1250.558282] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[ 1250.604695] usb usb2-port8: not reset yet, waiting 60ms
[ 1250.613782] e1000e: enp0s25 NIC Link is Down
[ 1250.666242] Bluetooth: hci0: unexpected event for opcode 0xfc2f
[ 1250.672701] usb usb2-port8: not reset yet, waiting 200ms
[ 1250.682244] Bluetooth: hci0: Intel firmware patch completed and activated
[ 1250.880714] usb usb2-port8: not reset yet, waiting 200ms
[ 1251.088702] usb usb2-port8: not reset yet, waiting 200ms
[ 1251.296784] usb usb2-port8: not reset yet, waiting 200ms
[ 1251.296860] hub 2-0:1.0: state 7 ports 9 chg 0000 evt 0100
[ 1251.296873] usb usb2-port8: status 0100, change 0001, 12 Mb/s
[ 1251.440846] usb usb2-port8: debounce total 100ms stable 100ms status 0x100
[ 1251.720031] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 1251.754626] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 1253.662989] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 1253.663021] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 1257.469186] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 1257.473261] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 1257.480321] wlo1: authenticated
[ 1257.480782] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 1257.484530] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=12)
[ 1257.486319] wlo1: associated
[ 1257.514490] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 1306.040671] wlo1: deauthenticating from 58:8b:f3:44:8f:5c by local choice (Reason: 3=DEAUTH_LEAVING)
[ 1316.086506] PM: suspend entry (deep)
[ 1316.099332] Filesystems sync: 0.012 seconds
[ 1316.100109] Freezing user space processes ... (elapsed 0.003 seconds) done.
[ 1316.103470] OOM killer disabled.
[ 1316.103471] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 1316.104968] printk: Suspending console(s) (use no_console_suspend to debug)
[ 1316.105973] usb usb3: usb auto-resume
[ 1316.105994] hub 3-0:1.0: hub_resume
[ 1316.106032] usb 2-5: usb suspend, wakeup 0
[ 1316.106053] usb usb3-port3: status 0263 change 0000
[ 1316.106057] usb usb1: usb auto-resume
[ 1316.106079] hub 1-0:1.0: hub_resume
[ 1316.106110] usb usb1-port1: status 0507 change 0000
[ 1316.106213] usb 1-1: usb auto-resume
[ 1316.111455] usb 2-3.2: usb suspend, wakeup 0
[ 1316.111478] hub 2-3:1.0: hub_suspend
[ 1316.111561] usb 2-3: usb suspend, wakeup 0
[ 1316.121686] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 1316.124238] sd 0:0:0:0: [sda] Stopping disk
[ 1316.133587] usb 3-3: usb auto-resume
[ 1316.153175] hub 2-0:1.0: hub_suspend
[ 1316.153242] usb usb2: bus suspend, wakeup 0
[ 1316.173548] usb 1-1: Waited 0ms for CONNECT
[ 1316.173552] usb 1-1: finish resume
[ 1316.173792] hub 1-1:1.0: hub_resume
[ 1316.174741] hub 1-1:1.0: hub_suspend
[ 1316.176905] usb 1-1: usb suspend, wakeup 0
[ 1316.176962] hub 1-0:1.0: hub_suspend
[ 1316.177009] usb usb1: bus suspend, wakeup 0
[ 1316.200175] e1000e: EEE TX LPI TIMER: 00000011
[ 1316.201557] usb 3-3: Waited 0ms for CONNECT
[ 1316.201563] usb 3-3: finish resume
[ 1316.202218] hub 3-3:1.0: hub_resume
[ 1316.203037] hub 3-3:1.0: hub_suspend
[ 1316.229515] usb 3-3: usb suspend, wakeup 0
[ 1316.249606] hub 3-0:1.0: hub_suspend
[ 1316.249647] usb usb3: bus suspend, wakeup 0
[ 1316.618973] radeon 0000:03:00.0: 16.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x4 link at 0000:00:1c.4 (capable of 63.008 Gb/s with 8 GT/s x8 link)
[ 1316.645911] [drm] PCIE gen 2 link speeds already enabled
[ 1316.655907] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 1316.656001] radeon 0000:03:00.0: WB enabled
[ 1316.656003] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x0000000067be349a
[ 1316.656004] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x0000000057315ff0
[ 1316.656005] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x000000001e461818
[ 1316.656006] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000058e3f68e
[ 1316.656007] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x000000004beb9f61
[ 1316.656800] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000a33a1135
[ 1316.757238] radeon 0000:03:00.0: failed VCE resume (-110).
[ 1316.989936] [drm] ring test on 0 succeeded in 1 usecs
[ 1316.989941] [drm] ring test on 1 succeeded in 1 usecs
[ 1316.989946] [drm] ring test on 2 succeeded in 1 usecs
[ 1316.989955] [drm] ring test on 3 succeeded in 5 usecs
[ 1316.989961] [drm] ring test on 4 succeeded in 4 usecs
[ 1317.165662] [drm] ring test on 5 succeeded in 2 usecs
[ 1317.165668] [drm] UVD initialized successfully.
[ 1317.165717] [drm] ib test on ring 0 succeeded in 0 usecs
[ 1317.165762] [drm] ib test on ring 1 succeeded in 0 usecs
[ 1317.165807] [drm] ib test on ring 2 succeeded in 0 usecs
[ 1317.165850] [drm] ib test on ring 3 succeeded in 0 usecs
[ 1317.165893] [drm] ib test on ring 4 succeeded in 0 usecs
[ 1317.841699] [drm] ib test on ring 5 succeeded
[ 1318.754062] ACPI: EC: interrupt blocked
[ 1318.758954] ehci-pci 0000:00:1d.0: wakeup: 1
[ 1318.759155] xhci_hcd 0000:00:14.0: wakeup: 1
[ 1318.777761] ehci-pci 0000:00:1d.0: --> PCI D3hot
[ 1318.778773] xhci_hcd 0000:00:14.0: --> PCI D3hot
[ 1318.798212] ACPI: Preparing to enter system sleep state S3
[ 1318.801253] ACPI: EC: event blocked
[ 1318.801254] ACPI: EC: EC stopped
[ 1318.801255] PM: Saving platform NVS memory
[ 1318.801272] Disabling non-boot CPUs ...
[ 1318.801706] irq_migrate_all_off_this_cpu: 5 callbacks suppressed
[ 1318.801708] IRQ 42: no longer affine to CPU1
[ 1318.801714] IRQ 43: no longer affine to CPU1
[ 1318.801720] IRQ 45: no longer affine to CPU1
[ 1318.801727] IRQ 51: no longer affine to CPU1
[ 1318.803648] smpboot: CPU 1 is now offline
[ 1318.804671] IRQ 53: no longer affine to CPU2
[ 1318.805698] smpboot: CPU 2 is now offline
[ 1318.807024] IRQ 1: no longer affine to CPU3
[ 1318.807031] IRQ 8: no longer affine to CPU3
[ 1318.807036] IRQ 9: no longer affine to CPU3
[ 1318.807040] IRQ 12: no longer affine to CPU3
[ 1318.807046] IRQ 17: no longer affine to CPU3
[ 1318.808107] smpboot: CPU 3 is now offline
[ 1318.809463] ACPI: Low-level resume complete
[ 1318.809570] ACPI: EC: EC started
[ 1318.809572] PM: Restoring platform NVS memory
[ 1318.816336] Enabling non-boot CPUs ...
[ 1318.816440] x86: Booting SMP configuration:
[ 1318.816443] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 1318.818749] CPU1 is up
[ 1318.818829] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 1318.825049] CPU2 is up
[ 1318.825110] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 1318.826835] CPU3 is up
[ 1318.830400] ACPI: Waking up from system sleep state S3
[ 1318.970931] ACPI: EC: interrupt unblocked
[ 1319.085723] ACPI: EC: event unblocked
[ 1319.086598] usb usb1: usb resume
[ 1319.089935] usb usb2: usb resume
[ 1319.093882] usb usb3: usb resume
[ 1319.093904] hub 3-0:1.0: hub_resume
[ 1319.094030] usb usb3-port3: status 0263 change 0000
[ 1319.094450] sd 0:0:0:0: [sda] Starting disk
[ 1319.102011] [drm] PCIE gen 2 link speeds already enabled
[ 1319.112446] [drm] PCIE GART of 2048M enabled (table at 0x00000000001D6000).
[ 1319.112540] radeon 0000:03:00.0: WB enabled
[ 1319.112542] radeon 0000:03:00.0: fence driver on ring 0 use gpu addr 0x0000000040000c00 and cpu addr 0x0000000067be349a
[ 1319.112543] radeon 0000:03:00.0: fence driver on ring 1 use gpu addr 0x0000000040000c04 and cpu addr 0x0000000057315ff0
[ 1319.112544] radeon 0000:03:00.0: fence driver on ring 2 use gpu addr 0x0000000040000c08 and cpu addr 0x000000001e461818
[ 1319.112544] radeon 0000:03:00.0: fence driver on ring 3 use gpu addr 0x0000000040000c0c and cpu addr 0x0000000058e3f68e
[ 1319.112545] radeon 0000:03:00.0: fence driver on ring 4 use gpu addr 0x0000000040000c10 and cpu addr 0x000000004beb9f61
[ 1319.113348] radeon 0000:03:00.0: fence driver on ring 5 use gpu addr 0x0000000000075a18 and cpu addr 0x00000000a33a1135
[ 1319.119148] usb 3-3: usb resume
[ 1319.142165] hub 1-0:1.0: hub_resume
[ 1319.142179] usb usb1-port1: status 0503 change 0000
[ 1319.142214] usb 1-1: Waited 0ms for CONNECT
[ 1319.142215] usb 1-1: finish resume
[ 1319.142283] hub 1-1:1.0: hub_resume
[ 1319.146148] hub 2-0:1.0: hub_resume
[ 1319.146175] usb usb2-port3: status 0503 change 0000
[ 1319.146188] usb usb2-port5: status 0101 change 0001
[ 1319.146213] usb usb2-port8: status 0101 change 0001
[ 1319.187140] usb 3-3: Waited 0ms for CONNECT
[ 1319.187141] usb 3-3: finish resume
[ 1319.187713] hub 3-3:1.0: hub_resume
[ 1319.214130] radeon 0000:03:00.0: failed VCE resume (-110).
[ 1319.251188] usb 2-5: Waited 0ms for CONNECT
[ 1319.251190] usb 2-5: finish reset-resume
[ 1319.251199] usb 2-3: Waited 0ms for CONNECT
[ 1319.251201] usb 2-3: finish resume
[ 1319.251261] hub 2-3:1.0: hub_resume
[ 1319.251338] usb 2-3-port2: status 0101 change 0001
[ 1319.359171] usb 2-3.2: Waited 0ms for CONNECT
[ 1319.359172] usb 2-3.2: finish reset-resume
[ 1319.379314] usb 2-5: reset full-speed USB device number 3 using xhci_hcd
[ 1319.405650] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 1319.414218] ata1.00: supports DRM functions and may not be fully accessible
[ 1319.450258] [drm] ring test on 0 succeeded in 1 usecs
[ 1319.450263] [drm] ring test on 1 succeeded in 1 usecs
[ 1319.450268] [drm] ring test on 2 succeeded in 1 usecs
[ 1319.450277] [drm] ring test on 3 succeeded in 5 usecs
[ 1319.450283] [drm] ring test on 4 succeeded in 4 usecs
[ 1319.462738] ata1.00: ATA Identify Device Log not supported
[ 1319.462739] ata1.00: Security Log not supported
[ 1319.511570] ata1.00: supports DRM functions and may not be fully accessible
[ 1319.527115] usb 2-5: ep0 maxpacket = 8
[ 1319.560250] ata1.00: ATA Identify Device Log not supported
[ 1319.560251] ata1.00: Security Log not supported
[ 1319.560253] ata1.00: configured for UDMA/100
[ 1319.607328] usb 2-3.2: reset full-speed USB device number 20 using xhci_hcd
[ 1319.626254] [drm] ring test on 5 succeeded in 2 usecs
[ 1319.626260] [drm] UVD initialized successfully.
[ 1319.626329] [drm] ib test on ring 0 succeeded in 0 usecs
[ 1319.626381] [drm] ib test on ring 1 succeeded in 0 usecs
[ 1319.626436] [drm] ib test on ring 2 succeeded in 0 usecs
[ 1319.626503] [drm] ib test on ring 3 succeeded in 0 usecs
[ 1319.626566] [drm] ib test on ring 4 succeeded in 0 usecs
[ 1319.708396] btusb 2-3.2:1.0: no reset_resume for driver btusb?
[ 1319.708397] btusb 2-3.2:1.1: no reset_resume for driver btusb?
[ 1319.708398] btusb 2-3.2:1.0: forced unbind
[ 1320.307364] [drm] ib test on ring 5 succeeded
[ 1320.679967] tpm tpm0: tpm_try_transmit: send(): error -5
[ 1320.690896] acpi LNXPOWER:02: Turning OFF
[ 1320.690961] acpi LNXPOWER:01: Turning OFF
[ 1320.691001] OOM killer enabled.
[ 1320.691002] Restarting tasks ...
[ 1320.691189] acpi PNP0501:00: Still not present
[ 1320.691368] hub 3-3:1.0: state 7 ports 4 chg 0000 evt 0000
[ 1320.691373] hub 2-3:1.0: state 7 ports 4 chg 0004 evt 0000
[ 1320.692830] btusb 2-3.2:1.0: usb_probe_interface
[ 1320.692833] btusb 2-3.2:1.0: usb_probe_interface - got id
[ 1320.692959] hub 3-0:1.0: state 7 ports 4 chg 0000 evt 0008
[ 1320.692974] hub 1-0:1.0: state 7 ports 3 chg 0000 evt 0000
[ 1320.692977] hub 1-1:1.0: state 7 ports 8 chg 0120 evt 0000
[ 1320.693752] usb 1-1-port5: status 0100, change 0000, 12 Mb/s
[ 1320.693798] usb 2-3-port2: status 0103, change 0000, 12 Mb/s
[ 1320.694041] hub 2-0:1.0: state 7 ports 9 chg 0120 evt 0000
[ 1320.694058] usb usb2-port5: status 0103, change 0000, 12 Mb/s
[ 1320.694064] usb 1-1-port8: status 0100, change 0000, 12 Mb/s
[ 1320.694071] hub 1-1:1.0: hub_suspend
[ 1320.694251] done.
[ 1320.694837] hub 3-3:1.0: hub_suspend
[ 1320.696147] usb usb2-port8: status 0101, change 0000, 12 Mb/s
[ 1320.697084] usb 1-1: usb auto-suspend, wakeup 1
[ 1320.716855] hub 1-0:1.0: hub_suspend
[ 1320.716880] usb usb1: bus auto-suspend, wakeup 1
[ 1320.727189] usb 3-3: usb auto-suspend, wakeup 1
[ 1320.747227] hub 3-0:1.0: hub_suspend
[ 1320.747236] usb usb3: bus auto-suspend, wakeup 1
[ 1320.763319] usb usb2-port8: not reset yet, waiting 60ms
[ 1320.783921] PM: suspend exit
[ 1320.831328] usb usb2-port8: not reset yet, waiting 200ms
[ 1320.947718] e1000e: enp0s25 NIC Link is Down
[ 1321.039172] usb usb2-port8: not reset yet, waiting 200ms
[ 1321.247148] usb usb2-port8: not reset yet, waiting 200ms
[ 1321.455245] usb usb2-port8: not reset yet, waiting 200ms
[ 1321.455318] hub 2-0:1.0: state 7 ports 9 chg 0000 evt 0100
[ 1321.455336] usb usb2-port8: status 0100, change 0001, 12 Mb/s
[ 1321.599263] usb usb2-port8: debounce total 100ms stable 100ms status 0x100
[ 1322.062020] psmouse serio3: synaptics: queried max coordinates: x [..5658], y [..4706]
[ 1322.094600] psmouse serio3: synaptics: queried min coordinates: x [1368..], y [1234..]
[ 1322.707256] Bluetooth: hci0: Reading Intel version information failed (-110)
[ 1322.707260] Bluetooth: hci0: command 0xfc05 tx timeout
[ 1324.065460] e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[ 1324.065490] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 1324.723278] Bluetooth: hci0: command 0x0c03 tx timeout
[ 1325.717424] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/18
[ 1325.717431] usb 2-3.2: can't read device descriptor -110
[ 1325.717434] usb 2-3.2: USB disconnect, device number 20
[ 1325.717436] usb 2-3.2: unregistering device
[ 1325.717439] usb 2-3.2: unregistering interface 2-3.2:1.0
[ 1325.717558] xhci_hcd 0000:00:14.0: shutdown urb ffff9a6cbc38fa80 ep1in-intr
[ 1325.719493] xhci_hcd 0000:00:14.0: shutdown urb ffff9a6cbc38f180 ep2in-bulk
[ 1325.719499] xhci_hcd 0000:00:14.0: shutdown urb ffff9a6cbc38fd80 ep2in-bulk
[ 1325.721627] Bluetooth: hci0: sending initial HCI reset command failed (-19)
[ 1325.723991] usb 2-3.2: unregistering interface 2-3.2:1.1
[ 1325.724127] usb 2-3.2: usb_disable_device nuking all URBs
[ 1325.807315] usb 2-3.2: new full-speed USB device number 23 using xhci_hcd
[ 1328.056571] wlo1: authenticate with 58:8b:f3:44:8f:5c
[ 1328.060808] wlo1: send auth to 58:8b:f3:44:8f:5c (try 1/3)
[ 1328.066076] wlo1: authenticated
[ 1328.067277] wlo1: associate with 58:8b:f3:44:8f:5c (try 1/3)
[ 1328.072874] wlo1: RX AssocResp from 58:8b:f3:44:8f:5c (capab=0x1011 status=0 aid=12)
[ 1328.075184] wlo1: associated
[ 1328.099896] IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
[ 1330.837224] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1335.957600] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1341.077606] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1341.155553] usb 2-3.2: device descriptor read/64, error -110
[ 1346.453615] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1351.573728] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1356.693745] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1356.771742] usb 2-3.2: device descriptor read/64, error -110
[ 1356.959617] usb 2-3.2: new full-speed USB device number 24 using xhci_hcd
[ 1362.069897] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1367.189813] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1372.310022] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1372.387976] usb 2-3.2: device descriptor read/64, error -110
[ 1377.686028] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1382.806048] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1387.926136] usb 2-3.2: kworker/3:1 timed out on ep0in len=0/64
[ 1388.004163] usb 2-3.2: device descriptor read/64, error -110
[ 1388.112248] usb 2-3-port2: attempt power cycle
[ 1388.448275] hub 2-3:1.0: port_wait_reset: err = -11
[ 1388.448280] usb 2-3-port2: not enabled, trying reset again...
[ 1388.716065] usb 2-3.2: new full-speed USB device number 25 using xhci_hcd
[ 1393.812212] xhci_hcd 0000:00:14.0: Timeout while waiting for setup device command
[ 1394.020293] usb 2-3.2: Device not responding to setup address.
[ 1394.228149] usb 2-3.2: device not accepting address 25, error -71
[ 1394.308150] usb 2-3.2: new full-speed USB device number 26 using xhci_hcd
[ 1399.444262] xhci_hcd 0000:00:14.0: Timeout while waiting for setup device command
[ 1399.652400] usb 2-3.2: Device not responding to setup address.
[ 1399.860225] usb 2-3.2: device not accepting address 26, error -71
[ 1399.860462] usb 2-3-port2: unable to enumerate USB device
[ 1399.860595] hub 2-3:1.0: state 7 ports 4 chg 0000 evt 0004
[ 1399.860767] hub 2-3:1.0: hub_suspend
[ 1399.880251] usb 2-3: usb auto-suspend, wakeup 1
ffff9a6cfcad6e40 1303001511 S Co:2:020:0 s 20 00 0000 0000 0009 9 = 05200649 64f510b7 3d
ffff9a6cfcad6e40 1303001711 C Co:2:020:0 0 9 >
ffff9a6cfaae1180 1303002584 C Ii:2:020:1 0:1 6 = 0e040105 2000
ffff9a6cfaae1180 1303002605 S Ii:2:020:1 -115:1 64 <
ffff9a6cfcad6e40 1303002641 S Co:2:020:0 s 20 00 0000 0000 000a 10 = 0b200701 24001200 0100
ffff9a6cfcad6e40 1303002877 C Co:2:020:0 0 10 >
ffff9a6cfaae1180 1303003531 C Ii:2:020:1 0:1 6 = 0e04010b 2000
ffff9a6cfaae1180 1303003549 S Ii:2:020:1 -115:1 64 <
ffff9a6cfcad6e40 1303003576 S Co:2:020:0 s 20 00 0000 0000 0005 5 = 0c200201 01
ffff9a6cfcad6e40 1303003804 C Co:2:020:0 0 5 >
ffff9a6cfaae1180 1303004556 C Ii:2:020:1 0:1 6 = 0e04020c 2000
ffff9a6cfaae1180 1303004570 S Ii:2:020:1 -115:1 64 <
ffff9a6c502aac00 1303004589 S Co:2:020:0 s 20 00 0000 0000 0008 8 = 01040533 8b9e0800
ffff9a6c502aac00 1303004828 C Co:2:020:0 0 8 >
ffff9a6cfaae1180 1303005556 C Ii:2:020:1 0:1 6 = 0f040002 0104
ffff9a6cfaae1180 1303005568 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303055530 C Ii:2:020:1 0:1 32 = 3e1e0201 0001e07c b377515c 1202011a 020a0c0b ff4c0010 06031a2e b70af1d2
ffff9a6cfaae1180 1303055544 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303056552 C Ii:2:020:1 0:1 14 = 3e0c0201 0401e07c b377515c 00d2
ffff9a6cfaae1180 1303056563 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303073530 C Ii:2:020:1 0:1 31 = 3e1d0201 00015179 86e3bf57 1102011a 020a0c0a ff4c0010 05031820 2e44cc
ffff9a6cfaae1180 1303073539 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303074526 C Ii:2:020:1 0:1 14 = 3e0c0201 04015179 86e3bf57 00cc
ffff9a6cfaae1180 1303074531 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303098528 C Ii:2:020:1 0:1 29 = 3e1b0201 0000c82a 29e29914 0f02011a 0bff4c00 09060303 c0a8000b aa
ffff9a6cfaae1180 1303098538 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303109596 C Ii:2:020:1 0:1 42 = 3e280201 03007dce 6f7d495c 1c1bff75 00420401 80605c49 7d6fce7d 5e497d6f
ffff9a6cfaae1180 1303109614 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303185566 C Ii:2:020:1 0:1 45 = 3e2b0201 00015bc0 891804d0 1f020106 11061bc5 d5a50200 aa9de311 2af21019
ffff9a6cfaae1180 1303185593 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303186535 C Ii:2:020:1 0:1 38 = 3e240201 04015bc0 891804d0 18020a04 14094578 70657274 5f443030 34313838
ffff9a6cfaae1180 1303186549 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1303748637 C Ii:2:020:1 0:1 31 = 3e1d0201 0001aebf 2982ad72 1102011a 020a0c0a ff4c0010 05511cbe 012db1
ffff9a6cfaae1180 1303748657 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1304294599 C Ii:2:020:1 0:1 14 = 3e0c0201 0401aebf 2982ad72 00b3
ffff9a6cfaae1180 1304294626 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1304603523 C Ii:2:020:1 0:1 42 = 3e280201 0201ed2c 50e07a4f 1c03039f fe17169f fe000000 00000000 00000000
ffff9a6cfaae1180 1304603543 S Ii:2:020:1 -115:1 64 <
ffff9a6c502aad80 1304715749 S Co:2:020:0 s 20 00 0000 0000 0003 3 = 020400
ffff9a6c502aad80 1304715978 C Co:2:020:0 0 3 >
ffff9a6cfaae1180 1304716504 C Ii:2:020:1 0:1 6 = 0e040202 0400
ffff9a6cfaae1180 1304716512 S Ii:2:020:1 -115:1 64 <
ffff9a6c502aad80 1304716524 S Co:2:020:0 s 20 00 0000 0000 0005 5 = 0c200200 00
ffff9a6c502aad80 1304716725 C Co:2:020:0 0 5 >
ffff9a6cfaae1180 1304723520 C Ii:2:020:1 0:1 6 = 0e04020c 2000
ffff9a6cfaae1180 1304723535 S Ii:2:020:1 -115:1 64 <
ffff9a6cfaae1180 1316077522 C Ii:2:020:1 -2:1 0
ffff9a6cf334e300 1316079524 C Bi:2:020:2 -2 0
ffff9a6cfaae1480 1316081510 C Bi:2:020:2 -2 0
ffff9a6cf51a2b40 1316081627 C Ii:2:002:1 -2:2048 0
ffff9a6cf5c8f600 1316123311 C Ii:2:001:1 -2:2048 0
ffff9a6c502aa780 1319114635 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff9a6c502aa780 1319114640 C Ci:2:001:0 0 4 = 00010000
ffff9a6cfa0d2540 1319114646 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff9a6cfa0d2540 1319114649 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aad80 1319114653 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff9a6c502aad80 1319114656 C Ci:2:001:0 0 4 = 03050000
ffff9a6cfa0d23c0 1319114661 S Ci:2:001:0 s a3 00 0000 0004 0004 4 <
ffff9a6cfa0d23c0 1319114664 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aab40 1319114667 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff9a6c502aab40 1319114670 C Ci:2:001:0 0 4 = 01010100
ffff9a6cfa0d20c0 1319114674 S Co:2:001:0 s 23 01 0010 0005 0000 0
ffff9a6cfa0d20c0 1319114678 C Co:2:001:0 0 0
ffff9a6c502aa000 1319114681 S Ci:2:001:0 s a3 00 0000 0006 0004 4 <
ffff9a6c502aa000 1319114683 C Ci:2:001:0 0 4 = 00010000
ffff9a6cfa0d2780 1319114686 S Ci:2:001:0 s a3 00 0000 0007 0004 4 <
ffff9a6cfa0d2780 1319114689 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aacc0 1319114692 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aacc0 1319114694 C Ci:2:001:0 0 4 = 01010100
ffff9a6cfa0d2840 1319114698 S Co:2:001:0 s 23 01 0010 0008 0000 0
ffff9a6cfa0d2840 1319114702 C Co:2:001:0 0 0
ffff9a6c502aa900 1319114705 S Ci:2:001:0 s a3 00 0000 0009 0004 4 <
ffff9a6c502aa900 1319114707 C Ci:2:001:0 0 4 = 00010000
ffff9a6cf5c8f600 1319219617 S Ii:2:001:1 -115:2048 4 <
ffff9a6c502aaf00 1319219633 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff9a6c502aaf00 1319219646 C Ci:2:001:0 0 4 = 01010000
ffff9a6cfa0d2e40 1319219672 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff9a6cfa0d2e40 1319219675 C Ci:2:001:0 0 4 = 03050000
ffff9a6c502aaf00 1319219676 S Co:2:001:0 s 23 03 0004 0005 0000 0
ffff9a6c502aaf00 1319219682 C Co:2:001:0 0 0
ffff9a6cfcafa900 1319219686 S Ci:2:002:0 s 80 00 0000 0000 0002 2 <
ffff9a6cfcafa900 1319219702 C Ci:2:002:0 0 2 = 0100
ffff9a6cfcafa900 1319219746 S Ci:2:002:0 s a3 00 0000 0001 0004 4 <
ffff9a6cfcafa900 1319219759 C Ci:2:002:0 0 4 = 00010000
ffff9a6cfcafa900 1319219764 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cfcafa900 1319219798 C Ci:2:002:0 0 4 = 01010100
ffff9a6cfcafa900 1319219823 S Co:2:002:0 s 23 01 0010 0002 0000 0
ffff9a6cfcafa900 1319219839 C Co:2:002:0 0 0
ffff9a6cfcafa900 1319219878 S Ci:2:002:0 s a3 00 0000 0003 0004 4 <
ffff9a6cfcafa900 1319219890 C Ci:2:002:0 0 4 = 00010000
ffff9a6cfcafa900 1319219893 S Ci:2:002:0 s a3 00 0000 0004 0004 4 <
ffff9a6cfcafa900 1319219930 C Ci:2:002:0 0 4 = 00010000
ffff9a6cfa0d2240 1319287606 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff9a6cfa0d2240 1319287610 C Ci:2:001:0 0 4 = 03011000
ffff9a6c502aa180 1319287618 S Co:2:001:0 s 23 01 0014 0005 0000 0
ffff9a6c502aa180 1319287624 C Co:2:001:0 0 0
ffff9a6cf51a2b40 1319327617 S Ii:2:002:1 -115:2048 1 <
ffff9a6cfcafa900 1319327631 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cfcafa900 1319327644 C Ci:2:002:0 0 4 = 01010000
ffff9a6c502aa240 1319347798 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6c502aa240 1319348057 C Ci:2:000:0 0 8 = 12011001 ff12ff08
ffff9a6c502aa240 1319348079 S Co:2:001:0 s 23 03 0004 0005 0000 0
ffff9a6c502aa240 1319348087 C Co:2:001:0 0 0
ffff9a6c502aa0c0 1319415616 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff9a6c502aa0c0 1319415628 C Ci:2:001:0 0 4 = 03011000
ffff9a6cfa0d2240 1319415633 S Co:2:001:0 s 23 01 0014 0005 0000 0
ffff9a6cfa0d2240 1319415638 C Co:2:001:0 0 0
ffff9a6cfcafa900 1319495597 S Ci:2:003:0 s 80 06 0100 0000 0012 18 <
ffff9a6cfcafa900 1319495808 C Ci:2:003:0 0 18 = 12011001 ff12ff08 8a133f00 04010000 0101
ffff9a6cfcafa900 1319495815 S Ci:2:003:0 s 80 06 0200 0000 002e 46 <
ffff9a6cfa0d2e40 1319495817 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cfa0d2e40 1319495847 C Co:2:002:0 0 0
ffff9a6cfcafa900 1319496136 C Ci:2:003:0 0 46 = 09022e00 010100a0 32090400 0004ff00 00000705 01024000 00070581 02400000
ffff9a6cfcafa900 1319496139 S Ci:2:003:0 s 80 06 0301 0409 00ff 255 <
ffff9a6cfcafa900 1319496383 C Ci:2:003:0 0 26 = 1a033000 30006200 30003600 30003100 36003900 66003900 3300
ffff9a6cfcafa900 1319496591 S Co:2:003:0 s 00 09 0001 0000 0000 0
ffff9a6cfcafa900 1319496696 C Co:2:003:0 0 0
ffff9a6cfcafa900 1319496706 S Ci:2:003:0 s 80 00 0000 0000 0002 2 <
ffff9a6cfcafa900 1319496825 C Ci:2:003:0 0 2 = 0000
ffff9a6cfa0d2e40 1319515618 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cfa0d2e40 1319515646 C Ci:2:002:0 0 4 = 03011000
ffff9a6cfa0d2e40 1319515650 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cfa0d2e40 1319515703 C Co:2:002:0 0 0
ffff9a6cfa0d2e40 1319575809 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cfa0d2e40 1319575997 C Ci:2:000:0 0 18 = 12010002 e0010140 8780dc07 01000000 0001
ffff9a6cfa0d2e40 1319576002 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cfa0d2e40 1319576021 C Co:2:002:0 0 0
ffff9a6cfa0d2e40 1319595616 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cfa0d2e40 1319595635 C Ci:2:002:0 0 4 = 03011000
ffff9a6cfa0d2e40 1319595639 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cfa0d2e40 1319595690 C Co:2:002:0 0 0
ffff9a6cfa0d2e40 1319675620 S Ci:2:020:0 s 80 06 0100 0000 0012 18 <
ffff9a6cfa0d2e40 1319675813 C Ci:2:020:0 0 18 = 12010002 e0010140 8780dc07 01000000 0001
ffff9a6cfa0d2840 1319675820 S Ci:2:020:0 s 80 06 0200 0000 00b1 177 <
ffff9a6cfa0d2840 1319676280 C Ci:2:020:0 0 177 = 0902b100 020100e0 32090400 0003e001 01000705 81034000 01070502 02400001
ffff9a6cfa0d2e40 1319676502 S Co:2:020:0 s 00 09 0001 0000 0000 0
ffff9a6cfa0d2e40 1319676666 C Co:2:020:0 0 0
ffff9a6cfa0d2e40 1319676679 S Ci:2:020:0 s 80 00 0000 0000 0002 2 <
ffff9a6cfa0d2e40 1319676866 C Ci:2:020:0 0 2 = 0100
ffff9a6c502aaa80 1320661397 S Ii:2:020:1 -115:1 64 <
ffff9a6c502aa0c0 1320661402 S Bi:2:020:2 -115 1028 <
ffff9a6c502aa240 1320661404 S Bi:2:020:2 -115 1028 <
ffff9a6c502aa180 1320661411 S Co:2:020:0 s 20 00 0000 0000 0003 3 = 030c00
ffff9a6c502aa180 1320661563 C Co:2:020:0 0 3 >
ffff9a6cbc385cc0 1320662266 S Ci:2:020:0 s 80 06 0100 0000 0012 18 <
ffff9a6c502aacc0 1320662510 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff9a6c502aacc0 1320662520 C Ci:2:001:0 0 4 = 03010000
ffff9a6c502aacc0 1320662526 S Ci:2:003:0 s 80 06 0100 0000 0012 18 <
ffff9a6c502aacc0 1320662781 C Ci:2:003:0 0 18 = 12011001 ff12ff08 8a133f00 04010000 0101
ffff9a6c502aacc0 1320662789 S Ci:2:003:0 s 80 06 0200 0000 002e 46 <
ffff9a6c502aacc0 1320663190 C Ci:2:003:0 0 46 = 09022e00 010100a0 32090400 0004ff00 00000705 01024000 00070581 02400000
ffff9a6c502aacc0 1320663198 S Ci:2:003:0 s 80 06 0301 0409 00ff 255 <
ffff9a6c502aacc0 1320663486 C Ci:2:003:0 0 26 = 1a033000 30006200 30003600 30003100 36003900 66003900 3300
ffff9a6c502aacc0 1320664598 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aacc0 1320664606 C Ci:2:001:0 0 4 = 01010000
ffff9a6c502aaf00 1320665526 S Co:2:001:0 s 23 03 0004 0008 0000 0
ffff9a6c502aaf00 1320665535 C Co:2:001:0 0 0
ffff9a6c502aaa80 1320673190 C Ii:2:020:1 0:1 6 = 0e040103 0c00
ffff9a6c502aaa80 1320673200 S Ii:2:020:1 -115:1 64 <
ffff9a6c501c8e40 1320673223 S Co:2:020:0 s 20 00 0000 0000 0003 3 = 05fc00
ffff9a6c502aad80 1320731723 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aad80 1320731772 C Ci:2:001:0 0 4 = 00011100
ffff9a6c502aa480 1320799773 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1320799786 C Ci:2:001:0 0 4 = 00011100
ffff9a6cf5c8f600 1320903644 C Ii:2:001:1 0:2048 2 = 0001
ffff9a6cf5c8f600 1320903681 S Ii:2:001:1 -115:2048 4 <
ffff9a6c502aa480 1321007614 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321007625 C Ci:2:001:0 0 4 = 00011100
ffff9a6cf5c8f600 1321151630 C Ii:2:001:1 0:2048 2 = 0001
ffff9a6cf5c8f600 1321151634 S Ii:2:001:1 -115:2048 4 <
ffff9a6c502aa480 1321215593 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321215600 C Ci:2:001:0 0 4 = 00011100
ffff9a6cf5c8f600 1321399677 C Ii:2:001:1 0:2048 2 = 0001
ffff9a6cf5c8f600 1321399686 S Ii:2:001:1 -115:2048 4 <
ffff9a6c502aa480 1321423630 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321423690 C Ci:2:001:0 0 4 = 00011100
ffff9a6c502aa480 1321423703 S Co:2:001:0 s 23 01 0014 0008 0000 0
ffff9a6c502aa480 1321423709 C Co:2:001:0 0 0
ffff9a6c502aa480 1321423712 S Co:2:001:0 s 23 01 0001 0008 0000 0
ffff9a6c502aa480 1321423717 C Co:2:001:0 0 0
ffff9a6c502aa480 1321423748 S Co:2:001:0 s 23 01 0001 0008 0000 0
ffff9a6c502aa480 1321423762 C Co:2:001:0 0 0
ffff9a6c502aa480 1321423776 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321423780 C Ci:2:001:0 0 4 = 00010100
ffff9a6c502aa480 1321423783 S Co:2:001:0 s 23 01 0010 0008 0000 0
ffff9a6c502aa480 1321423788 C Co:2:001:0 0 0
ffff9a6c502aa480 1321423794 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321423797 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aa480 1321459684 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321459703 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aa480 1321495686 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321495708 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aa480 1321531685 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321531702 C Ci:2:001:0 0 4 = 00010000
ffff9a6c502aa480 1321567682 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff9a6c502aa480 1321567706 C Ci:2:001:0 0 4 = 00010000
ffff9a6c501c8e40 1322677771 C Co:2:020:0 -2 0
ffff9a6c502aaa80 1322679780 C Ii:2:020:1 -2:1 0
ffff9a6c502aa240 1322681774 C Bi:2:020:2 -2 0
ffff9a6c502aa0c0 1322683803 C Bi:2:020:2 -2 0
ffff9a6cbc38fa80 1322683895 S Ii:2:020:1 -115:1 64 <
ffff9a6cbc38fd80 1322683903 S Bi:2:020:2 -115 1028 <
ffff9a6cbc38f180 1322683904 S Bi:2:020:2 -115 1028 <
ffff9a6c502aa0c0 1322683960 S Co:2:020:0 s 20 00 0000 0000 0003 3 = 030c00
ffff9a6cbc385cc0 1325685692 C Ci:2:020:0 -2 0
ffff9a6cbc38fa80 1325687862 C Ii:2:020:1 -108:1 0
ffff9a6cbc38f180 1325689944 C Bi:2:020:2 -108 0
ffff9a6cbc38fd80 1325689963 C Bi:2:020:2 -108 0
ffff9a6c502aa0c0 1325692037 C Co:2:020:0 -2 0
ffff9a6c50049000 1325694270 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6c50049000 1325694301 C Co:2:002:0 0 0
ffff9a6cf51a2b40 1325709999 C Ii:2:002:1 0:2048 1 = 04
ffff9a6cf51a2b40 1325710007 S Ii:2:002:1 -115:2048 1 <
ffff9a6c50049000 1325715616 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6c50049000 1325715638 C Ci:2:002:0 0 4 = 03011000
ffff9a6c50049000 1325715644 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6c50049000 1325715677 C Co:2:002:0 0 0
ffff9a6c50049000 1325775868 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6c50049000 1330805543 C Ci:2:000:0 -2 0
ffff9a6cbc38ff00 1330805568 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc38ff00 1335925830 C Ci:2:000:0 -2 0
ffff9a6cf618a240 1335925888 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cf618a240 1341045768 C Ci:2:000:0 -2 0
ffff9a6cbc38ff00 1341045831 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cbc38ff00 1341045870 C Co:2:002:0 0 0
ffff9a6cbc38ff00 1341063703 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cbc38ff00 1341063763 C Ci:2:002:0 0 4 = 03011000
ffff9a6cbc38ff00 1341063792 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cbc38ff00 1341063825 C Co:2:002:0 0 0
ffff9a6cbc38ff00 1341231715 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc38ff00 1346421706 C Ci:2:000:0 -2 0
ffff9a6cbc38ff00 1346421771 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc38ff00 1351541768 C Ci:2:000:0 -2 0
ffff9a6cfd15c840 1351541821 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cfd15c840 1356661708 C Ci:2:000:0 -2 0
ffff9a6cbc385240 1356661777 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cbc385240 1356661813 C Co:2:002:0 0 0
ffff9a6cbc385240 1356679709 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cbc385240 1356679765 C Ci:2:002:0 0 4 = 03011000
ffff9a6cbc385240 1356679789 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cbc385240 1356679821 C Co:2:002:0 0 0
ffff9a6cbc385240 1356847713 S Co:2:002:0 s 23 01 0001 0002 0000 0
ffff9a6cbc385240 1356847762 C Co:2:002:0 0 0
ffff9a6cbc385240 1356847926 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cbc385240 1356847988 C Co:2:002:0 0 0
ffff9a6cbc385240 1356867618 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cbc385240 1356867662 C Ci:2:002:0 0 4 = 03011000
ffff9a6cbc385240 1356867676 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cbc385240 1356867701 C Co:2:002:0 0 0
ffff9a6cbc385240 1356927679 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc385240 1362037781 C Ci:2:000:0 -2 0
ffff9a6cbc385240 1362037862 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc385240 1367157662 C Ci:2:000:0 -2 0
ffff9a6cbc385240 1367157712 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc385240 1372277779 C Ci:2:000:0 -2 0
ffff9a6cbc385240 1372277865 S Co:2:002:0 s 23 03 0004 0002 0000 0
ffff9a6cbc385240 1372277901 C Co:2:002:0 0 0
ffff9a6cbc385240 1372295702 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff9a6cbc385240 1372295759 C Ci:2:002:0 0 4 = 03011000
ffff9a6cbc385240 1372295827 S Co:2:002:0 s 23 01 0014 0002 0000 0
ffff9a6cbc385240 1372295865 C Co:2:002:0 0 0
ffff9a6cbc385240 1372471642 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff9a6cbc385240 1377653718 C Ci:2:000:0 -2 0
ffff9a6cbc385240 1377653807 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
Thanks,
Paul
On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:
> On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern <[email protected]> wrote:
>
> > On Sun, 19 Jan 2020, Paul Zimmerman wrote:
> >
> > > I reported this regression last week (see
> > > https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
> > > but I got no response to my email. Today I have retested with
> > > 5.5-rc7 and verified that the problem still exists. So I am
> > > resending with a different subject line to see if anyone responds.
> > >
> > > The $subject patch causes a regression on my HP EliteBook laptop
> > > with a built-in USB bluetooth adapter. About 50% of the time, a
> > > suspend/resume cycle will cause the bluetooth adapter to stop
> > > working.
> > >
> > > The dmesg log below shows two suspend/resume cycles. At time
> > > 63.928 you can see the bluetooth adapter being successfully
> > > resumed, and at time 140.969 you can see it fail. After reverting
> > > the patch, the bluetooth adapter resumes 100% of the time.
> > >
> > > I also included below a lsusb -v of the bluetooth adapter. Is
> > > there any other debugging info you'd like me to send?
> >
> > It looks like your dmesg log was made without enabling debugging
> > messages in usbcore. Can you collect another log with debugging
> > messages turned on?
> >
> > echo 'module usbcore =p'
> > >/sys/kernel/debug/dynamic_debug/control
> >
> > Also, it might not hurt to collect and post a usbmon trace for a bad
> > suspend-resume cycle.
>
> Hi Alan,
>
> Thanks for responding. The new dmesg log and the usbmon trace are
> below. The dmesg shows a good suspend/resume followed by a bad one.
> The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only
> for the failed suspend/resume case.
I did some more debugging on this using ftrace, here is an annotated
log that shows what I think is happening on a failed resume. Note that
hub_port_connect_change() is the function that the patch modified to
call usb_get_device_descriptor() in some circumstances.
This first call to hub_port_connect_change() is for a different device,
not the failing one. There are multiple other calls to that function in
the trace, but they are not for the device in question:
kworker/1:6-19987 [001] 7803.175058: funcgraph_entry: | hub_port_connect_change() {
kworker/1:6-19987 [001] 7803.175069: funcgraph_entry: ! 11911.151 us | usb_get_device_descriptor();
kworker/2:5-20675 [002] 7803.179333: funcgraph_entry: | usb_probe_interface() {
Starting here is a worker thread that is trying to setup the bluetooth
adapter after the resume:
kworker/u17:1-3175 [002] 7803.179457: funcgraph_entry: | hci_power_on() {
kworker/u17:1-3175 [002] 7803.179458: funcgraph_entry: | hci_dev_do_open() {
kworker/u17:1-3175 [002] 7803.179468: funcgraph_entry: | btusb_setup_intel() {
kworker/2:5-20675 [002] 7803.179480: funcgraph_exit: ! 147.596 us | }
And here is a worker thread that is handling the connect change on the USB
port with the bluetooth device. This happens while the btusb_setup_intel()
function called by the other thread above is still running:
kworker/3:1-16790 [003] 7803.181323: funcgraph_entry: | hub_port_connect_change() {
kworker/3:1-16790 [003] 7803.181330: funcgraph_entry: | usb_get_device_descriptor() {
kworker/0:2-19962 [000] 7803.184885: funcgraph_entry: 6.016 us | hub_port_connect_change();
kworker/0:2-19962 [000] 7803.187208: funcgraph_entry: 5.462 us | hub_port_connect_change();
kworker/1:6-19987 [001] 7803.187835: funcgraph_exit: ! 12776.810 us | }
kworker/1:6-19987 [001] 7803.187846: funcgraph_entry: ! 767445.344 us | hub_port_connect_change();
By this point the failure has happened ("Bluetooth: hci0: Reading Intel
version information failed (-110)") , and it looks like somebody
queues another work to try setting up the bluetooth adapter again:
hciconfig-21074 [000] 7803.193549: funcgraph_entry: | hci_dev_open() {
kworker/1:6-19987 [001] 7803.955315: funcgraph_entry: ! 144039.307 us | hub_port_connect_change();
kworker/u17:1-3175 [003] 7805.203325: funcgraph_exit: ! 2023855 us | }
kworker/u17:1-3175 [003] 7805.211728: funcgraph_exit: ! 2032269 us | }
kworker/u17:1-3175 [003] 7805.211731: funcgraph_exit: ! 2032273 us | }
hciconfig-21074 [000] 7805.211760: funcgraph_entry: | hci_dev_do_open() {
hciconfig-21074 [000] 7805.211777: funcgraph_entry: ! 3069605 us | btusb_setup_intel();
And here the usb_get_device_descriptor() call made by the USB worker thread
finally completes. It also fails ("kworker/3:1 timed out on ep0in len=0/18"):
kworker/3:1-16790 [003] 7808.277224: funcgraph_exit: ! 5095893 us | }
hciconfig-21074 [001] 7808.283313: funcgraph_exit: ! 3071554 us | }
hciconfig-21074 [001] 7808.283315: funcgraph_exit: ! 5089767 us | }
So if I'm understanding this correctly, there are two threads that are
trying to access the USB bluetooth device at the same time. I have no
idea if that is how it's supposed to work.
Thanks,
Paul
On Tue, 21 Jan 2020, Paul Zimmerman wrote:
> On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:
>
> > On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern <[email protected]> wrote:
> >
> > > On Sun, 19 Jan 2020, Paul Zimmerman wrote:
> > >
> > > > I reported this regression last week (see
> > > > https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
> > > > but I got no response to my email. Today I have retested with
> > > > 5.5-rc7 and verified that the problem still exists. So I am
> > > > resending with a different subject line to see if anyone responds.
> > > >
> > > > The $subject patch causes a regression on my HP EliteBook laptop
> > > > with a built-in USB bluetooth adapter. About 50% of the time, a
> > > > suspend/resume cycle will cause the bluetooth adapter to stop
> > > > working.
> > > >
> > > > The dmesg log below shows two suspend/resume cycles. At time
> > > > 63.928 you can see the bluetooth adapter being successfully
> > > > resumed, and at time 140.969 you can see it fail. After reverting
> > > > the patch, the bluetooth adapter resumes 100% of the time.
> > > >
> > > > I also included below a lsusb -v of the bluetooth adapter. Is
> > > > there any other debugging info you'd like me to send?
> > >
> > > It looks like your dmesg log was made without enabling debugging
> > > messages in usbcore. Can you collect another log with debugging
> > > messages turned on?
> > >
> > > echo 'module usbcore =p'
> > > >/sys/kernel/debug/dynamic_debug/control
> > >
> > > Also, it might not hurt to collect and post a usbmon trace for a bad
> > > suspend-resume cycle.
> >
> > Hi Alan,
> >
> > Thanks for responding. The new dmesg log and the usbmon trace are
> > below. The dmesg shows a good suspend/resume followed by a bad one.
> > The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only
> > for the failed suspend/resume case.
It might be interesting to have a usbmon trace of a successful resume
as well, for comparison. However I suspect it would just show that
the new Get-Device-Descriptor request worked and everything else
continued on normally.
> I did some more debugging on this using ftrace, here is an annotated
> log that shows what I think is happening on a failed resume. Note that
> hub_port_connect_change() is the function that the patch modified to
> call usb_get_device_descriptor() in some circumstances.
>
> This first call to hub_port_connect_change() is for a different device,
> not the failing one. There are multiple other calls to that function in
> the trace, but they are not for the device in question:
> kworker/1:6-19987 [001] 7803.175058: funcgraph_entry: | hub_port_connect_change() {
> kworker/1:6-19987 [001] 7803.175069: funcgraph_entry: ! 11911.151 us | usb_get_device_descriptor();
> kworker/2:5-20675 [002] 7803.179333: funcgraph_entry: | usb_probe_interface() {
>
> Starting here is a worker thread that is trying to setup the bluetooth
> adapter after the resume:
> kworker/u17:1-3175 [002] 7803.179457: funcgraph_entry: | hci_power_on() {
> kworker/u17:1-3175 [002] 7803.179458: funcgraph_entry: | hci_dev_do_open() {
> kworker/u17:1-3175 [002] 7803.179468: funcgraph_entry: | btusb_setup_intel() {
> kworker/2:5-20675 [002] 7803.179480: funcgraph_exit: ! 147.596 us | }
>
> And here is a worker thread that is handling the connect change on the USB
> port with the bluetooth device. This happens while the btusb_setup_intel()
> function called by the other thread above is still running:
> kworker/3:1-16790 [003] 7803.181323: funcgraph_entry: | hub_port_connect_change() {
> kworker/3:1-16790 [003] 7803.181330: funcgraph_entry: | usb_get_device_descriptor() {
> kworker/0:2-19962 [000] 7803.184885: funcgraph_entry: 6.016 us | hub_port_connect_change();
> kworker/0:2-19962 [000] 7803.187208: funcgraph_entry: 5.462 us | hub_port_connect_change();
> kworker/1:6-19987 [001] 7803.187835: funcgraph_exit: ! 12776.810 us | }
> kworker/1:6-19987 [001] 7803.187846: funcgraph_entry: ! 767445.344 us | hub_port_connect_change();
>
> By this point the failure has happened ("Bluetooth: hci0: Reading Intel
> version information failed (-110)") , and it looks like somebody
> queues another work to try setting up the bluetooth adapter again:
> hciconfig-21074 [000] 7803.193549: funcgraph_entry: | hci_dev_open() {
> kworker/1:6-19987 [001] 7803.955315: funcgraph_entry: ! 144039.307 us | hub_port_connect_change();
> kworker/u17:1-3175 [003] 7805.203325: funcgraph_exit: ! 2023855 us | }
> kworker/u17:1-3175 [003] 7805.211728: funcgraph_exit: ! 2032269 us | }
> kworker/u17:1-3175 [003] 7805.211731: funcgraph_exit: ! 2032273 us | }
> hciconfig-21074 [000] 7805.211760: funcgraph_entry: | hci_dev_do_open() {
> hciconfig-21074 [000] 7805.211777: funcgraph_entry: ! 3069605 us | btusb_setup_intel();
>
> And here the usb_get_device_descriptor() call made by the USB worker thread
> finally completes. It also fails ("kworker/3:1 timed out on ep0in len=0/18"):
> kworker/3:1-16790 [003] 7808.277224: funcgraph_exit: ! 5095893 us | }
> hciconfig-21074 [001] 7808.283313: funcgraph_exit: ! 3071554 us | }
> hciconfig-21074 [001] 7808.283315: funcgraph_exit: ! 5089767 us | }
>
> So if I'm understanding this correctly, there are two threads that are
> trying to access the USB bluetooth device at the same time. I have no
> idea if that is how it's supposed to work.
In fact it isn't, although in principle this shouldn't cause any
trouble. It looks like your bluetooth device is deficient: It
sometimes crashes if it receives a Get-Device-Descriptor request while
it is busy with something else.
Still, since there was no real connection change at the port, there's
no reason to call hub_port_connect_change() here. Let's see if the
patch below fixes your problem.
Alan Stern
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
--- usb-devel.orig/drivers/usb/core/hub.c
+++ usb-devel/drivers/usb/core/hub.c
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
#ifdef CONFIG_PM
udev->reset_resume = 1;
#endif
- /* Don't set the change_bits when the device
- * was powered off.
- */
- if (test_bit(port1, hub->power_bits))
- set_bit(port1, hub->change_bits);
} else {
/* The power session is gone; tell hub_wq */
On Wed, 22 Jan 2020 14:31:29 -0500 (EST)
Alan Stern <[email protected]> wrote:
> On Tue, 21 Jan 2020, Paul Zimmerman wrote:
>
> > On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:
> >
> > > On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern <[email protected]> wrote:
> > >
> > > > On Sun, 19 Jan 2020, Paul Zimmerman wrote:
> > > >
> > > > > I reported this regression last week (see
> > > > > https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
> > > > > but I got no response to my email. Today I have retested with
> > > > > 5.5-rc7 and verified that the problem still exists. So I am
> > > > > resending with a different subject line to see if anyone responds.
> > > > >
> > > > > The $subject patch causes a regression on my HP EliteBook laptop
> > > > > with a built-in USB bluetooth adapter. About 50% of the time, a
> > > > > suspend/resume cycle will cause the bluetooth adapter to stop
> > > > > working.
> > > > >
> > > > > The dmesg log below shows two suspend/resume cycles. At time
> > > > > 63.928 you can see the bluetooth adapter being successfully
> > > > > resumed, and at time 140.969 you can see it fail. After reverting
> > > > > the patch, the bluetooth adapter resumes 100% of the time.
> > > > >
> > > > > I also included below a lsusb -v of the bluetooth adapter. Is
> > > > > there any other debugging info you'd like me to send?
> > > >
> > > > It looks like your dmesg log was made without enabling debugging
> > > > messages in usbcore. Can you collect another log with debugging
> > > > messages turned on?
> > > >
> > > > echo 'module usbcore =p'
> > > > >/sys/kernel/debug/dynamic_debug/control
> > > >
> > > > Also, it might not hurt to collect and post a usbmon trace for a bad
> > > > suspend-resume cycle.
> > >
> > > Hi Alan,
> > >
> > > Thanks for responding. The new dmesg log and the usbmon trace are
> > > below. The dmesg shows a good suspend/resume followed by a bad one.
> > > The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only
> > > for the failed suspend/resume case.
>
> It might be interesting to have a usbmon trace of a successful resume
> as well, for comparison. However I suspect it would just show that
> the new Get-Device-Descriptor request worked and everything else
> continued on normally.
< snip >
> > So if I'm understanding this correctly, there are two threads that are
> > trying to access the USB bluetooth device at the same time. I have no
> > idea if that is how it's supposed to work.
>
> In fact it isn't, although in principle this shouldn't cause any
> trouble. It looks like your bluetooth device is deficient: It
> sometimes crashes if it receives a Get-Device-Descriptor request while
> it is busy with something else.
>
> Still, since there was no real connection change at the port, there's
> no reason to call hub_port_connect_change() here. Let's see if the
> patch below fixes your problem.
>
> Alan Stern
>
>
>
> Index: usb-devel/drivers/usb/core/hub.c
> ===================================================================
> --- usb-devel.orig/drivers/usb/core/hub.c
> +++ usb-devel/drivers/usb/core/hub.c
> @@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
> #ifdef CONFIG_PM
> udev->reset_resume = 1;
> #endif
> - /* Don't set the change_bits when the device
> - * was powered off.
> - */
> - if (test_bit(port1, hub->power_bits))
> - set_bit(port1, hub->change_bits);
>
> } else {
> /* The power session is gone; tell hub_wq */
>
I can confirm this fixes the issue for me, I did a couple dozen
suspend/resume cycles without seeing a failure.
I see the code you removed was added by Lan Tianyu in commit
ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
wonder if your patch would break that? I don't know what that is
or how to test it.
In any case:
Tested-by: Paul Zimmerman <[email protected]>
On Wed, 22 Jan 2020, Paul Zimmerman wrote:
> > Still, since there was no real connection change at the port, there's
> > no reason to call hub_port_connect_change() here. Let's see if the
> > patch below fixes your problem.
> >
> > Alan Stern
> >
> >
> >
> > Index: usb-devel/drivers/usb/core/hub.c
> > ===================================================================
> > --- usb-devel.orig/drivers/usb/core/hub.c
> > +++ usb-devel/drivers/usb/core/hub.c
> > @@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
> > #ifdef CONFIG_PM
> > udev->reset_resume = 1;
> > #endif
> > - /* Don't set the change_bits when the device
> > - * was powered off.
> > - */
> > - if (test_bit(port1, hub->power_bits))
> > - set_bit(port1, hub->change_bits);
> >
> > } else {
> > /* The power session is gone; tell hub_wq */
> >
>
> I can confirm this fixes the issue for me, I did a couple dozen
> suspend/resume cycles without seeing a failure.
>
> I see the code you removed was added by Lan Tianyu in commit
> ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
No, not really. The set_bit() call was added by me in a much earlier
commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the
"if" test, so that set_bit() doesn't always get called. Now with this
change, set_bit() never gets called.
> wonder if your patch would break that? I don't know what that is
> or how to test it.
While some code review by people who are familiar with this material
wouldn't hurt, I don't think you need to worry about any additional
testing.
> In any case:
> Tested-by: Paul Zimmerman <[email protected]>
Thank you. I'll submit the patch soon.
Alan Stern
Hi Alan,
On 1/23/20 8:50 AM, Alan Stern wrote:
> On Wed, 22 Jan 2020, Paul Zimmerman wrote:
>
>>> Still, since there was no real connection change at the port, there's
>>> no reason to call hub_port_connect_change() here. Let's see if the
>>> patch below fixes your problem.
>>>
>>> Alan Stern
>>>
>>>
>>>
>>> Index: usb-devel/drivers/usb/core/hub.c
>>> ===================================================================
>>> --- usb-devel.orig/drivers/usb/core/hub.c
>>> +++ usb-devel/drivers/usb/core/hub.c
>>> @@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
>>> #ifdef CONFIG_PM
>>> udev->reset_resume = 1;
>>> #endif
>>> - /* Don't set the change_bits when the device
>>> - * was powered off.
>>> - */
>>> - if (test_bit(port1, hub->power_bits))
>>> - set_bit(port1, hub->change_bits);
>>>
>>> } else {
>>> /* The power session is gone; tell hub_wq */
>>>
>>
>> I can confirm this fixes the issue for me, I did a couple dozen
>> suspend/resume cycles without seeing a failure.
>>
>> I see the code you removed was added by Lan Tianyu in commit
>> ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
>
> No, not really. The set_bit() call was added by me in a much earlier
> commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the
> "if" test, so that set_bit() doesn't always get called. Now with this
> change, set_bit() never gets called.
>
>> wonder if your patch would break that? I don't know what that is
>> or how to test it.
>
> While some code review by people who are familiar with this material
> wouldn't hurt, I don't think you need to worry about any additional
> testing.
>
>> In any case:
>> Tested-by: Paul Zimmerman <[email protected]>
>
> Thank you. I'll submit the patch soon.
>
> Alan Stern
Ping? Unfortunately 5.5 was released with this regression, do you plan
to submit this patch soon?
--
Paul
On Thu, 30 Jan 2020, Paul Zimmerman wrote:
> Hi Alan,
>
> On 1/23/20 8:50 AM, Alan Stern wrote:
> > On Wed, 22 Jan 2020, Paul Zimmerman wrote:
> >
> >>> Still, since there was no real connection change at the port, there's
> >>> no reason to call hub_port_connect_change() here. Let's see if the
> >>> patch below fixes your problem.
> >>>
> >>> Alan Stern
> >>>
> >>>
> >>>
> >>> Index: usb-devel/drivers/usb/core/hub.c
> >>> ===================================================================
> >>> --- usb-devel.orig/drivers/usb/core/hub.c
> >>> +++ usb-devel/drivers/usb/core/hub.c
> >>> @@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
> >>> #ifdef CONFIG_PM
> >>> udev->reset_resume = 1;
> >>> #endif
> >>> - /* Don't set the change_bits when the device
> >>> - * was powered off.
> >>> - */
> >>> - if (test_bit(port1, hub->power_bits))
> >>> - set_bit(port1, hub->change_bits);
> >>>
> >>> } else {
> >>> /* The power session is gone; tell hub_wq */
> >>>
> >>
> >> I can confirm this fixes the issue for me, I did a couple dozen
> >> suspend/resume cycles without seeing a failure.
> >>
> >> I see the code you removed was added by Lan Tianyu in commit
> >> ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
> >
> > No, not really. The set_bit() call was added by me in a much earlier
> > commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the
> > "if" test, so that set_bit() doesn't always get called. Now with this
> > change, set_bit() never gets called.
> >
> >> wonder if your patch would break that? I don't know what that is
> >> or how to test it.
> >
> > While some code review by people who are familiar with this material
> > wouldn't hurt, I don't think you need to worry about any additional
> > testing.
> >
> >> In any case:
> >> Tested-by: Paul Zimmerman <[email protected]>
> >
> > Thank you. I'll submit the patch soon.
> >
> > Alan Stern
>
> Ping? Unfortunately 5.5 was released with this regression, do you plan
> to submit this patch soon?
Oops. It totally slipped my mind, sorry. Thanks for reminding me.
Submission coming up...
Alan Stern