Systemd continually failing to hibernate in Ubuntu 21.10?

crabfanatic · May 2, 2022, 2:42pm

Last night as I went to bed, I closed the lid on my Framework laptop.

When I woke up this morning, I opened the lid, and the screen was blank. After smashing some keyboard buttons and pressing the power button, the display eventually came on and I was able to log in and resume my session.

A few seconds later, the screen went blank and became unresponsive. I then closed the lid and opened it again, and roughly 20 seconds later the screen came alive and I was able to log in again.

Then, less than a minute later, the screen went blank again.

This process repeated 4-5 times before I got bored and turned the machine off. It didn’t want to fully shut down, so I had to long-press the power button and it eventually shut off.

Upon rebooting, the machine is back to normal. The kernel log shows an infinite loop of these messages for the last 7 hours:

May  1 12:48:16 c4 kernel: [278122.269063] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.290272] audit: type=1107 audit(1651434496.143:4851): pid=1054 uid=103 auid=4294967295 ses=4294967295 subj=unconfined msg='apparmor="DENIED" operation="dbus_signal"  bus="system" path="/org/freedesktop/login1" interface="org.freedesktop.login1.Manager" member="PrepareForSleep" name=":1.14" mask="receive" pid=518409 label="snap.firefox.firefox" peer_pid=1083 peer_label="unconfined"
May  1 12:48:16 c4 kernel: [278122.290272]  exe="/usr/bin/dbus-daemon" sauid=103 hostname=? addr=? terminal=?'
May  1 12:48:16 c4 kernel: [278122.292272] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.295013] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.297245] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.298905] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.303494] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.304421] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.307730] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.308052] wlp170s0: deauthenticating from f6:9f:c2:72:1a:38 by local choice (Reason: 3=DEAUTH_LEAVING)
May  1 12:48:16 c4 kernel: [278122.308493] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.317182] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.328832] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
May  1 12:48:16 c4 kernel: [278122.509970] PM: suspend entry (deep)
May  1 12:48:16 c4 kernel: [278122.513294] Filesystems sync: 0.003 seconds
May  1 12:48:19 c4 kernel: [278122.516525] Freezing user space processes ... (elapsed 0.033 seconds) done.
May  1 12:48:19 c4 kernel: [278122.550257] OOM killer disabled.
May  1 12:48:19 c4 kernel: [278122.550259] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
May  1 12:48:19 c4 kernel: [278122.551885] printk: Suspending console(s) (use no_console_suspend to debug)
May  1 12:48:19 c4 kernel: [278124.554447] ACPI: EC: interrupt blocked
May  1 12:48:19 c4 kernel: [278124.559535] ------------[ cut here ]------------
May  1 12:48:19 c4 kernel: [278124.559537] thunderbolt 0000:00:0d.3: RX ring 0 already stopped
May  1 12:48:19 c4 kernel: [278124.559540] ------------[ cut here ]------------
May  1 12:48:19 c4 kernel: [278124.559541] thunderbolt 0000:00:0d.2: RX ring 0 already stopped
May  1 12:48:19 c4 kernel: [278124.559598] WARNING: CPU: 1 PID: 519525 at drivers/thunderbolt/nhi.c:710 tb_ring_stop+0x95/0x1f0 [thunderbolt]
May  1 12:48:19 c4 kernel: [278124.559598] WARNING: CPU: 6 PID: 524470 at drivers/thunderbolt/nhi.c:710 tb_ring_stop+0x95/0x1f0 [thunderbolt]
May  1 12:48:19 c4 kernel: [278124.559611] Modules linked in: r8153_ecm
May  1 12:48:19 c4 kernel: [278124.559612] Modules linked in:
May  1 12:48:19 c4 kernel: [278124.559612]  cdc_ether usbnet
May  1 12:48:19 c4 kernel: [278124.559613]  r8153_ecm
...
May  1 12:48:19 c4 kernel: [278125.058319] thunderbolt 0000:00:0d.2: PM: failed to suspend async: error -110
May  1 12:48:19 c4 kernel: [278125.058306] PM: pci_pm_suspend_noirq(): nhi_suspend_noirq+0x0/0x70 [thunderbolt] returns -110
May  1 12:48:19 c4 kernel: [278125.058331] PM: dpm_run_callback(): pci_pm_suspend_noirq+0x0/0x2d0 returns -110
May  1 12:48:19 c4 kernel: [278125.058338] thunderbolt 0000:00:0d.3: PM: failed to suspend async: error -110
May  1 12:48:19 c4 kernel: [278125.058482] ACPI: EC: interrupt unblocked
May  1 12:48:19 c4 kernel: [278125.405851] PM: noirq suspend of devices failed
May  1 12:48:19 c4 kernel: [278125.547269] nvme nvme0: 8/0/0 default/read/poll queues
May  1 12:48:19 c4 kernel: [278125.719572] acpi LNXPOWER:0f: Turning OFF
May  1 12:48:19 c4 kernel: [278125.721227] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_component_ops [i915])
May  1 12:48:19 c4 kernel: [278125.721544] acpi LNXPOWER:0b: Turning OFF
May  1 12:48:19 c4 kernel: [278125.722163] acpi LNXPOWER:07: Turning OFF
May  1 12:48:19 c4 kernel: [278125.722181] acpi LNXPOWER:06: Turning OFF
May  1 12:48:19 c4 kernel: [278125.722638] OOM killer enabled.
May  1 12:48:19 c4 kernel: [278125.722639] Restarting tasks ... done.
May  1 12:48:19 c4 kernel: [278125.738612] PM: suspend exit
May  1 12:48:19 c4 kernel: [278125.738653] PM: suspend entry (s2idle)
May  1 12:48:22 c4 kernel: [278125.747427] Filesystems sync: 0.008 seconds
May  1 12:48:22 c4 kernel: [278125.747675] Freezing user space processes ... (elapsed 0.008 seconds) done.
May  1 12:48:22 c4 kernel: [278125.756174] OOM killer disabled.
May  1 12:48:22 c4 kernel: [278125.756174] Freezing remaining freezable tasks ... (elapsed 0.021 seconds) done.
May  1 12:48:22 c4 kernel: [278125.778167] printk: Suspending console(s) (use no_console_suspend to debug)
May  1 12:48:22 c4 kernel: [278127.086559] ACPI: EC: interrupt blocked
May  1 12:48:22 c4 kernel: [278127.091209] ------------[ cut here ]------------
May  1 12:48:22 c4 kernel: [278127.091211] thunderbolt 0000:00:0d.3: RX ring 0 already stopped
May  1 12:48:22 c4 kernel: [278127.091214] ------------[ cut here ]------------
May  1 12:48:22 c4 kernel: [278127.091215] thunderbolt 0000:00:0d.2: RX ring 0 already stopped
May  1 12:48:22 c4 kernel: [278127.091271] WARNING: CPU: 5 PID: 524478 at drivers/thunderbolt/nhi.c:710 tb_ring_stop+0x95/0x1f0 [thunderbolt]
May  1 12:48:22 c4 kernel: [278127.091271] WARNING: CPU: 0 PID: 524489 at drivers/thunderbolt/nhi.c:710 tb_ring_stop+0x95/0x1f0 [thunderbolt]
...

My install is a pretty vanilla install of 21.10 except for that I enabled the deep sleep:

$ cat /sys/power/mem_sleep
s2idle [deep]

Has anybody else experienced this?

Water261 · May 2, 2022, 11:33pm

The error is right there, systemd is unable to hibernate due to kernel lockdown. This is an intentional feature and is used when the system is booted with Secure Boot on. If you need hibernate than you can disable secure boot but it does come with security risks. Otherwise I’d just shutdown the machine whenever it’s not in use for over 30 minutes.

crabfanatic · May 3, 2022, 4:40pm

Thank you for that! I did not know that secure boot prevents hibernation. If I had read the kernel_lockdown man page more carefully, I would have seen this:

       On an EFI-enabled x86 or arm64 machine, lockdown will be  automatically
       enabled if the system boots in EFI Secure Boot mode.

mackncheesiest · May 3, 2022, 6:35pm

In the meantime, there are a couple of blog posts from someone who’s done work on kernel patchsets to make hibernation play nice with kernel lockdown, and they’re a pretty fun read by themselves imo

Chiraag_Nataraj · May 4, 2022, 1:34pm

I found this out the hard way on my desktop (I regularly use hibernate on all of my devices) and have disabled secure boot ever since. The funniest part is that the particular issue that led to them disabling hibernate with secure boot (the fact that swap is often encrypted) isn’t an issue on my system (swap is an LVM volume inside an encrypted partition, as are / and /home) so as I understand it, the main threat vector they’re defending against here (by disabling hibernate) doesn’t really apply to me(?).

Ah well. I’ll wait for hibernate to become supported with secure boot enabled, I guess.