20.03.2020 13:29, Carlos E. R. пишет:
Hi,
This past night I could not hibernate my desktop machine, it refused. Looking at the log, I found a clue:
<4.5> 2020-03-20 03:07:40 Telcontar sudo - - - root : TTY=pts/76 ; PWD=/root ; USER=root ; COMMAND=/usr/bin/chvt 10 <10.6> 2020-03-20 03:07:40 Telcontar sudo - - - pam_unix(sudo:session): session opened for user root by (uid=0) <10.6> 2020-03-20 03:07:41 Telcontar sudo - - - pam_unix(sudo:session): session closed for user root <4.5> 2020-03-20 03:07:46 Telcontar sudo - - - root : TTY=pts/76 ; PWD=/root ; USER=root ; COMMAND=/usr/bin/systemctl hibernate <10.6> 2020-03-20 03:07:46 Telcontar sudo - - - pam_unix(sudo:session): session opened for user root by (uid=0) <10.6> 2020-03-20 03:07:46 Telcontar sudo - - - pam_unix(sudo:session): session closed for user root <3.6> 2020-03-20 03:07:46 Telcontar systemd 1 - - Reached target Sleep. <3.6> 2020-03-20 03:07:46 Telcontar systemd 1 - - Starting Hibernate... <0.7> 2020-03-20 03:07:46 Telcontar kernel - - - [317397.413158] PM: Hibernation mode set to 'shutdown' <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - INFO: running /usr/lib/systemd/system-sleep/grub2.sleep for hibernate <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - INFO: Running prepare-grub .. <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - 2020-03-20 03:07:46+01:00 - Hibernating the system now... <3.4> 2020-03-20 03:07:46 Telcontar systemd-sh - - - Hibernating the system now... <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - service: no such service upsd.service <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - running kernel is grub menu entry Main_openSUSE (vmlinuz-4.12.14-lp151.28.40-default) <3.6> 2020-03-20 03:07:46 Telcontar systemd-sleep 14514 - - preparing boot-loader: selecting entry Main_openSUSE, kernel /boot/4.12.14-lp151.28.40-default <3.6> 2020-03-20 03:07:47 Telcontar systemd-sleep 14514 - - running /usr/sbin/grub2-once "Main_openSUSE" <3.6> 2020-03-20 03:07:47 Telcontar systemd-sleep 14514 - - time needed for sync: 0.5 seconds, time needed for grub: 0.2 seconds. <3.6> 2020-03-20 03:07:47 Telcontar systemd-sleep 14514 - - INFO: Done. <3.6> 2020-03-20 03:07:51 Telcontar systemd-sleep 14514 - - Suspending system... <0.4> 2020-03-20 03:07:51 Telcontar kernel - - - [317402.526273] PM: Tried to create trampoline again <0.6> 2020-03-20 03:07:51 Telcontar kernel - - - [317402.559008] PM: Syncing filesystems ... <3.4> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - The canary thread is apparently starving. Taking action. <3.6> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - Demoting known real-time threads. <3.5> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - Successfully demoted thread 5399 of process 5394 (/usr/bin/pulseaudio). <3.5> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - Successfully demoted thread 5398 of process 5394 (/usr/bin/pulseaudio). <3.5> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - Successfully demoted thread 5394 of process 5394 (/usr/bin/pulseaudio). <3.5> 2020-03-20 03:08:12 Telcontar rtkit-daemon 5395 - - Demoted 3 threads. <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317403.182461] PM: done. <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317403.182463] Freezing user space processes ... <0.3> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185120] Freezing of tasks failed after 20.001 seconds (2 tasks refusing to freeze, wq_busy=0): <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185147] pool D 0 14428 5381 0x00000004 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185150] Call Trace: <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185159] ? __schedule+0x27f/0x830 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185161] schedule+0x28/0x80 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185168] request_wait_answer+0x79/0x1e0 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185172] ? wait_woken+0x80/0x80 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185176] __fuse_request_send+0x78/0x80 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185180] fuse_simple_request+0xbd/0x190 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185184] fuse_do_getattr+0xf3/0x2b0 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185190] fuse_update_attributes+0x7a/0x90 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185198] vfs_statx+0x79/0xb0 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185200] SYSC_newlstat+0x26/0x40 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185203] do_syscall_64+0x7b/0x160 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185204] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185206] RIP: 0033:0x7fc61ad0f535 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185207] RSP: 002b:00007fc60d1e8738 EFLAGS: 00000246 ORIG_RAX: 0000000000000006 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185209] RAX: ffffffffffffffda RBX: 00007fc60413d5c0 RCX: 00007fc61ad0f535 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185209] RDX: 00007fc60d1e87a0 RSI: 00007fc60d1e87a0 RDI: 00007fc604172fd0 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185210] RBP: 0000559c247e1590 R08: 00007fc6040aa860 R09: 00007fc61ad60470 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185211] R10: 0000000000100007 R11: 0000000000000246 R12: 00007fc604172fd0 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185212] R13: 00007fc60d1e8920 R14: 00007fc604172fd0 R15: 00007fc604017110 <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185253] mc D 0 3425 1 0x00000004 <======================= <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185255] Call Trace: <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185257] ? __schedule+0x27f/0x830 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185259] schedule+0x28/0x80 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185261] request_wait_answer+0x110/0x1e0 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185263] ? wait_woken+0x80/0x80 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185265] __fuse_request_send+0x78/0x80 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185268] fuse_simple_request+0xbd/0x190 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185271] fuse_do_getattr+0xf3/0x2b0 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185275] fuse_update_attributes+0x7a/0x90 [fuse] <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185276] vfs_statx+0x79/0xb0 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185278] SYSC_newlstat+0x26/0x40 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185279] do_syscall_64+0x7b/0x160 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185281] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185282] RIP: 0033:0x7f9d3c1b1535 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185282] RSP: 002b:00007fff021b3808 EFLAGS: 00000246 ORIG_RAX: 0000000000000006 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185284] RAX: ffffffffffffffda RBX: 00007fff021b4940 RCX: 00007f9d3c1b1535 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185285] RDX: 00007fff021b3840 RSI: 00007fff021b3840 RDI: 00007fff021b3940 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185286] RBP: 00007fff021b3910 R08: 0000000000000000 R09: 00007f9d3c202290 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185286] R10: 00007f9d3c1ffe30 R11: 0000000000000246 R12: 00007fff021b3940 <0.4> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185287] R13: 000056285945211a R14: 0000562859452124 R15: 00007fff021b3954 <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185291] OOM killer enabled. <0.6> 2020-03-20 03:08:12 Telcontar kernel - - - [317423.185292] Restarting tasks ... done. <3.5> 2020-03-20 03:08:12 Telcontar systemd 1 - - systemd-hibernate.service: Main process exited, code=exited, status=1/FAILURE <3.3> 2020-03-20 03:08:12 Telcontar systemd 1 - - Failed to start Hibernate. <3.4> 2020-03-20 03:08:12 Telcontar systemd 1 - - Dependency failed for Hibernate. <4.6> 2020-03-20 03:08:12 Telcontar systemd-logind 1557 - - Operation 'sleep' finished. <3.5> 2020-03-20 03:08:12 Telcontar systemd 1 - - hibernate.target: Job hibernate.target/start failed with result 'dependency'. <3.6> 2020-03-20 03:08:12 Telcontar systemd 1 - - sleep.target: Unit not needed anymore. Stopping. <3.5> 2020-03-20 03:08:12 Telcontar systemd 1 - - systemd-hibernate.service: Unit entered failed state. <3.4> 2020-03-20 03:08:12 Telcontar systemd 1 - - systemd-hibernate.service: Failed with result 'exit-code'. <3.6> 2020-03-20 03:08:12 Telcontar systemd 1 - - Stopped target Sleep.
The user run application 'mc' (Midnight Commander) was blocking hibernation (and now I see there was another application named 'pool').
I tried to kill 'mc' with killall -9. It still refused. I killed the terminal that had it, no way. In the end, I had to poweroff the machine instead.
I think that mc was blocked because it had open a remote directory externally:
sshfs cer@192.168.1.134:/ ~/fusermount/
and that other machine had been hibernated a minute before.
How can it be that a plebeian app stops the almighty kernel in its tracks?
Both threads are in kernel mode and as you yourself said cannot be interrupted. So there is little kernel can do. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org