jlebon
commented
3 years ago Can you provide the full logs for ignition-ostree-uuid-boot.service?
Closed ArneCL closed 3 years ago
jlebon
commented
3 years ago Can you provide the full logs for ignition-ostree-uuid-boot.service?
jlebon
commented
3 years ago It's probably either e2fsck or tune2fs failing. set -x would've been useful here (which actually... we should just enable that in all our initrd scripts when rd.debug is enabled).
ArneCL
commented
3 years ago @jlebon I could do so, if it would not continue to reboot ... Is there any magic key-combination or ignition option to boot to shel/ssh even with error occuring?
lucab
commented
3 years ago @ArneCL you should get an emergency prompt in the initramfs, right after the failure. It can be activated by following the on-screen instructions (i.e. pressing Enter) within 5 minutes. If you don't see the prompt, you may first need to adjust the console settings according to your environment, see https://docs.fedoraproject.org/en-US/fedora-coreos/emergency-shell/.
ArneCL
commented
3 years ago @lucab I do get a serial console - However I do not get a prompt to press enter :( However, in the GRUB-Edit section, i can see that two terminals are configured . Do I understand correctly that the emergency-console might be displayed on the "wrong" terminal, if two terminals are configured?
bgilbert
commented
3 years ago @ArneCL Yes. You may need to remove one console from the kernel command line arguments.
lucab
commented
3 years ago @ArneCL yes, it may happen if you only have a virtual console and no serial. In that case, dropping the wrong entry from the command-line (or even both, if kernel autodetection can handle your hardware) should give you back the missing prompt.
ArneCL
commented
3 years ago @bgilbert @lucab Unfortunately, this is giving me a hard time:
As stated I do have access to the serial console - However, removing the second console in the GRUB-Edit does not seem to get me an emergency console, only a "virtual console" .
I can see that my changes to the GRUB-Edit take effect, i.e. i can also disable the console I'm accessing it with - Thus giving me a blank screen after hitting ctrl-x to boot....
Any Ideas? Can I provide you with more Input from my Side?
ArneCL
commented
3 years ago @bgilbert @lucab Good news - I was able to obtain some additional debug info by routing the systemd-output to console by setting the kernel parameters systemd.log_level=debug systemd.log_target=console systemd.journald.forward_to_console=1
ignition-ostree-uuid-root.service: Changed dead -> start
Starting Ignition OSTree: …rate filesystem UUID (root)...
systemd-journald.service: Got notification message from PID 207 (FDSTORE=1)
systemd-journald.service: Added fd 36 (n/a) to fd store.
[ 34.024586] ignition-ostree-firstboot-uuid[933]: No changes required for /dev/disk/by-label/root TYPE=xfs UUID=135bed75-bfb2-4a89-8fe6-1f7ea7b8789d
systemd-journald.service: Received EPOLLHUP on stored fd 36 (stored), closing.
Received SIGCHLD from PID 933 (ignition-ostree).
Child 933 (ignition-ostree) died (code=exited, status=0/SUCCESS)
ignition-ostree-uuid-root.service: Failed to read oom_kill field of memory.events cgroup attribute: No such file or directory
ignition-ostree-uuid-root.service: Child 933 belongs to ignition-ostree-uuid-root.service.
ignition-ostree-uuid-root.service: Main process exited, code=exited, status=0/SUCCESS
ignition-ostree-uuid-root.service: Changed start -> exited
ignition-ostree-uuid-root.service: Job 280 ignition-ostree-uuid-root.service/start finished, result=done
[ OK ] Finished Ignition OSTree: …nerate filesystem UUID (root).
ignition-ostree-uuid-root.service: Control group is empty.
ignition-ostree-mount-firstboot-sysroot.service: ConditionPathExists=!/run/ostree-live succeeded.
ignition-ostree-mount-firstboot-sysroot.service: ConditionKernelCommandLine=ostree succeeded.
ignition-ostree-mount-firstboot-sysroot.service: ConditionKernelCommandLine=!root succeeded.
Failed to read pids.max attribute of cgroup root, ignoring: No such file or directory
ignition-ostree-mount-firstboot-sysroot.service: Passing 0 fds to service
ignition-ostree-mount-firstboot-sysroot.service: About to execute: /usr/sbin/ignition-ostree-mount-sysroot
ignition-ostree-mount-firstboot-sysroot.service: Forked /usr/sbin/ignition-ostree-mount-sysroot as 936
ignition-ostree-mount-firstboot-sysroot.service: Executing: /usr/sbin/ignition-ostree-mount-sysroot
ignition-ostree-mount-firstboot-sysroot.service: Changed dead -> start
Starting Ignition OSTree: Mount (firstboot) /sysroot...
systemd-journald.service: Got notification message from PID 207 (FDSTORE=1)
systemd-journald.service: Added fd 36 (n/a) to fd store.
[ 34.142748] ignition-ostree-mount-sysroot[939]: mount: /sysroot: /dev/vda4 already mounted on /sysroot/sysroot.
systemd-journald.service: Received EPOLLHUP on stored fd 36 (stored), closing.
Received SIGCHLD from PID 936 (ignition-ostree).
Child 936 (ignition-ostree) died (code=exited, status=32/n/a)
ignition-ostree-mount-firstboot-sysroot.service: Failed to read oom_kill field of memory.events cgroup attribute: No such file or directory
ignition-ostree-mount-firstboot-sysroot.service: Child 936 belongs to ignition-ostree-mount-firstboot-sysroot.service.
ignition-ostree-mount-firstboot-sysroot.service: Main process exited, code=exited, status=32/n/a
ignition-ostree-mount-firstboot-sysroot.service: Failed with result 'exit-code'.
ignition-ostree-mount-firstboot-sysroot.service: Service will not restart (restart setting)
ignition-ostree-mount-firstboot-sysroot.service: Changed start -> failed
ignition-ostree-mount-firstboot-sysroot.service: Job 277 ignition-ostree-mount-firstboot-sysroot.service/start finished, result=failed
[FAILED] Failed to start Ignition O…e: Mount (firstboot) /sysroot.
See 'systemctl status ignition-ostree-m…firstboot-sysroot.service' for details.
ignition-ostree-growfs.service: Job 296 ignition-ostree-growfs.service/start finished, result=dependency
[DEPEND] Dependency failed for Igni… OSTree: Grow root filesystem.
ignition-ostree-growfs.service: Job ignition-ostree-growfs.service/start failed with result 'dependency'.
ignition-ostree-mount-firstboot-sysroot.service: Unit entered failed state.
ignition-ostree-mount-firstboot-sysroot.service: Control group is empty.
ignition-remount-sysroot.service: ConditionPathIsReadWrite=!/sysroot failed.
ignition-remount-sysroot.service: Starting requested but condition failed. Not starting unit.
ignition-remount-sysroot.service: Job 276 ignition-remount-sysroot.service/start finished, result=done
ignition-mount.service: ConditionPathExists=/etc/initrd-release succeeded.
Failed to read pids.max attribute of cgroup root, ignoring: No such file or directory
ignition-mount.service: Passing 0 fds to service
ignition-mount.service: About to execute: /usr/bin/ignition --root=/sysroot --platform=${PLATFORM_ID} --stage=mount --log-to-stdout
ignition-mount.service: Forked /usr/bin/ignition as 940
ignition-mount.service: Changed dead -> startignition-mount.service: Executing: /usr/bin/ignition --root=/sysroot --platform=metal --stage=mount --log-to-stdoutand also
Starting Ignition OSTree: …rate filesystem UUID (boot)...
ignition-setup-base.service: starting held back, waiting for: ignition-ostree-uuid-boot.service
ignition-setup-user.service: starting held back, waiting for: ignition-ostree-uuid-boot.service
systemd-journald.service: Got notification message from PID 207 (FDSTORE=1)
systemd-journald.service: Added fd 36 (n/a) to fd store.
[ 32.306273] ignition-ostree-firstboot-uuid[874]: e2fsck 1.45.5 (07-Jan-2020)
[ 32.317993] ignition-ostree-firstboot-uuid[874]: Pass 1: Checking inodes, blocks, and sizes
[ 32.332394] ignition-ostree-firstboot-uuid[874]: Pass 2: Checking directory structure
[ 32.337020] ignition-ostree-firstboot-uuid[874]: Pass 3: Checking directory connectivity
[ 32.341191] ignition-ostree-firstboot-uuid[874]: Pass 4: Checking reference counts
[ 32.349878] ignition-ostree-firstboot-uuid[874]: Pass 5: Checking group summary information
[ 32.360987] ignition-ostree-firstboot-uuid[874]: boot: 314/98304 files (0.0% non-contiguous), 111226/393216 blocks
[ 32.375961] ignition-ostree-firstboot-uuid[882]: tune2fs 1.45.5 (07-Jan-2020)
[ 32.378688] ignition-ostree-firstboot-uuid[882]: This operation requires a freshly checked filesystem.systemd-journald.service: Received EPOLLHUP on stored fd 36 (stored), closing.
[ 32.387856] Received SIGCHLD from PID 869 (ignition-ostree).
Child 869 (ignition-ostree) died (code=exited, status=1/FAILURE)
ignition-ostree-firstboot-uuid[882]: Please run e2fsck -f on the filesystem.ignition-ostree-uuid-boot.service: Failed to read oom_kill field of memory.events cgroup attribute: No such file or directory
ignition-ostree-uuid-boot.service: Child 869 belongs to ignition-ostree-uuid-boot.service.
ignition-ostree-uuid-boot.service: Main process exited, code=exited, status=1/FAILURE
openstacker
commented
3 years ago I'm getting the same issue withe FCOS 33.20210301.3.1, see the console log below.
jlebon
commented
3 years ago @openstacker This looks like a different but serious issue. In your case, it looks like no restamping occurred unlike the original post. I've split it out into a separate issue: https://github.com/coreos/fedora-coreos-tracker/issues/784.
ArneCL
commented
3 years ago @jlebon I tinkered around with Fedora 34.20210427.3.0 today.
The error still persists, but due to the improved logging it can be seen that tune2fs seems to be failing. By accident, I managed to stop the boot-loop and get an emergency shell (by providing the ignition file at the end of this post)
Running tune2fs -U random /dev/vda3 fails, with error run e2fsck ... EVEN when e2fsck is run (see screenshot below.) I found a related issue at kernel.org, where they suggest to run tune2fs -O metadata_csum_seed -U random as a workaround. Running tune2fs with that option indeed works (see screenshot). Please note that in #258 / Comment @bjencks mentions facing an error with tune2fs too (not sure if these errors are related)
Hopefully this provides enough information to fix this issue? If you need more details/logs/... feel free to ask!
Ignition File With this ignition, fcos will try to write the enable-passwords.conf file two times and failing the second time, as the file already exists. This stopps the boot-loop and enables to access to the emergency-shell.
variant: fcos
version: 1.3.0
storage:
files:
- path: /etc/ssh/sshd_config.d/20-enable-passwords.conf
mode: 0644
contents:
inline: |
# Fedora CoreOS disables SSH password login by default.
# Enable it.
# This file must sort before 40-disable-passwords.conf.
PasswordAuthentication yes
dustymabe
commented
3 years ago Hey @ArneCL - I'm able to reproduce this on some local hardware I own. Unfortunately I think tune2fs -O metadata_csum_seed -U random will make it so that grub won't be able to access that filesystem. At least that's what happens to me and IIUC right now GRUB doesn't support that feature flag.
What does work for me is to change the UUID after install but before reboot. Something like:
sudo coreos-installer install /dev/sdX --ignition fcos.ign
sudo e2fsck -yf /dev/sdX3
sudo tune2fs -U random /dev/sdX3The ignition-ostree-uuid-boot.service on the ignition boot will detect the UUID has been changed and gracefully exit and you'll be able to get past that issue.
We need to figure out how to make this problem go away, though. So that we don't need a workaround.
cgwalters
commented
3 years ago I don't understand why this would only happen in some circumstances, or just on some hardware.
dustymabe
commented
3 years ago I don't understand why this would only happen in some circumstances, or just on some hardware.
Race condition maybe?
In my case I'm using a local build of FCOS for aarch64 and trying to install to a Raspberry Pi4 targetting a external USB drive (2T).
bhale
commented
3 years ago I believe I am experiencing this same issue on a different hypervisor (KVM/libvirt) and I'm using RHCOS. The commonality is I am using TrueNAS SCALE and the underlying VirtIO/AHCI device being virtualized is backed by a ZFS ZVOL. This might have nothing to do with the loop, but I thought it was interesting that I share this with the OP.
I was attempting to run OCP 4.8 fc3 in my home lab to do some learning. However this boot loop was not resolved by the above instructions about tune2fs - even after e2fsck -yf, or, using tune2fs to mark the device as dirty and fscking again, tune2fs continued to refuse the -U random command, claiming the disk was not clean. Every other utility reported that the disk was clean.
Is there any other work around you could suggest to get past the uuid service not starting?
Are there any logs I could produce that would be helpful to the cause?
bhale
commented
3 years ago BTW I've been having this same bootloop behavior with FCOS on the first boot, and I assumed I was doing something wrong with my ignition config. Once I hit this in OCP I figured out how to access my serial console for the emergency shell and did some deeper digging, which lead me to this issue. I can readily reproduce this with either FCOS or RHCOS, whichever helps.
dustymabe
commented
3 years ago @bhale - are you using coreos-installer to install or are you picking up one of the other disk images?
cgwalters
commented
3 years ago From: Lukas Czerner lczerner@redhat.com 4:45 AM (5 hours ago)
I quickly went over the links below and it is pretty clear that the e2fsck is being run right before the tune2fs, so it should work just fine
e2fsck -fy "${target}" && tune2fs -U random "${target}"However the mounting itself is done with a coreos-assembler from the link below and I understand that those two pieces of code will be run on a completely different systems ?
One very trivial way to trigger the problem would be if there is a time inconsistency between the two system such that even though the e2fsck is being run after the mount in reality, the time set by e2fsck in s_lastcheck precedes the time set by ext4 driver in s_mtime.
Then we hit this condition in tune2fs:
/* Refuse to modify anything but a freshly checked valid filesystem. */ if (!(fs->super->s_state & EXT2_VALID_FS) || (fs->super->s_state & EXT2_ERROR_FS) || (fs->super->s_lastcheck < fs->super->s_mtime)) {It might explain why the problem is seen only sometimes on some machines. Is it a likely explanation of what you're seeing ?
Now, e2fsck does have a check to prevent this sort of time related problems and is able to fix it, however it has been bound to a condition of a non-zero check interval. Unfortunately since the default is to disable the periodic fsck, the value of checkinterval is zero and the time check is bypassed. Maybe we should change that, I'll think about it.
dustymabe
commented
3 years ago OK we've been given a patched grub that allows us to use the metadata_csum_seed feature of the ext4 filesystem which will:
Allow the filesystem to store the metadata checksum seed in the superblock, enabling the administrator to change the UUID of a filesystem using the metadata_csum feature while it is mounted.
TL;DR It's a workaround for this problem and should prevent the need for us to run any filesystem checking before we run tune2fs -U random.
@ArneCL @openstacker @bhale - can I get you to test and report if the following dev builds help?
bhale
commented
3 years ago @dustymabe That did the trick for me. Thank you for looking into this.
bhale
commented
3 years ago For other future adventurers, I noticed another way to mitigate the problem - thanks to the diagnosis above that the tune2fs is failing because of an inconsistent clock. In truenas (probably anything frontending qemu) there is a setting for the guest system clock. The default is local time, the 2nd option is UTC.
Changing this to UTC worked around the issue for me in FCOS and RHCOS.
cgwalters
commented
3 years ago Based on the above, I think another workaround is for us to add a small new service (probably in the initramfs) to set the system clock to at least the timestamp of the root filesystem's / ctime or so.
dustymabe
commented
3 years ago One very trivial way to trigger the problem would be if there is a time inconsistency between the two system such that even though the e2fsck is being run after the mount in reality, the time set by e2fsck in s_lastcheck precedes the time set by ext4 driver in s_mtime.
This is interesting because I was actually doing the build of FCOS on the same system as I'm doing the install on. The difference is that once the system is up and running chronyd will fix the time so the build of FCOS was built using the correct time, but early in the ignition boot when the boot uuid code runs chronyd hasn't run yet so the time is still set to whatever the incorrect hwclock time is:
May 25 11:20:13 rpi4 chronyd[1025]: Selected source 107.174.240.219 (2.fedora.pool.ntp.org)
May 25 11:20:13 rpi4 chronyd[1025]: System clock wrong by 1500938.381446 seconds
Jun 11 20:15:51 rpi4 systemd-resolved[986]: Clock change detected. Flushing caches.
Jun 11 20:15:51 rpi4 chronyd[1025]: System clock was stepped by 1500938.381446 seconds
Jun 11 20:15:51 rpi4 chronyd[1025]: System clock TAI offset set to 37 secondsand indeed my hwclock on this pi4 is out of sync:
[core@rpi4 ~]$ sudo hwclock --get
2021-05-28 06:50:06.545717+00:00Based on the above, I think another workaround is for us to add a small new service (probably in the initramfs) to set the system clock to at least the timestamp of the root filesystem's
/ctime or so.
That would probably work. I almost wonder if we should also make a CLHM helper or something to let people know when their hwclock is severely out of date.
bjencks
commented
3 years ago RPis don't have a real hardware clock, so such a helper would just be noisy on them and similar systems. I like the idea of setting the clock to something we know will work in early boot.
dustymabe
commented
3 years ago OK Now I've got an easy reproducer for the problem, just setting the time to something in the not too distant past right before running the fsck and tune2fs. cosa build && cosa run with that is at least an easy reproducer. Should make testing fixes easier.
$ git diff HEAD^ overlay.d/05core/usr/lib/dracut/modules.d/40ignition-ostree/ignition-ostree-firstboot-uuid
diff --git a/overlay.d/05core/usr/lib/dracut/modules.d/40ignition-ostree/ignition-ostree-firstboot-uuid b/overlay.d/05core/usr/lib/dracut/modules.d/40ignition-ostree/ignition-ostree-firstboot-uuid
index 0027bed..c9d734f 100755
--- a/overlay.d/05core/usr/lib/dracut/modules.d/40ignition-ostree/ignition-ostree-firstboot-uuid
+++ b/overlay.d/05core/usr/lib/dracut/modules.d/40ignition-ostree/ignition-ostree-firstboot-uuid
@@ -27,10 +27,9 @@ esac
if [ "${TYPE}" == "${orig_type}" ] && [ "${UUID}" == "${orig_uuid}" ]; then
case "${TYPE}" in
- # For now we need to fsck first, see https://github.com/coreos/coreos-assembler/pull/1452
- # Basically we're not passing `metadata_csum_seed` as a mkfs.ext4 option
- # because grub2 barfs on it.
- ext4) e2fsck -fy "${target}" && tune2fs -U random "${target}" ;;
+ ext4)
+ date --set="2021-04-14 20:12:00";
+ e2fsck -fy "${target}" && tune2fs -U random "${target}" ;;
xfs) xfs_admin -U generate "${target}" ;;
*) echo "unexpected filesystem type ${TYPE}" 1>&2; exit 1 ;;
esacThe fix for this went into testing stream release 34.20210626.2.0. Please try out the new release and report issues.
dustymabe
commented
3 years ago The fix for this went into stable stream release 34.20210626.3.1.
Describe the bug After installing FCOS on a BHyve VM, the VM gets stuck in a boot-loop. On the emergency-console, I can see the error messages pasted below:
Failed to start Ignition OSTree: Generate filesystem UUID (boot). The error occurs with VirtIO disks as well as with AHCI Disks (UEFI). Please note that FCOS 31.20200517.3.0-live.x86_64.iso installs and runs fine, however FCOS >=32.20201104.3.0-live.x86_64.iso fails with the described error.Reproduction steps Steps to reproduce the behavior:
curl -LOsudo coreos-installer install /dev/vda --ignition fcos.ignExpected behavior FCOS / VM booting to shell A clear and concise description of what actually happened.
Actual behavior FCOS rebooting due to error while creating Filesystem UUID
System details
Ignition config
Additional information Add any other information about the problem here.