7

Can we confirm the log message "recovering journal" from fsck should be interpreted as indicating the filesystem was not cleanly unmounted / shut down the last time? Or, are there other possible reasons to be aware of?

May 03 11:52:34 alan-laptop systemd-fsck[461]: /dev/mapper/alan_dell_2016-fedora: recovering journal
May 03 11:52:42 alan-laptop systemd-fsck[461]: /dev/mapper/alan_dell_2016-fedora: clean, 365666/2621440 files, 7297878/10485760 blocks

May 03 11:52:42 alan-laptop systemd[1]: Mounting /sysroot...
May 03 11:52:42 alan-laptop kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
May 03 11:52:42 alan-laptop systemd[1]: Mounted /sysroot.

Compare fsck of /home from the same boot, which shows no such message:

(ignore the -1 hour jump, it's due to "RTC time in the local time zone")

May 03 10:52:57 alan-laptop systemd[1]: Starting File System Check on /dev/mapper/alan_dell_2016-home...
May 03 10:52:57 alan-laptop systemd-fsck[743]: /dev/mapper/alan_dell_2016-home: clean, 1469608/19857408 files, 70150487/79429632 blocks
May 03 10:52:57 alan-laptop systemd[1]: Started File System Check on /dev/mapper/alan_dell_2016-home.
May 03 10:52:57 alan-laptop audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-fsc>
May 03 10:52:57 alan-laptop systemd[1]: Mounting /home...
May 03 10:52:57 alan-laptop systemd[1]: Mounted /boot/efi.
May 03 10:52:57 alan-laptop kernel: EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
May 03 10:52:57 alan-laptop systemd[1]: Mounted /home.
May 03 10:52:57 alan-laptop systemd[1]: Reached target Local File Systems.

Version

$ rpm -q --whatprovides $(which fsck.ext4)
e2fsprogs-1.43.8-2.fc28.x86_64

Motivation

This happened immediately after an offline update; it was most likely triggered by a PackageKit bug:

Bug 1564462 - offline update performed unclean shutdown

where it effectively uses systemctl reboot --force. I'm concerned that there's a bug in Fedora here, because systemd forced shutdown is still supposed to kill all processes and then unmount the filesystems cleanly where possible.

The above messages are from Fedora 28, systemd-238-7.fc28.1.x86_64. Fedora 27 was using a buggy version of systemd which could have failed to unmount filesystems:

systemd-shutdown[1]: Failed to parse /proc/self/mountinfo #6796

however the fix should be included in systemd 235 and above. So I'm concerned there's yet another bug lurking somewhere.

The filesystem is on LVM.

I seem to remember that shutdown is associated with a few screenfuls of repeated messages in a few seconds immediately before the screen goes black. I think they are from inside the shutdown initrd. I don't know if this represents a problem or not.

Jeff Schaller
  • 66,199
  • 35
  • 114
  • 250
sourcejedi
  • 48,311
  • 17
  • 143
  • 296

2 Answers2

12

The “recovering journal” message is output by e2fsck_run_ext3_journal, which is only called if ext2fs_has_feature_journal_needs_recovery indicates that the journal needs recovery. This “feature” is a flag which is set by the kernel whenever a journalled Ext3/4 file system is mounted, and cleared when the file system is unmounted, when recovery is completed (when mounting an unclean file system, or remounting a file system read-only), and when freezing the file system (before taking a snapshot).

Ignoring snapshots, this means that e2fsck only prints the message when it encounters a file system which hasn’t been cleanly unmounted, so its presence is proof of an unclean unmount (and perhaps shutdown, assuming the unmount was supposed to take place during shutdown).

Stephen Kitt
  • 411,918
  • 54
  • 1,065
  • 1,164
1

The journal contains commands to the filessytem that haven't been yet ben commited. On a clean unmount, whatever is in there is commited, and the journal cleared. So yes, replaying a journal means an unclean shutdown. But not viceversa, the unclean shutdown could have happened when there was nothing in the journal.

vonbrand
  • 18,156
  • 2
  • 37
  • 59