XFS journal corruption after every reboot/shutdown

XFS journal corruption after every reboot/shutdown

[Heinz Diehl]

Hi,

the root partition on three different Fedora 27 based machines is
XFS-formatted. After every reboot or shutdown, dmesgs shows the following lines after
restarting:

[htd@kiera ~]$ dmesg | grep XFS
[    2.773271] SGI XFS with ACLs, security attributes, no debug enabled
[    2.774950] XFS (sda2): Mounting V4 Filesystem
[    2.851266] XFS (sda2): Starting recovery (logdev: internal)
[    2.876522] XFS (sda2): Ending recovery (logdev: internal)

/dev/sda2 is the root partition. /home, which also is XFS formatted, is
fine. The journal gets automatically recovered in the boot process and
root mounts just fine. But this happens after every single reboot or
shutdown - on three different machines with two different kernels
(4.14.4 and 4.14.12) and three different harddisks. And it's always
and solely the root partition which is affected.

To me, it looks like the root partition doesn't get properly unmounted
on reboot or shutdown, but I can not find anything in the logs that is
suspicious. I have also looked into systemd sourcecode and the systemd shutdown
process, but can not see that the root partition is actually unmounted.

Do you have any advice what to do further, or any hint on what could be
happening here? Is this behaviour intended?

I have also filed a bug report here because there's F27 on all machines:
https://bugzilla.redhat.com/show_bug.cgi?id=1533620

Many thanks in advance,
 Heinz 

Re: XFS journal corruption after every reboot/shutdown

[Dave Chinner]

On Thu, Jan 11, 2018 at 11:44:51PM +0100, Heinz Diehl wrote:
> Hi,
> 
> the root partition on three different Fedora 27 based machines is
> XFS-formatted. After every reboot or shutdown, dmesgs shows the following lines after
> restarting:
> 
> [htd@kiera ~]$ dmesg | grep XFS
> [    2.773271] SGI XFS with ACLs, security attributes, no debug enabled
> [    2.774950] XFS (sda2): Mounting V4 Filesystem
> [    2.851266] XFS (sda2): Starting recovery (logdev: internal)
> [    2.876522] XFS (sda2): Ending recovery (logdev: internal)

That's not corruption - that's normal log recovery running at mount
time.

> /dev/sda2 is the root partition. /home, which also is XFS formatted, is
> fine. The journal gets automatically recovered in the boot process and
> root mounts just fine. But this happens after every single reboot or
> shutdown - on three different machines with two different kernels
> (4.14.4 and 4.14.12) and three different harddisks. And it's always
> and solely the root partition which is affected.
> 
> To me, it looks like the root partition doesn't get properly unmounted
> on reboot or shutdown, but I can not find anything in the logs that is
> suspicious. I have also looked into systemd sourcecode and the systemd shutdown
> process, but can not see that the root partition is actually unmounted.

That's because it's not. systemd itself still has open references to
the root filesysetm, so when it tries to unmount the root fs, it
fails with -EBUSY. So it then remounts the root filesystem read
only. It does this with ext3/4 filesystems as well - put a serial
console on your machine and just before the machine reboots/powers
off you'll see something like this:

[1883430.750756] systemd-shutdown[1]: Unmounting file systems.
[1883430.752130] systemd-shutdown[17403]: Remounting '/' read-only in with options 'seclabel,errors=remount-ro,data=ordered'.
[1883430.856501] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,data=ordered
[1883430.908480] systemd-shutdown[1]: All filesystems unmounted.

On XFS, this leaves the journal dirty so that when the filesystem
is mounted on boot it can clean up things like orphan inodes that
were present at the time of the remount,ro (e.g. open but unlinked
files).

IOWs, what you are seeing is normal filesystem behaviour that is a
result of systemd being unable to unmount the root filesystem
cleanly because it still has references open to the root filesystem.

> I have also filed a bug report here because there's F27 on all machines:
> https://bugzilla.redhat.com/show_bug.cgi?id=1533620

Not a bug, please close it.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS journal corruption after every reboot/shutdown

[Eric Sandeen]

On 1/11/18 5:13 PM, Dave Chinner wrote:
>> I have also filed a bug report here because there's F27 on all machines:
>> https://bugzilla.redhat.com/show_bug.cgi?id=1533620
> Not a bug, please close it.

Or, it's a systemd bug.  I switched components, they can decide whether
it's their bug.  :)

-Eric

Re: XFS journal corruption after every reboot/shutdown

[Heinz Diehl]

On 12.01.2018, Dave Chinner wrote: 

> On XFS, this leaves the journal dirty so that when the filesystem
> is mounted on boot it can clean up things like orphan inodes that
> were present at the time of the remount,ro (e.g. open but unlinked
> files).

> IOWs, what you are seeing is normal filesystem behaviour that is a
> result of systemd being unable to unmount the root filesystem
> cleanly because it still has references open to the root filesystem.

Ok, I see. Thanks for clarifying!

> > I have also filed a bug report here because there's F27 on all machines:
> > https://bugzilla.redhat.com/show_bug.cgi?id=1533620
 
> Not a bug, please close it.

I remember a time not too long ago where the root fs was clean after a
reboot/shutdown (maybe around F25?). So something must have changed
in the way systemd performs a reboot/shutdown..

Thanks,
 Heinz
 

Re: XFS journal corruption after every reboot/shutdown

[Chris Murphy]

On Sat, Jan 13, 2018 at 1:17 AM, Heinz Diehl <htd+ml@fritha.org> wrote:

> I remember a time not too long ago where the root fs was clean after a
> reboot/shutdown (maybe around F25?). So something must have changed
> in the way systemd performs a reboot/shutdown..

I forget when, but plymouth started exempting itself from being force
quit by systemd on shutdown. In my case it was preventing remount ro.
I'm not even certain systemd tries to do umount on rootfs if an
initramfs is being used, I'm pretty sure it only does remount ro. And
in the successful remount ro case, I never see the log replay on XFS
at next boot.

You could try to mask the use of plymouth in systemd (or uninstall
it). If the problem goes away, that's the culprit. If it doesn't you
can probably track down what's holding up the remount ro with
https://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1
And following the "eventually shuts down" section.


-- 
Chris Murphy

Re: XFS journal corruption after every reboot/shutdown

[Heinz Diehl]

On 13.01.2018, Chris Murphy wrote: 

> You could try to mask the use of plymouth in systemd (or uninstall
> it). If the problem goes away, that's the culprit.

I removed plymouth a long time ago, because to me it's useless.

> If it doesn't you can probably track down what's holding up the remount ro with
> https://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1
> And following the "eventually shuts down" section.

And that solved the problem! Not the debugging itself, but the debug script
that is mentioned in the text you directed me to. After placing the
debug script in /usr/lib/systemd/systemd-shutdown, the root fs is
clean after reboot/shutdown:

[htd@chiara ~]$ dmesg | grep XFS
[    2.085668] SGI XFS with ACLs, security attributes, no debug enabled
[    2.086856] XFS (nvme0n1p3): Mounting V5 Filesystem
[    2.093919] XFS (nvme0n1p3): Ending clean mount

Here's the debug script:

#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /

It simply remounts the root fs rw, dumps the output of dmesg to disk,
and remounts the root fs ro afterwards. I tried to find out exactly
where and when in the shutdown process this script is executed, but
have to admit that my understanding of systemd is not deep enough.

I think something in how systemd performs a reboot/shutdown is
wrong. Will add this information to my bug report and hope this rings
a bell for the systemd developers. 

Thanks a lot,
Heinz