You are not logged in.
Hello there!
Firstly a quick description of my problem:
When I try to run "systemctl hibernate", my screen goes black, power button is flickering as it used to do while generation hibernation image but instead of taking a while to write the systems state to swap, the screen turn on again after less then a second and the system unfreezes itself to be present in the same state as before trying to hibernate.
I've been using Arch for a few years now and used to hibernate from time to time. As I don't use this feature that often (usually only every few weeks or months) I cannot really tell when the problem did started.
The problem first appeared after a kernel update to versions beyond 5.0. Back then I was able to "fix" it by using linux-lts kernel instead, but recently this was updated from 4.19 to 5.4 too, leaving me with the problem again. Also tried switching back to the mainline kernel but with no benefit.
For hibernation, I use a swap file on f2fs inside a luks encrypted root partition, that used to work pretty well for a long time. I already tried to regenerate the swap file (using dd instead of fallocate as I know of the issues the latter has with f2fs), my swap file is larger then my RAM, gets mounted correctly on a normal boot and I also double checked the file_offset kernel parameter.
Does anybody have any idea on how to fix this?
When the problem first appeared back then, I searched through several logs but all I could read from them was the system was freezing and unfreezing shortly after. Surely I can provide logs, if anybody can tell me, how I could try to get some which are verbose enough so they are of an actual use.
Great thanks in advance!
Sarius
EDIT:
Eventually took a look at the log again, sadly still no idea what's causing the issue. After all, here is the relevant part of the log:
Feb 15 13:29:54 phoenix audit[2298]: USER_ACCT pid=2298 uid=1000 auid=1000 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="sarius" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix sudo[2298]: sarius : TTY=pts/0 ; PWD=/home/sarius ; USER=root ; COMMAND=/usr/bin/systemctl hibernate
Feb 15 13:29:54 phoenix audit[2298]: CRED_REFR pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix kernel: audit: type=1101 audit(1581769794.553:52): pid=2298 uid=1000 auid=1000 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="sarius" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix kernel: audit: type=1110 audit(1581769794.553:53): pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix sudo[2298]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 15 13:29:54 phoenix audit[2298]: USER_START pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix kernel: audit: type=1105 audit(1581769794.563:54): pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix sudo[2298]: pam_unix(sudo:session): session closed for user root
Feb 15 13:29:54 phoenix audit[2298]: USER_END pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix audit[2298]: CRED_DISP pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix kernel: audit: type=1106 audit(1581769794.673:55): pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:54 phoenix kernel: audit: type=1104 audit(1581769794.673:56): pid=2298 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
Feb 15 13:29:59 phoenix systemd-logind[970]: Delay lock is active (UID 1000/sarius, PID 1129/xss-lock) but inhibitor timeout is reached.
Feb 15 13:29:59 phoenix systemd[1]: Reached target Sleep.
Feb 15 13:29:59 phoenix systemd[1]: Starting autorandr execution hook...
Feb 15 13:29:59 phoenix systemd[1]: Starting Hibernate...
Feb 15 13:30:00 phoenix systemd-sleep[2314]: Suspending system...
Feb 15 13:30:00 phoenix kernel: PM: hibernation entry
Feb 15 13:30:02 phoenix kernel: Filesystems sync: 0.013 seconds
Feb 15 13:30:02 phoenix kernel: Freezing user space processes ... (elapsed 0.166 seconds) done.
Feb 15 13:30:02 phoenix kernel: OOM killer disabled.
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x00000000-0x00000fff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x00058000-0x00058fff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x0008c000-0x000fffff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x6c7ba000-0x6c7bafff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x6c7c8000-0x6c7c9fff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [meMy Hauppauge PVR-250 remote just doesn't work any more, after installing a recent kernel version. Actually, I just did it a few hours ago ;).m 0x6c7d9000-0x6c7d9fff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x70e12000-0x70e13fff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x7a779000-0x7befefff]
Feb 15 13:30:02 phoenix kernel: PM: Marking nosave pages: [mem 0x7bf00000-0xffffffff]
Feb 15 13:30:02 phoenix kernel: PM: Basic memory bitmaps created
Feb 15 13:30:02 phoenix kernel: PM: Preallocating image memory... done (allocated 945862 pages)
Feb 15 13:30:02 phoenix kernel: PM: Allocated 3783448 kbytes in 0.55 seconds (6878.99 MB/s)
Feb 15 13:30:02 phoenix kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Feb 15 13:30:02 phoenix kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Feb 15 13:30:02 phoenix kernel: wlp5s0: deauthenticating from 34:81:c4:28:63:d2 by local choice (Reason: 3=DEAUTH_LEAVING)
Feb 15 13:30:02 phoenix kernel: ACPI: EC: interrupt blocked
Feb 15 13:30:02 phoenix kernel: ACPI: Preparing to enter system sleep state S4
Feb 15 13:30:02 phoenix kernel: ACPI: EC: event blocked
Feb 15 13:30:02 phoenix kernel: ACPI: EC: EC stopped
Feb 15 13:30:02 phoenix kernel: PM: Saving platform NVS memory
Feb 15 13:30:02 phoenix kernel: Disabling non-boot CPUs ...
Feb 15 13:30:02 phoenix kernel: smpboot: CPU 1 is now offline
Feb 15 13:30:02 phoenix kernel: smpboot: CPU 2 is now offline
Feb 15 13:30:02 phoenix kernel: smpboot: CPU 3 is now offline
Feb 15 13:30:02 phoenix kernel: PM: Creating hibernation image:
Feb 15 13:30:02 phoenix kernel: PM: Need to copy 940980 pages
Feb 15 13:30:02 phoenix kernel: PM: Normal pages needed: 940980 + 1024, available pages: 3228178
Feb 15 13:30:02 phoenix kernel: PM: Hibernation image created (940980 pages copied)
Feb 15 13:30:02 phoenix kernel: PM: Restoring platform NVS memory
Feb 15 13:30:02 phoenix kernel: ACPI: EC: EC started
Feb 15 13:30:02 phoenix kernel: Enabling non-boot CPUs ...
Feb 15 13:30:02 phoenix kernel: x86: Booting SMP configuration:
Feb 15 13:30:02 phoenix kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Feb 15 13:30:02 phoenix kernel: CPU1 is up
Feb 15 13:30:02 phoenix kernel: smpboot: Booting Node 0 Processor 2 APIC 0x1
Feb 15 13:30:02 phoenix kernel: CPU2 is up
Feb 15 13:30:02 phoenix kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Feb 15 13:30:02 phoenix kernel: CPU3 is up
Feb 15 13:30:02 phoenix kernel: ACPI: Waking up from system sleep state S4
Feb 15 13:30:02 phoenix kernel: ACPI: EC: interrupt unblocked
Feb 15 13:30:02 phoenix kernel: ACPI: EC: event unblocked
Feb 15 13:30:02 phoenix kernel: r8169 0000:04:00.0 enp4s0: Link is Down
Feb 15 13:30:02 phoenix kernel: nvme nvme0: 4/0/0 default/read/poll queues
Feb 15 13:30:02 phoenix kernel: ath10k_pci 0000:05:00.0: unsupported HTC service id: 1536
Feb 15 13:30:02 phoenix kernel: acpi LNXPOWER:01: Turning OFF
Feb 15 13:30:02 phoenix kernel: mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_component_ops [i915])
Feb 15 13:30:02 phoenix kernel: PM: Cannot find swap device, try swapon -a
Feb 15 13:30:02 phoenix kernel: PM: Cannot get swap writer
Feb 15 13:30:02 phoenix kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Feb 15 13:30:02 phoenix kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Feb 15 13:30:02 phoenix kernel: ata1.00: supports DRM functions and may not be fully accessible
Feb 15 13:30:02 phoenix kernel: ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
Feb 15 13:30:02 phoenix kernel: ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Feb 15 13:30:02 phoenix kernel: ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) rejected by device (Stat=0x51 Err=0x04)
Feb 15 13:30:02 phoenix kernel: ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Feb 15 13:30:02 phoenix kernel: ata2.00: configured for UDMA/133
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Feb 15 13:30:02 phoenix kernel: ata1.00: ACPI cmd ef/10:09:00:00:00:a0 (SET FEATURES) succeeded
Feb 15 13:30:02 phoenix kernel: ata1.00: supports DRM functions and may not be fully accessible
Feb 15 13:30:02 phoenix kernel: ata1.00: configured for UDMA/133
Feb 15 13:30:02 phoenix kernel: ata1.00: Enabling discard_zeroes_data
Feb 15 13:30:02 phoenix kernel: PM: Basic memory bitmaps freed
Feb 15 13:30:02 phoenix kernel: OOM killer enabled.
Feb 15 13:30:02 phoenix kernel: Restarting tasks ... done.
Feb 15 13:30:02 phoenix wpa_supplicant[968]: wlp5s0: CTRL-EVENT-DISCONNECTED bssid=34:81:c4:28:63:d2 reason=3 locally_generated=1
Feb 15 13:30:02 phoenix wpa_supplicant[968]: wlp5s0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Feb 15 13:30:02 phoenix pulseaudio[1268]: W: [alsa-sink-CX20753/4 Analog] alsa-util.c: Could not recover alsa device from SUSPENDED state, trying to restart PCM
Feb 15 13:30:02 phoenix systemd-networkd[420]: wlp5s0: Lost carrier
Feb 15 13:30:02 phoenix systemd-timesyncd[954]: No network connectivity, watching for changes.
Feb 15 13:30:02 phoenix kernel: PM: hibernation exit
Feb 15 13:30:02 phoenix systemd-sleep[2314]: Failed to suspend system. System resumed again: No such device
Feb 15 13:30:02 phoenix systemd[1]: systemd-hibernate.service: Main process exited, code=exited, status=1/FAILURE
Feb 15 13:30:02 phoenix systemd[1]: systemd-hibernate.service: Failed with result 'exit-code'.
Feb 15 13:30:02 phoenix systemd[1]: Failed to start Hibernate.
Feb 15 13:30:02 phoenix systemd[1]: Dependency failed for Hibernate.
Feb 15 13:30:02 phoenix systemd[1]: hibernate.target: Job hibernate.target/start failed with result 'dependency'.
Feb 15 13:30:02 phoenix systemd[1]: Stopped target Sleep.
Feb 15 13:30:02 phoenix audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hibernate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Feb 15 13:30:02 phoenix systemd-logind[970]: Operation 'sleep' finished.
Feb 15 13:30:02 phoenix systemd-networkd[420]: lo: Reset carrier
Feb 15 13:30:02 phoenix kernel: audit: type=1130 audit(1581769802.849:57): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hibernate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'While I think those are probably the most important lines:
Feb 15 13:30:02 phoenix systemd-sleep[2314]: Failed to suspend system. System resumed again: No such device
Feb 15 13:30:02 phoenix systemd[1]: systemd-hibernate.service: Main process exited, code=exited, status=1/FAILURE
Feb 15 13:30:02 phoenix systemd[1]: systemd-hibernate.service: Failed with result 'exit-code'.
Feb 15 13:30:02 phoenix systemd[1]: Failed to start Hibernate.
Feb 15 13:30:02 phoenix systemd[1]: Dependency failed for Hibernate.
Feb 15 13:30:02 phoenix systemd[1]: hibernate.target: Job hibernate.target/start failed with result 'dependency'.
Feb 15 13:30:02 phoenix systemd[1]: Stopped target Sleep.
Feb 15 13:30:02 phoenix audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hibernate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'FINAL EDIT:
I recently came across this https://bugs.archlinux.org/task/63841
Seems like my issue is related to f2fs and f2fs only...
Just fired up a virtual machine to test things and yes, swap file on f2fs fails while it's possible to hibernate successfully on ext4 basis.
So if anybody comes across reading this I can only advise you to just change your root filesystem...
Last edited by sarius (2020-02-15 19:37:44)
Offline