Bugzilla – Bug 1226043
kernel: EXT4-fs error (device dm-0): ext4_mark_recovery_complete:6245: comm mount: Orphan file not empty on read-only fs.
Last modified: 2024-06-13 09:42:59 UTC
If an filesystem error occurs due to power outage, and it fixes the filesystem errors, it still get's stuck in rescue mode. `journcalctl -b` shows: May 16 10:01:31 edge.vendanor.com systemd[1]: Finished Cryptography Setup for rpi_rootfs. May 16 10:01:31 edge.vendanor.com systemd[1]: Found device /dev/disk/by-uuid/6d048af7-a4ba-4e50-8808-d686e13c286e. May 16 10:01:31 edge.vendanor.com systemd[1]: Reached target Local Encrypted Volumes. May 16 10:01:31 edge.vendanor.com systemd[1]: Reached target Initrd Root Device. May 16 10:01:31 edge.vendanor.com systemd[1]: Reached target System Initialization. May 16 10:01:31 edge.vendanor.com systemd[1]: Reached target Basic System. May 16 10:01:32 edge.vendanor.com systemd[1]: Finished dracut initqueue hook. May 16 10:01:32 edge.vendanor.com systemd[1]: Reached target Preparation for Remote File Systems. May 16 10:01:32 edge.vendanor.com systemd[1]: Reached target Remote Encrypted Volumes. May 16 10:01:32 edge.vendanor.com systemd[1]: Reached target Remote File Systems. May 16 10:01:32 edge.vendanor.com systemd[1]: dracut pre-mount hook was skipped because no trigger condition checks were met. May 16 10:01:32 edge.vendanor.com systemd[1]: Starting File System Check on /dev/disk/by-uuid/6d048af7-a4ba-4e50-8808-d686e13c286e... May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: e2fsck 1.47.0 (5-Feb-2023) May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: ROOT: recovering journal May 16 10:01:32 edge.vendanor.com systemd[1]: clevis-luks-askpass.service: Deactivated successfully. May 16 10:01:32 edge.vendanor.com systemd[1]: clevis-luks-askpass.service: Consumed 3.372s CPU time, 6.6M memory peak, 0B memory swap peak. May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: Clearing orphaned inode 18323 (uid=1001, gid=1001, mode=0100600, size=4194304) May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: Clearing orphaned inode 48587 (uid=1001, gid=1001, mode=040700, size=4096) May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: Truncating orphaned inode 130498 (uid=1000, gid=1000, mode=0100644, size=0) May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: Setting free blocks count to 263168 (was 263539) May 16 10:01:32 edge.vendanor.com systemd-fsck[799]: ROOT: clean, 65957/323840 files, 1043456/1306624 blocks May 16 10:01:32 edge.vendanor.com systemd[1]: Finished File System Check on /dev/disk/by-uuid/6d048af7-a4ba-4e50-8808-d686e13c286e. May 16 10:01:32 edge.vendanor.com systemd[1]: Mounting /sysroot... May 16 10:01:32 edge.vendanor.com kernel: EXT4-fs (dm-0): orphan cleanup on readonly fs May 16 10:01:32 edge.vendanor.com kernel: EXT4-fs error (device dm-0): ext4_orphan_get:1420: comm mount: bad orphan inode 18323 May 16 10:01:32 edge.vendanor.com kernel: ext4_test_bit(bit=2130, block=304) = 0 May 16 10:01:33 edge.vendanor.com kernel: EXT4-fs error (device dm-0): ext4_orphan_get:1420: comm mount: bad orphan inode 48587 May 16 10:01:33 edge.vendanor.com kernel: ext4_test_bit(bit=10, block=308) = 0 May 16 10:01:33 edge.vendanor.com kernel: EXT4-fs (dm-0): 1 truncate cleaned up May 16 10:01:33 edge.vendanor.com kernel: EXT4-fs (dm-0): recovery complete May 16 10:01:33 edge.vendanor.com kernel: EXT4-fs error (device dm-0): ext4_mark_recovery_complete:6245: comm mount: Orphan file not empty on read-only fs. May 16 10:01:33 edge.vendanor.com kernel: EXT4-fs (dm-0): mount failed May 16 10:01:33 edge.vendanor.com mount[822]: mount: /sysroot: mount system call failed: Structure needs cleaning. May 16 10:01:33 edge.vendanor.com mount[822]: dmesg(1) may have more information after failed mount system call. May 16 10:01:33 edge.vendanor.com systemd[1]: sysroot.mount: Mount process exited, code=exited, status=32/n/a May 16 10:01:33 edge.vendanor.com systemd[1]: sysroot.mount: Failed with result 'exit-code'. May 16 10:01:33 edge.vendanor.com systemd[1]: Failed to mount /sysroot. May 16 10:01:33 edge.vendanor.com systemd[1]: Dependency failed for Initrd Root File System. May 16 10:01:33 edge.vendanor.com systemd[1]: Dependency failed for Mountpoints Configured in the Real Root. May 16 10:01:33 edge.vendanor.com systemd[1]: initrd-parse-etc.service: Job initrd-parse-etc.service/start failed with result 'dependency'. May 16 10:01:33 edge.vendanor.com systemd[1]: initrd-parse-etc.service: Triggering OnFailure= dependencies. May 16 10:01:33 edge.vendanor.com systemd[1]: initrd-root-fs.target: Job initrd-root-fs.target/start failed with result 'dependency'. May 16 10:01:33 edge.vendanor.com systemd[1]: initrd-root-fs.target: Triggering OnFailure= dependencies. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped target Basic System. May 16 10:01:33 edge.vendanor.com systemd[1]: Reached target Initrd File Systems. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped target System Initialization. May 16 10:01:33 edge.vendanor.com systemd[1]: dracut-initqueue.service: Deactivated successfully. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped dracut initqueue hook. May 16 10:01:33 edge.vendanor.com systemd[1]: dracut-pre-udev.service: Deactivated successfully. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped dracut pre-udev hook. May 16 10:01:33 edge.vendanor.com systemd[1]: dracut-cmdline.service: Deactivated successfully. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped dracut cmdline hook. May 16 10:01:33 edge.vendanor.com systemd[1]: dracut-cmdline-ask.service: Deactivated successfully. May 16 10:01:33 edge.vendanor.com systemd[1]: Stopped dracut ask for additional cmdline parameters. May 16 10:01:33 edge.vendanor.com systemd[1]: Started Emergency Shell. May 16 10:01:33 edge.vendanor.com systemd[1]: Reached target Emergency Mode. May 16 10:01:33 edge.vendanor.com systemd[1]: Startup finished in 1.878s (kernel) + 0 (initrd) + 13.097s (userspace) = 14.976s. May 16 10:01:33 edge.vendanor.com systemd[1]: Received SIGRTMIN+21 from PID 414 (plymouthd). May 16 10:01:33 edge.vendanor.com systemd[1]: Received SIGRTMIN+21 from PID 414 (plymouthd). This is on Raspberry Pi CM4, filesystem is setup like this: /etc/fstab: /dev/mapper/rpi_rootfs / ext4 defaults,noatime 0 1 /dev/mmcblk0p2 /boot ext4 defaults,noatime 0 0 /dev/mmcblk0p1 /boot/efi vfat utf8 0 2 /etc/crypttab: rpi_rootfs UUID=4fb99d03-eec8-4a6c-8d46-e14a6afd975a none x-initrd.attach GRUB_CMDLINE_LINUX_DEFAULT from /etc/default/grub: GRUB_CMDLINE_LINUX_DEFAULT="systemd.show_status=0 vt.global_cursor_default=0 plymouth.ignore-serial-consoles video=HDMI-A-1:1920x1080M@60,rotate=90 fsck.repair=yes cgroup_enable=memory swapaccount=1 net.ifnames=0 rd.neednet=1 ip=192.168.250.20::192.168.250.200:255.255.255.0::eth0:off quiet splash"
This seems to point at an issue with e2fsck, which reports a successful check: > ROOT: clean, 65957/323840 files, 1043456/1306624 blocks but it then fails mounting. I guess you may have tried this already but it's worth asking: have you tried to manually rerun e2fsck against that file system? Did it still a similar output (e.g. that it cleaned inode 18323, 48587, etc...)? (There's a newer upstream release of the e2fsprogs that seem to have a few fixes that seem related to orphan list processing, but unfortunately it's not on TW yet.)
I have run fsck in rescue when the system didn't automatically boot, no issues found, so I just rebooted the system from dracut-ssh with reboot -f and it boots, I've also added fsck.mode=force so fsck is run on each boot, and no filesystem issues are found. But the issue have occurred several times on 2 different RPI's, it doesn't boot even if filesystem errors are corrected.
Awesome, thanks for confirming. So, here's my theory: e2fsck _claims_ to have fixed the issue. Then, when filesystem is being mounted, it detects inconsistencies (because e2fsck didn't fix them). And, because the filesystem is being mounted read-only, the kernel can not fix it either and simply aborts the operation. It looks like, by re-running e2fsck, the filesystem is finally fixed, so it might be something "simple", but I'll need to dig deeper and try to reproduce it. Thank you for reporting, I'll see what I can find and report back here.
Here's my understanding of what happens: there was an application (or applications) that had files open and those files were deleted while still open. Which means that these files were added to the 'orphan files' list. And the power outage happen while this list still had files in it. After a reboot, the e2fsck tries to clear this list but doesn't clean the inode that manages the list itself. When the kernel tries to mount it, it correctly detects the filesystem still requires recovery and, because it is being mounted read-only, it can not do the recovery itself and fails. Later, when you manually run e2fsck it will finally do the full recovery and the filesystem can then be mounted. All this to say that this seems to be a bug in e2fsck for which I've sent out a fix upstream[1]. Hopefully it won't take long for a fix to be merged. Again, thank you for your report. [1] https://lore.kernel.org/all/20240611142704.14307-1-luis.henriques@linux.dev/
Thank you. After I added "fsck.mode=force" I could no longer reproduce the issue when cutting power, as soon as I removed "fsck.mode=force" it's stuck almost every time the power is cut. Even if you fixed the issue, is it a good idea to keep fsck.mode=force for machines that are often shut down by cutting power? I assume it does not hurt, since it only takes a few seconds more when booting. This is what I'm seeing now when running fsck manually: initramfs-ssh:/root# fsck -f -y /dev/mmcblk0p1 fsck from util-linux 2.40.1 Cannot initialize conversion from codepage 850 to ANSI_X3.4-1968: Invalid argument Cannot initialize conversion from ANSI_X3.4-1968 to codepage 850: Invalid argument Using internal CP850 conversion table fsck.fat 4.2 (2021-01-31) Dirty bit is set. Fs was not properly unmounted and some data may be corrupt. Automatically removing dirty bit. *** Filesystem was changed *** Writing changes. /dev/mmcblk0p1: 360 files, 3261/40915 clusters initramfs-ssh:/root# fsck -f -y /dev/mmcblk0p2 fsck from util-linux 2.40.1 e2fsck 1.47.0 (5-Feb-2023) /dev/mmcblk0p2: recovering journal Pass 1: Checking inodes, blocks, and sizes Pass 2: Checking directory structure Pass 3: Checking directory connectivity Pass 4: Checking reference counts Pass 5: Checking group summary information Feature orphan_present is set but orphan file is clean. Clear? yes /dev/mmcblk0p2: ***** FILE SYSTEM WAS MODIFIED ***** /dev/mmcblk0p2: 666/131072 files (0.5% non-contiguous), 53121/524288 blocks initramfs-ssh:/root# fsck -f -y /dev/mapper/rpi_rootfs fsck from util-linux 2.40.1 e2fsck 1.47.0 (5-Feb-2023) Pass 1: Checking inodes, blocks, and sizes Pass 2: Checking directory structure Pass 3: Checking directory connectivity Pass 4: Checking reference counts Pass 5: Checking group summary information Orphan file (inode 12) block 13 is not clean. Clear? yes ROOT: ***** FILE SYSTEM WAS MODIFIED ***** ROOT: 344398/1748736 files (0.2% non-contiguous), 4462948/7064315 blocks initramfs-ssh:/root# reboot Failed to set wall message, ignoring: The name org.freedesktop.login1 was not provided by any .service files Call to Reboot failed: The name org.freedesktop.login1 was not provided by any .service files
(In reply to Jonas Kvinge from comment #5) > Thank you. After I added "fsck.mode=force" I could no longer reproduce the > issue when cutting power, as soon as I removed "fsck.mode=force" it's stuck > almost every time the power is cut. > > Even if you fixed the issue, is it a good idea to keep fsck.mode=force for > machines that are often shut down by cutting power? I assume it does not > hurt, since it only takes a few seconds more when booting. I guess that what 'fsck.mode=force' will do is to run e2fsck with '-f' even if the filesystem seems to be clean (but I'm not familiar with the details on how this parameter is handled, probably by systemd). In general, forcing the filesystem check shouldn't be needed in most cases, but it should also be harmless. On the other hand, my patch to e2fsck is to actually force it to do a full check in the presence of the orphan files inode. So using that kernel parameter seems to be a good workaround to the issue. (In the meantime, I haven't had any feedback on my patch yet.)