Librem14/byzantium: hybernation stopped working

Hardware
1

Below is what I get in dmesg at the moment when I try to hibernate using Fn-Esc on my Librem14 running byzantium and Gnome/Xorg. I’m sure this worked after my last reboot, but it eventually stopped working.

The notebook seems to enter hybernation, display and external monitor turn black, but the white power led stays solid and doesn’t start to dim. System comes back after a few moments.

Anybody else observing this? Any idea where to start to debug it?

I already looked briefly at the mentioned PID and PPID: PID didn’t exist anymore after the hybernation attempt and PPID is systemd --user. journalctrl does not show any interesting messages for those two PIDs at all.

[238976.430231] net_ratelimit: 242090 callbacks suppressed
[238976.430234] r8169 0000:02:00.0 eth0: Link is Down
[238981.424928] PM: suspend entry (deep)
[238981.447224] Filesystems sync: 0.022 seconds
[238981.447936] (NULL device *): firmware: direct-loading firmware brcm/BCM20702A1-0b05-17cb.hcd
[238981.447967] Freezing user space processes ... 
[239001.455257] Freezing of tasks failed after 20.007 seconds (2 tasks refusing to freeze, wq_busy=0):
[239001.455612] task:pool-org.gnome. state:D stack:    0 pid: 1964 ppid:  2535 flags:0x00004004
[239001.455619] Call Trace:
[239001.455632]  __schedule+0x282/0x870
[239001.455639]  schedule+0x46/0xb0
[239001.455652]  request_wait_answer+0x137/0x220 [fuse]
[239001.455659]  ? add_wait_queue_exclusive+0x70/0x70
[239001.455668]  fuse_simple_request+0x1a1/0x310 [fuse]
[239001.455677]  fuse_dentry_revalidate+0x17a/0x380 [fuse]
[239001.455686]  lookup_fast+0xd7/0x150
[239001.455690]  walk_component+0x41/0x1d0
[239001.455695]  path_lookupat+0x73/0x1c0
[239001.455700]  filename_lookup+0xaa/0x1b0
[239001.455706]  ? getname_flags.part.0+0x45/0x1a0
[239001.455711]  vfs_statx+0x74/0x130
[239001.455717]  do_statx+0x40/0x80
[239001.455722]  ? switch_fpu_return+0x40/0xb0
[239001.455728]  ? exit_to_user_mode_prepare+0x6e/0x120
[239001.455732]  __x64_sys_statx+0x21/0x30
[239001.455737]  do_syscall_64+0x33/0x80
[239001.455743]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[239001.455748] RIP: 0033:0x7f6f2178d74a
[239001.455751] RSP: 002b:00007f6f16ffb7a8 EFLAGS: 00000202 ORIG_RAX: 000000000000014c
[239001.455755] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f6f2178d74a
[239001.455758] RDX: 0000000000000900 RSI: 00007f6f08008fb0 RDI: 00000000ffffff9c
[239001.455760] RBP: 00007f6f16ffca80 R08: 00007f6f16ffb820 R09: 0000000000100006
[239001.455762] R10: 0000000000000fff R11: 0000000000000202 R12: 00007f6ef4003210
[239001.455764] R13: 00007f6f08008fb0 R14: 00007f6edc02e120 R15: 00007f6f0800a030
[239001.455770] task:pool-org.gnome. state:D stack:    0 pid: 1965 ppid:  2535 flags:0x00004004
[239001.455774] Call Trace:
[239001.455779]  __schedule+0x282/0x870
[239001.455783]  schedule+0x46/0xb0
[239001.455791]  request_wait_answer+0x137/0x220 [fuse]
[239001.455796]  ? add_wait_queue_exclusive+0x70/0x70
[239001.455803]  fuse_simple_request+0x1a1/0x310 [fuse]
[239001.455811]  fuse_dentry_revalidate+0x17a/0x380 [fuse]
[239001.455818]  lookup_fast+0xd7/0x150
[239001.455821]  walk_component+0x41/0x1d0
[239001.455825]  path_lookupat+0x73/0x1c0
[239001.455830]  filename_lookup+0xaa/0x1b0
[239001.455835]  ? getname_flags.part.0+0x45/0x1a0
[239001.455840]  vfs_statx+0x74/0x130
[239001.455845]  do_statx+0x40/0x80
[239001.455850]  ? switch_fpu_return+0x40/0xb0
[239001.455854]  ? exit_to_user_mode_prepare+0x6e/0x120
[239001.455858]  __x64_sys_statx+0x21/0x30
[239001.455862]  do_syscall_64+0x33/0x80
[239001.455867]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[239001.455870] RIP: 0033:0x7f6f2178d74a
[239001.455872] RSP: 002b:00007f6f167fa7a8 EFLAGS: 00000206 ORIG_RAX: 000000000000014c
[239001.455876] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f6f2178d74a
[239001.455878] RDX: 0000000000000900 RSI: 000055ab2b4f0c20 RDI: 00000000ffffff9c
[239001.455880] RBP: 00007f6f167fba80 R08: 00007f6f167fa820 R09: 0000000000100006
[239001.455882] R10: 0000000000000fff R11: 0000000000000206 R12: 00007f6ef00074f0
[239001.455884] R13: 000055ab2b4f0c20 R14: 000055ab2b2bdad0 R15: 00007f6efc002520

[239001.455915] OOM killer enabled.
[239001.455916] Restarting tasks ... done.
[239001.464580] video LNXVIDEO:00: Restoring backlight state
[239001.656152] PM: suspend exit
[239001.656201] PM: suspend entry (s2idle)
[239001.674344] Filesystems sync: 0.018 seconds
[239001.674506] Freezing user space processes ... 
[239021.683315] Freezing of tasks failed after 20.008 seconds (2 tasks refusing to freeze, wq_busy=0):
[239021.683695] task:pool-org.gnome. state:D stack:    0 pid: 1964 ppid:  2535 flags:0x00004004
[239021.683702] Call Trace:
[239021.683716]  __schedule+0x282/0x870
[239021.683722]  schedule+0x46/0xb0
[239021.683735]  request_wait_answer+0x137/0x220 [fuse]
[239021.683743]  ? add_wait_queue_exclusive+0x70/0x70
[239021.683751]  fuse_simple_request+0x1a1/0x310 [fuse]
[239021.683759]  fuse_dentry_revalidate+0x17a/0x380 [fuse]
[239021.683769]  lookup_fast+0xd7/0x150
[239021.683774]  walk_component+0x41/0x1d0
[239021.683779]  path_lookupat+0x73/0x1c0
[239021.683783]  filename_lookup+0xaa/0x1b0
[239021.683789]  ? getname_flags.part.0+0x45/0x1a0
[239021.683795]  vfs_statx+0x74/0x130
[239021.683801]  do_statx+0x40/0x80
[239021.683807]  ? switch_fpu_return+0x40/0xb0
[239021.683812]  ? exit_to_user_mode_prepare+0x6e/0x120
[239021.683816]  __x64_sys_statx+0x21/0x30
[239021.683821]  do_syscall_64+0x33/0x80
[239021.683827]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[239021.683833] RIP: 0033:0x7f6f2178d74a
[239021.683836] RSP: 002b:00007f6f16ffb7a8 EFLAGS: 00000202 ORIG_RAX: 000000000000014c
[239021.683840] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f6f2178d74a
[239021.683843] RDX: 0000000000000900 RSI: 00007f6f08008fb0 RDI: 00000000ffffff9c
[239021.683845] RBP: 00007f6f16ffca80 R08: 00007f6f16ffb820 R09: 0000000000100006
[239021.683847] R10: 0000000000000fff R11: 0000000000000202 R12: 00007f6ef4003210
[239021.683849] R13: 00007f6f08008fb0 R14: 00007f6edc02e120 R15: 00007f6f0800a030
[239021.683855] task:pool-org.gnome. state:D stack:    0 pid: 1965 ppid:  2535 flags:0x00004004
[239021.683859] Call Trace:
[239021.683864]  __schedule+0x282/0x870
[239021.683868]  schedule+0x46/0xb0
[239021.683876]  request_wait_answer+0x137/0x220 [fuse]
[239021.683881]  ? add_wait_queue_exclusive+0x70/0x70
[239021.683888]  fuse_simple_request+0x1a1/0x310 [fuse]
[239021.683896]  fuse_dentry_revalidate+0x17a/0x380 [fuse]
[239021.683903]  lookup_fast+0xd7/0x150
[239021.683907]  walk_component+0x41/0x1d0
[239021.683911]  path_lookupat+0x73/0x1c0
[239021.683915]  filename_lookup+0xaa/0x1b0
[239021.683920]  ? getname_flags.part.0+0x45/0x1a0
[239021.683925]  vfs_statx+0x74/0x130
[239021.683930]  do_statx+0x40/0x80
[239021.683934]  ? switch_fpu_return+0x40/0xb0
[239021.683939]  ? exit_to_user_mode_prepare+0x6e/0x120
[239021.683943]  __x64_sys_statx+0x21/0x30
[239021.683947]  do_syscall_64+0x33/0x80
[239021.683952]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[239021.683955] RIP: 0033:0x7f6f2178d74a
[239021.683957] RSP: 002b:00007f6f167fa7a8 EFLAGS: 00000206 ORIG_RAX: 000000000000014c
[239021.683961] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f6f2178d74a
[239021.683963] RDX: 0000000000000900 RSI: 000055ab2b4f0c20 RDI: 00000000ffffff9c
[239021.683965] RBP: 00007f6f167fba80 R08: 00007f6f167fa820 R09: 0000000000100006
[239021.683967] R10: 0000000000000fff R11: 0000000000000206 R12: 00007f6ef00074f0
[239021.683969] R13: 000055ab2b4f0c20 R14: 000055ab2b2bdad0 R15: 00007f6efc002520

[239021.684001] OOM killer enabled.
[239021.684002] Restarting tasks ... done.
[239021.695773] video LNXVIDEO:00: Restoring backlight state
[239021.890604] PM: suspend exit
[239021.928198] r8169 0000:02:00.0: firmware: failed to load rtl_nic/rtl8168h-2.fw (-2)
[239021.928202] r8169 0000:02:00.0: Direct firmware load for rtl_nic/rtl8168h-2.fw failed with error -2
[239021.928207] r8169 0000:02:00.0: Unable to load firmware rtl_nic/rtl8168h-2.fw (-2)
[239021.953840] Generic FE-GE Realtek PHY r8169-200:00: attached PHY driver [Generic FE-GE Realtek PHY] (mii_bus:phy_addr=r8169-200:00, irq=IGNORE)
[239022.079452] r8169 0000:02:00.0 eth0: Link is Down
[239025.703887] r8169 0000:02:00.0 eth0: Link is Up - 1Gbps/Full - flow control off
[239025.703914] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[239027.959715] audit: type=1400 audit(1635978403.659:313): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/snap/bin/" pid=13508 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
2

Hmm, it looks like the consolidation of userspace (IE: your session) failed. This happens before your session is even written to the disk. If the image to be written to disk is not created, hibernation cannot occur. So the creation of the image failing explains why hibernation didn’t work.

Why it failed is a mystery to me. But I am curious if the upgrade didn’t upgrade components that are responsible for hibernation?

3

I usually get something similar if a process is really stuck on something, like busy reading from a remote file system. Which happens all the time because WiFi gets shut down first, and Plasma checks on my remote file systems more than it should.

I usually just kill the offending processes, or make sure they are forced out of this state (in my case, force-unmounting the filesystem).

For the more technically inclined, checking the stacks of the hanging processes (/proc/…/tasks/stack) could say what is so important that they can’t be interrupted.

4

Hm, yes, I unmounted all gvfs mounts (2x nextcloud, a few smb mounts) and tried again and I could suspend again.

I’ll have to keep an eye which mount it actually causes if the problem returns.

Thanks for pointing me in the right direction! I actually didn’t find any hint about the PID mentioned in the log I quoted. Only the PPID is known to journal and logfiles. For PID I do only find the message hinting in the direction of Gnome Thread Pools…

5

I’m usually getting file.so or kio something. kio is some kind of a thread pool, so that checks out.