Comment # 6
on bug 1183990
from Carlos Robinson
Yes, I did reproduce the problem. With a change: id did not try to powerdown
when hibernate "failed", and it did succeed after about half an hour.
I issued the hibernation request at about 10 minutes to midnight, just a few
minutes after the texpire job starts to run and activity in /var/spool/news
ramps up and continues for half an hour.
I will attach the /var/kog/message file out of syslog (by the way, the kernel
boot messages are missing, this started happening with 15.2)
I have an allmessages file if you want it too, but it is way verbose and
perhaps sensitive (may contain nntp and mail entries). Ask for it if you need
it.
I have also saved "journalctl -b > journalparabugzilla", ask for it if you need
it.
Time points, two attempts - watch for line wraps in report:
2021-03-27 18:13:08+01:00 - Booting the system now
================================================================================
Linux Telcontar 5.11.10-2.gfa5dcf1-default #1 SMP Fri Mar 26 08:43:28 UTC 2021
(fa5dcf1) x86_64 x86_64 x86_64 GNU/Linux
boots up
normal afternoon.
cron job start
<9.4> 2021-03-27T23:45:01.556746+01:00 Telcontar texpire - - - CER: running
leafnode's texpire without ionice
I request hibernate ("systemctl hibernate" as root):
<3.6> 2021-03-27T23:52:08.166881+01:00 Telcontar systemd 1 - - Reached target
Sleep.
<3.6> 2021-03-27T23:52:08.167292+01:00 Telcontar systemd 1 - - Starting
Hibernate...
<3.4> 2021-03-27T23:52:08.226198+01:00 Telcontar systemd-sh - - - Hibernating
the system now...
and hibernation happens uneventfully.
<3.6> 2021-03-27T23:52:10.144155+01:00 Telcontar systemd-sleep 31043 - - INFO:
Done.
<3.6> 2021-03-27T23:52:13.262746+01:00 Telcontar systemd-sleep 31043 - -
Suspending system...
<0.6> 2021-03-27T23:52:13.266649+01:00 Telcontar kernel - - - [20367.676939]
PM: hibernation: hibernation entry
<0.6> 2021-03-28T00:20:10.274394+01:00 Telcontar kernel - - - [20368.195058]
Filesystems sync: 0.517 seconds
<0.6> 2021-03-28T00:20:10.274493+01:00 Telcontar kernel - - - [20368.195061]
Freezing user space processes ... (elapsed 0.001 seconds) done.
<0.6> 2021-03-28T00:20:10.274494+01:00 Telcontar kernel - - - [20368.196906]
OOM killer disabled.
I think that it was a success. But sometime later I wake up the machine and
try again, this time when I see continuous write activity on sdc9 aka
/var/spool/news.
Thawing the system:
<0.6> 2021-03-28T00:20:10.281155+01:00 Telcontar kernel - - - [20374.643302]
PM: hibernation: hibernation exit
<0.5> 2021-03-28T00:20:10.281156+01:00 Telcontar kernel - - - [20374.643572] sd
10:0:0:0: [sde] Synchronizing SCSI cache
<3.6> 2021-03-28T00:20:10.284616+01:00 Telcontar systemd-sleep 31043 - -
System resumed.
<3.6> 2021-03-28T00:20:10.284827+01:00 Telcontar pulseaudio 6878 - - W:
[alsa-sink-ALC892 Analog] alsa-util.c: Could not recover alsa device from
SUSPENDED state, trying to restart PCM
<3.6> 2021-03-28T00:20:10.303628+01:00 Telcontar systemd 1 - - Starting Do
daily mandb update...
<3.6> 2021-03-28T00:20:10.304331+01:00 Telcontar systemd 1 - - Starting Rotate
log files...
<3.6> 2021-03-28T00:20:10.305693+01:00 Telcontar systemd 1 - - Starting Update
locate database...
<3.6> 2021-03-28T00:20:10.389183+01:00 Telcontar systemd-sleep 31043 - - INFO:
Running grub-once-restore ..
<3.4> 2021-03-28T00:20:10.418684+01:00 Telcontar systemd-sh - - - Thawing the
system now...
I issue systemctl hibernate. The system is busy with cronjobs, and I see
continuous write activity on sdc9. The worst moment to hibernate.
<3.6> 2021-03-28T00:20:10.459479+01:00 Telcontar systemd 1 - - Started
Hibernate.
<3.6> 2021-03-28T00:20:10.459582+01:00 Telcontar systemd 1 - - sleep.target:
Unit not needed anymore. Stopping.
<3.6> 2021-03-28T00:20:10.459658+01:00 Telcontar systemd 1 - - Stopped target
Sleep.
<3.6> 2021-03-28T00:20:10.459727+01:00 Telcontar systemd 1 - - Reached target
Hibernate.
<4.6> 2021-03-28T00:20:10.459800+01:00 Telcontar systemd-logind 1731 - -
Operation 'sleep' finished.
<3.6> 2021-03-28T00:20:10.460173+01:00 Telcontar systemd 1 - -
hibernate.target: Unit not needed anymore. Stopping.
<3.6> 2021-03-28T00:20:10.460269+01:00 Telcontar systemd 1 - - Stopped target
Hibernate.
<0.6> 2021-03-28T00:20:10.525146+01:00 Telcontar kernel - - - [20374.886301] sd
10:0:0:0: [sde] Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR
driverbyte=DRIVER_OK
<3.6> 2021-03-28T00:20:10.909232+01:00 Telcontar do_mandb 32042 - - find:
���������standard output���������: Broken pipe
<3.6> 2021-03-28T00:20:10.909441+01:00 Telcontar do_mandb 32042 - - find:
write error
Notice that in the middle of a failed request to hibernate, the system is
still starting cron jobs adding more delay
<3.6> 2021-03-28T00:20:14.076079+01:00 Telcontar systemd 1 - - Reloading
System Logging Service.
<3.6> 2021-03-28T00:20:14.076923+01:00 Telcontar systemd 1 - - Reloaded System
Logging Service.
<3.6> 2021-03-28T00:20:16.575734+01:00 Telcontar systemd 1 - - Started Rotate
log files.
<3.6> 2021-03-28T00:23:04.377712+01:00 Telcontar systemd 1 - - Reached target
Sleep.
<3.6> 2021-03-28T00:23:04.378315+01:00 Telcontar systemd 1 - - Starting
Hibernate...
<3.6> 2021-03-28T00:23:04.409724+01:00 Telcontar systemd-sleep 24504 - - INFO:
Running prepare-grub ..
<3.4> 2021-03-28T00:23:04.436985+01:00 Telcontar systemd-sh - - - Hibernating
the system now...
<3.6> 2021-03-28T00:23:04.674795+01:00 Telcontar systemd-sleep 24504 - -
preparing boot-loader: selecting entry main-os, kernel
/boot/5.11.10-2.gfa5dcf1-default
<3.6> 2021-03-28T00:23:44.081034+01:00 Telcontar systemd 1 - - Starting Backup
RPM database...
<3.6> 2021-03-28T00:24:07.216108+01:00 Telcontar systemd 1 - - Started Backup
RPM database.
<3.4> 2021-03-28T00:24:34.406964+01:00 Telcontar systemd-sleep 24504 - -
system-sleep terminated by signal ALRM.
<3.3> 2021-03-28T00:24:34.407204+01:00 Telcontar systemd-sleep 24504 - -
Execution failed: Protocol error
<3.6> 2021-03-28T00:24:34.407299+01:00 Telcontar systemd-sleep 24504 - -
Suspending system...
<0.6> 2021-03-28T00:24:34.409141+01:00 Telcontar kernel - - - [20638.773346]
PM: hibernation: hibernation entry
<3.6> 2021-03-28T00:35:12.724847+01:00 Telcontar systemd 1 - - Started Update
locate database.
<5.6> 2021-03-28T00:41:06.345537+01:00 Telcontar rsyslogd - - - -- MARK --
<9.4> 2021-03-28T00:45:26.408094+01:00 Telcontar texpire - - - CER: finished
This is when /dev/sdc9 activity would stop, but I was not looking, I had
gone from the room tired of waiting.
<1.6> 2021-03-28T00:45:26.435402+01:00 Telcontar run-crons 30712 - - leafnode:
OK
<9.6> 2021-03-28T00:45:26.473139+01:00 Telcontar run-crons.daily - - -
Considering my daily cron jobs.
<9.6> 2021-03-28T00:45:26.502372+01:00 Telcontar run-crons.daily - - -
Disabling google-chrome cron job (removing its execute permission).
<1.4> 2021-03-28T00:45:26.530153+01:00 Telcontar run-crons 30712 - - mio.daily
returned 1
<1.6> 2021-03-28T00:45:26.563622+01:00 Telcontar run-crons 30712 - -
storebackup: OK
<1.6> 2021-03-28T00:45:26.849819+01:00 Telcontar run-crons 30712 - -
suse-texlive: OK
Time discontinuity here, which means that now is when machine actually
hibernates, about half an hour after I issued the order. Imagine I was in an
emergency, like on UPS battery. Normally I panic much earlier and try to
powerdown, which fails, then I hit the power switch and pray for a good
recovery later.
<0.6> 2021-03-28T00:58:54.286380+01:00 Telcontar kernel - - - [21931.825420]
Filesystems sync: 1293.045 seconds
<0.6> 2021-03-28T00:58:54.286458+01:00 Telcontar kernel - - - [21931.825426]
Freezing user space processes ... (elapsed 0.001 seconds) done.
<0.6> 2021-03-28T00:58:54.286460+01:00 Telcontar kernel - - - [21931.827418]
OOM killer disabled.
<0.7> 2021-03-28T00:58:54.286460+01:00 Telcontar kernel - - - [21931.827620]
PM: hibernation: Marking nosave pages: [mem 0x00000000-0x00000fff]
<3.4> 2021-03-28T00:58:54.337671+01:00 Telcontar systemd-sh - - - Thawing the
system now...
<3.6> 2021-03-28T00:58:54.375645+01:00 Telcontar systemd 1 - - Started
Hibernate.
<3.6> 2021-03-28T00:58:54.375759+01:00 Telcontar systemd 1 - - sleep.target:
Unit not needed anymore. Stopping.
<3.6> 2021-03-28T00:58:54.375855+01:00 Telcontar systemd 1 - - Stopped target
Sleep.
<3.6> 2021-03-28T00:58:54.375937+01:00 Telcontar systemd 1 - - Reached target
Hibernate.
<3.6> 2021-03-28T00:58:54.376069+01:00 Telcontar systemd 1 - -
hibernate.target: Unit not needed anymore. Stopping.
<3.6> 2021-03-28T00:58:54.376156+01:00 Telcontar systemd 1 - - Stopped target
Hibernate.
<4.6> 2021-03-28T00:58:54.376213+01:00 Telcontar systemd-logind 1731 - -
Operation 'sleep' finished.
I will now hibernate the machine and go to sleep myself. If you want me to
run some command on the same session, tell me; on Monday I'll reboot to the
Leap standard kernel.