Attachment 14549 Details for Bug 33246 – journal of suspend-resume with comments

journal of suspend-resume with comments

suspend_OK.txt (text/plain), 7.69 KB, created by Morgan Leijström on 2024-05-27 10:03:43 CEST

(hide)

Description:

Filename:

MIME Type:

Creator: Morgan Leijström

Created: 2024-05-27 10:03:43 CEST

Size: 7.69 KB

patch

obsolete

>maj 27 09:05:44 localhost systemd-logind[1140]: The system will suspend now!
>maj 27 09:05:44 localhost kscreenlocker_greet[184183]: Qt: Session management error: networkIdsList argument is NULL
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: kf.kirigami: Failed to find a Kirigami platform plugin
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/VirtualKeyboard.qml:8:1: module "QtQuick.VirtualKeyboard" is not installed
>maj 27 09:05:45 localhost systemd[1]: Reached target sleep.target.
>maj 27 09:05:45 localhost systemd[1]: Starting systemd-suspend.service...
>
>
>    For a failed suspend, here is where journal log ends.
>
>
>maj 27 09:05:45 localhost systemd-sleep[184194]: Entering sleep state 'suspend'...
>maj 27 09:05:45 localhost kernel: PM: suspend entry (deep)
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
>maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
>maj 27 09:05:45 localhost kernel: Filesystems sync: 0.042 seconds
>maj 27 09:06:40 localhost kernel: Freezing user space processes
>maj 27 09:06:40 localhost kernel: Freezing user space processes completed (elapsed 0.004 seconds)
>maj 27 09:06:40 localhost kernel: OOM killer disabled.
>maj 27 09:06:40 localhost kernel: Freezing remaining freezable tasks
>maj 27 09:06:40 localhost kernel: Freezing remaining freezable tasks completed (elapsed 0.000 seconds)
>maj 27 09:06:40 localhost kernel: printk: Suspending console(s) (use no_console_suspend to debug)
>maj 27 09:06:40 localhost kernel: wlp3s0: deauthenticating from c0:06:c3:d6:9b:a3 by local choice (Reason: 3=DEAUTH_LEAVING)
>maj 27 09:06:40 localhost kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
>maj 27 09:06:40 localhost kernel: ata1.00: Entering standby power mode
>maj 27 09:06:40 localhost kernel: e1000e: EEE TX LPI TIMER: 00000000
>maj 27 09:06:40 localhost kernel: ACPI: EC: interrupt blocked
>maj 27 09:06:40 localhost kernel: ACPI: PM: Preparing to enter system sleep state S3
>maj 27 09:06:40 localhost kernel: ACPI: EC: event blocked
>maj 27 09:06:40 localhost kernel: ACPI: EC: EC stopped
>maj 27 09:06:40 localhost kernel: ACPI: PM: Saving platform NVS memory
>maj 27 09:06:40 localhost kernel: Disabling non-boot CPUs ...
>maj 27 09:06:40 localhost kernel: smpboot: CPU 1 is now offline
>maj 27 09:06:40 localhost kernel: smpboot: CPU 2 is now offline
>maj 27 09:06:40 localhost kernel: smpboot: CPU 3 is now offline
>
>    IIUC the lines between my previous comment and here belongs to (sucessful)suspending, albeit the timestamps belong to resume.
>    I beleive it is somewhere in this pass the problem exist when it fails, but it is then not gettin logged because storing of this pass to the journal is not performed untill resuming?
>
>maj 27 09:06:40 localhost kernel: ACPI: PM: Low-level resume complete
>maj 27 09:06:40 localhost kernel: ACPI: EC: EC started
>maj 27 09:06:40 localhost kernel: ACPI: PM: Restoring platform NVS memory
>maj 27 09:06:40 localhost kernel: Enabling non-boot CPUs ...
>maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
>maj 27 09:06:40 localhost kernel: CPU1 is up
>maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
>maj 27 09:06:40 localhost kernel: CPU2 is up
>maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 3 APIC 0x5
>maj 27 09:06:40 localhost kernel: CPU3 is up
>maj 27 09:06:40 localhost kernel: ACPI: PM: Waking up from system sleep state S3
>maj 27 09:06:40 localhost kernel: ACPI: EC: interrupt unblocked
>maj 27 09:06:40 localhost kernel: sdhci-pci 0000:0d:00.0: MMC controller base frequency changed to 50Mhz.
>maj 27 09:06:40 localhost kernel: ACPI: EC: event unblocked
>maj 27 09:06:40 localhost kernel: tpm tpm0: TPM is disabled/deactivated (0x6)
>maj 27 09:06:40 localhost kernel: usb 1-1.6: reset high-speed USB device number 4 using ehci-pci
>maj 27 09:06:40 localhost kernel: ata6: SATA link down (SStatus 0 SControl 300)
>maj 27 09:06:40 localhost kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
>maj 27 09:06:40 localhost kernel: ata1.00: Entering active power mode
>maj 27 09:06:40 localhost kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>maj 27 09:06:40 localhost kernel: ata5: SATA link down (SStatus 0 SControl 300)
>maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0(SECURITY FREEZE LOCK) filtered out
>maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0(SET FEATURES) filtered out
>maj 27 09:06:40 localhost kernel: sd 0:0:0:0: [sda] Starting disk
>maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0(SECURITY FREEZE LOCK) filtered out
>maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0(SET FEATURES) filtered out
>maj 27 09:06:40 localhost kernel: ata2.00: configured for UDMA/100
>maj 27 09:06:40 localhost kernel: ata1.00: configured for UDMA/133
>maj 27 09:06:40 localhost kernel: usb 1-1.4: reset full-speed USB device number 3 using ehci-pci
>maj 27 09:06:40 localhost kernel: sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
>maj 27 09:06:40 localhost kernel: iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1
>maj 27 09:06:40 localhost kernel: firewire_core 0000:0d:00.3: rediscovered device fw0
>maj 27 09:06:40 localhost kernel: psmouse serio1: synaptics: queried max coordinates: x [..5888], y [..4820]
>maj 27 09:06:40 localhost kernel: iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1
>maj 27 09:06:40 localhost kernel: OOM killer enabled.
>maj 27 09:06:40 localhost rtkit-daemon[1127]: The canary thread is apparently starving. Taking action.
>maj 27 09:06:40 localhost systemd[1]: Starting systemd-rfkill.service...
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Demoting known real-time threads.
>maj 27 09:06:40 localhost kernel: Restarting tasks ... done.
>maj 27 09:06:40 localhost kernel: random: crng reseeded on system resumption
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 10218 of process 9907.
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7513 of process 7421.
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7512 of process 7421.
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7421 of process 7421.
>maj 27 09:06:40 localhost rtkit-daemon[1127]: Demoted 4 threads.
>maj 27 09:06:40 localhost kernel: Bluetooth: MGMT ver 1.22
>maj 27 09:06:40 localhost systemd-sleep[184194]: System returned from sleep state.
>maj 27 09:06:40 localhost kernel: PM: suspend exit
>maj 27 09:06:40 localhost systemd[1]: systemd-suspend.service: Deactivated successfully.
>maj 27 09:06:40 localhost pulseaudio[7421]: Could not find org.bluez.BatteryProviderManager1.RegisterBatteryProvider(), is bluetoothd started with experimental features enabled (-E flag)?
>maj 27 09:06:40 localhost systemd[1]: Finished systemd-suspend.service.
>maj 27 09:06:40 localhost systemd[1]: Stopped target sleep.target.
>maj 27 09:06:40 localhost systemd[1]: Reached target suspend.target.
>maj 27 09:06:40 localhost systemd[1]: Stopped target suspend.target.
>maj 27 09:06:40 localhost systemd-logind[1140]: Operation 'sleep' finished.
>maj 27 09:06:40 localhost systemd[1]: Stopped target bluetooth.target.
>maj 27 09:06:40 localhost systemd[1]: Started systemd-rfkill.service.
>maj 27 09:06:40 localhost systemd[1]: Reached target bluetooth.target.
>maj 27 09:06:40 localhost systemd[7288]: Reached target bluetooth.target.
>
>...and all is OK

maj 27 09:05:44 localhost systemd-logind[1140]: The system will suspend now!
maj 27 09:05:44 localhost kscreenlocker_greet[184183]: Qt: Session management error: networkIdsList argument is NULL
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: kf.kirigami: Failed to find a Kirigami platform plugin
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: file:///usr/share/plasma/look-and-feel/org.kde.breeze.desktop/contents/components/VirtualKeyboard.qml:8:1: module "QtQuick.VirtualKeyboard" is not installed
maj 27 09:05:45 localhost systemd[1]: Reached target sleep.target.
maj 27 09:05:45 localhost systemd[1]: Starting systemd-suspend.service...


    For a failed suspend, here is where journal log ends.


maj 27 09:05:45 localhost systemd-sleep[184194]: Entering sleep state 'suspend'...
maj 27 09:05:45 localhost kernel: PM: suspend entry (deep)
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
maj 27 09:05:45 localhost kscreenlocker_greet[184183]: QXcbClipboard: SelectionRequest too old
maj 27 09:05:45 localhost kernel: Filesystems sync: 0.042 seconds
maj 27 09:06:40 localhost kernel: Freezing user space processes
maj 27 09:06:40 localhost kernel: Freezing user space processes completed (elapsed 0.004 seconds)
maj 27 09:06:40 localhost kernel: OOM killer disabled.
maj 27 09:06:40 localhost kernel: Freezing remaining freezable tasks
maj 27 09:06:40 localhost kernel: Freezing remaining freezable tasks completed (elapsed 0.000 seconds)
maj 27 09:06:40 localhost kernel: printk: Suspending console(s) (use no_console_suspend to debug)
maj 27 09:06:40 localhost kernel: wlp3s0: deauthenticating from c0:06:c3:d6:9b:a3 by local choice (Reason: 3=DEAUTH_LEAVING)
maj 27 09:06:40 localhost kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
maj 27 09:06:40 localhost kernel: ata1.00: Entering standby power mode
maj 27 09:06:40 localhost kernel: e1000e: EEE TX LPI TIMER: 00000000
maj 27 09:06:40 localhost kernel: ACPI: EC: interrupt blocked
maj 27 09:06:40 localhost kernel: ACPI: PM: Preparing to enter system sleep state S3
maj 27 09:06:40 localhost kernel: ACPI: EC: event blocked
maj 27 09:06:40 localhost kernel: ACPI: EC: EC stopped
maj 27 09:06:40 localhost kernel: ACPI: PM: Saving platform NVS memory
maj 27 09:06:40 localhost kernel: Disabling non-boot CPUs ...
maj 27 09:06:40 localhost kernel: smpboot: CPU 1 is now offline
maj 27 09:06:40 localhost kernel: smpboot: CPU 2 is now offline
maj 27 09:06:40 localhost kernel: smpboot: CPU 3 is now offline

    IIUC the lines between my previous comment and here belongs to (sucessful)suspending, albeit the timestamps belong to resume.
    I beleive it is somewhere in this pass the problem exist when it fails, but it is then not gettin logged because storing of this pass to the journal is not performed untill resuming?

maj 27 09:06:40 localhost kernel: ACPI: PM: Low-level resume complete
maj 27 09:06:40 localhost kernel: ACPI: EC: EC started
maj 27 09:06:40 localhost kernel: ACPI: PM: Restoring platform NVS memory
maj 27 09:06:40 localhost kernel: Enabling non-boot CPUs ...
maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
maj 27 09:06:40 localhost kernel: CPU1 is up
maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
maj 27 09:06:40 localhost kernel: CPU2 is up
maj 27 09:06:40 localhost kernel: smpboot: Booting Node 0 Processor 3 APIC 0x5
maj 27 09:06:40 localhost kernel: CPU3 is up
maj 27 09:06:40 localhost kernel: ACPI: PM: Waking up from system sleep state S3
maj 27 09:06:40 localhost kernel: ACPI: EC: interrupt unblocked
maj 27 09:06:40 localhost kernel: sdhci-pci 0000:0d:00.0: MMC controller base frequency changed to 50Mhz.
maj 27 09:06:40 localhost kernel: ACPI: EC: event unblocked
maj 27 09:06:40 localhost kernel: tpm tpm0: TPM is disabled/deactivated (0x6)
maj 27 09:06:40 localhost kernel: usb 1-1.6: reset high-speed USB device number 4 using ehci-pci
maj 27 09:06:40 localhost kernel: ata6: SATA link down (SStatus 0 SControl 300)
maj 27 09:06:40 localhost kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
maj 27 09:06:40 localhost kernel: ata1.00: Entering active power mode
maj 27 09:06:40 localhost kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
maj 27 09:06:40 localhost kernel: ata5: SATA link down (SStatus 0 SControl 300)
maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0(SECURITY FREEZE LOCK) filtered out
maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0(SET FEATURES) filtered out
maj 27 09:06:40 localhost kernel: sd 0:0:0:0: [sda] Starting disk
maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0(SECURITY FREEZE LOCK) filtered out
maj 27 09:06:40 localhost kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0(SET FEATURES) filtered out
maj 27 09:06:40 localhost kernel: ata2.00: configured for UDMA/100
maj 27 09:06:40 localhost kernel: ata1.00: configured for UDMA/133
maj 27 09:06:40 localhost kernel: usb 1-1.4: reset full-speed USB device number 3 using ehci-pci
maj 27 09:06:40 localhost kernel: sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
maj 27 09:06:40 localhost kernel: iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1
maj 27 09:06:40 localhost kernel: firewire_core 0000:0d:00.3: rediscovered device fw0
maj 27 09:06:40 localhost kernel: psmouse serio1: synaptics: queried max coordinates: x [..5888], y [..4820]
maj 27 09:06:40 localhost kernel: iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1
maj 27 09:06:40 localhost kernel: OOM killer enabled.
maj 27 09:06:40 localhost rtkit-daemon[1127]: The canary thread is apparently starving. Taking action.
maj 27 09:06:40 localhost systemd[1]: Starting systemd-rfkill.service...
maj 27 09:06:40 localhost rtkit-daemon[1127]: Demoting known real-time threads.
maj 27 09:06:40 localhost kernel: Restarting tasks ... done.
maj 27 09:06:40 localhost kernel: random: crng reseeded on system resumption
maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 10218 of process 9907.
maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7513 of process 7421.
maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7512 of process 7421.
maj 27 09:06:40 localhost rtkit-daemon[1127]: Successfully demoted thread 7421 of process 7421.
maj 27 09:06:40 localhost rtkit-daemon[1127]: Demoted 4 threads.
maj 27 09:06:40 localhost kernel: Bluetooth: MGMT ver 1.22
maj 27 09:06:40 localhost systemd-sleep[184194]: System returned from sleep state.
maj 27 09:06:40 localhost kernel: PM: suspend exit
maj 27 09:06:40 localhost systemd[1]: systemd-suspend.service: Deactivated successfully.
maj 27 09:06:40 localhost pulseaudio[7421]: Could not find org.bluez.BatteryProviderManager1.RegisterBatteryProvider(), is bluetoothd started with experimental features enabled (-E flag)?
maj 27 09:06:40 localhost systemd[1]: Finished systemd-suspend.service.
maj 27 09:06:40 localhost systemd[1]: Stopped target sleep.target.
maj 27 09:06:40 localhost systemd[1]: Reached target suspend.target.
maj 27 09:06:40 localhost systemd[1]: Stopped target suspend.target.
maj 27 09:06:40 localhost systemd-logind[1140]: Operation 'sleep' finished.
maj 27 09:06:40 localhost systemd[1]: Stopped target bluetooth.target.
maj 27 09:06:40 localhost systemd[1]: Started systemd-rfkill.service.
maj 27 09:06:40 localhost systemd[1]: Reached target bluetooth.target.
maj 27 09:06:40 localhost systemd[7288]: Reached target bluetooth.target.

...and all is OK

Actions: View

Attachments on bug 33246: 14549