Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ostree-finalize-staged.service times out on slow hardware #1824

Open
AdmiralNemo opened this issue Oct 30, 2024 · 8 comments
Open

ostree-finalize-staged.service times out on slow hardware #1824

AdmiralNemo opened this issue Oct 30, 2024 · 8 comments
Labels

Comments

@AdmiralNemo
Copy link

AdmiralNemo commented Oct 30, 2024

Describe the bug

On certain slow systems, such as Raspberry Pis, the ostree-finalize-staged.service unit fails often because it takes "too long" to do its work. This often results in reboot loops, where Zincati continuously tries to apply the update, but this fails, so the machine reboots back into the old version.

Oct 29 19:17:15 k8s-aarch64-n0.zzz.xyz systemd[1]: ostree-finalize-staged.service: Stopping timed out. Aborting.
Oct 29 19:17:15 k8s-aarch64-n0.zzz.xyz systemd[1]: ostree-finalize-staged.service: Killing process 17616 (ostree) with signal SIGABRT.
Oct 29 19:17:23 k8s-aarch64-n0.zzz.xyz systemd[1]: ostree-finalize-staged.service: Control process exited, code=dumped, status=6/ABRT
Oct 29 19:17:23 k8s-aarch64-n0.zzz.xyz systemd[1]: ostree-finalize-staged.service: Failed with result 'timeout'.

Reproduction steps

This is consistently reproducible for me on my "regular" Raspberry Pi 4b devices, with "generic" class 10 SD cards. I do not notice it on my CM4 devices that use eMMC.

Expected behavior

I would expect updates to succeed, regardless of how long they take.

Actual behavior

Especially when an upgrade requires "pruning" a previous version of FCOS, updates fail to apply and machines get stuck in a reboot loop. Manually running rpm-ostree cleanup -r usually resolves it.

Increasing the timeout with a unit drop-in configuration file also resolves the issue, e.g.

[Service]
TimeoutStopSec=15m

System details

metal: Raspberry Pi 4b

State: idle
AutomaticUpdatesDriver: Zincati
  DriverState: active; periodically polling for updates (last checked Wed 2024-10-30 23:36:17 UTC)
BootedDeployment:
● fedora:fedora/aarch64/coreos/stable
                  Version: 40.20241006.3.0 (2024-10-21T14:06:10Z)
               BaseCommit: be9fd1180854f8f6e58e673c43e3e8dc7c5ce2ceeaec736d31e7d8fb62469c96
             GPGSignature: Valid signature by 115DF9AEF857853EE8445D0A0727707EA15B79CC
          LayeredPackages: pam_ssh_agent_auth

Butane or Ignition config

No response

Additional information

The ostree-finalized-staged.service unit file has this snip:

# This is a quite long timeout intentionally; the failure mode
# here is that people don't get an upgrade.  We need to handle
# cases with slow rotational media, etc.
TimeoutStopSec=5m

I guess 5 minutes is probably not "quite long" enough?

@cgwalters
Copy link
Member

Do you have substantial data in /etc?

@AdmiralNemo
Copy link
Author

Do you have substantial data in /etc?

Not really?

[core@k8s-aarch64-n0 ~]$ sudo du -xhs /etc
41M	/etc

Most of that appears to come from /etc/selinux and /etc/udev. The only data I have added there is 27K in /etc/kubernetes

@dustymabe
Copy link
Member

Wow. yeah, 5m is pretty long.

Any chance you have more of the logs from one of those failed runs? I'm interested to see log messages with timestamps to see if we can tell how far it did make it before the timeout.

@AdmiralNemo
Copy link
Author

Sure:

Oct 29 19:12:15 k8s-aarch64-n0.zzz.xyz systemd[1]: Stopping ostree-finalize-staged.service - OSTree Finalize Staged Deployment...
Oct 29 19:12:16 k8s-aarch64-n0.zzz.xyz ostree[17616]: Finalizing staged deployment
Oct 29 19:12:27 k8s-aarch64-n0.zzz.xyz ostree[17616]: Copying /etc changes: 13 modified, 1 removed, 72 added
Oct 29 19:12:27 k8s-aarch64-n0.zzz.xyz ostree[17616]: Copying /etc changes: 13 modified, 1 removed, 72 added
Oct 29 19:12:27 k8s-aarch64-n0.zzz.xyz ostree[17616]: Refreshing SELinux policy
Oct 29 19:14:18 k8s-aarch64-n0.zzz.xyz ostree[17616]: Refreshed SELinux policy in 110123 ms
Oct 29 19:14:18 k8s-aarch64-n0.zzz.xyz ostree[17616]: Finalized deployment
Oct 29 19:15:09 k8s-aarch64-n0.zzz.xyz ostree[17616]: bootfs is sufficient for calculated new size: 149.8 MB
Oct 29 19:17:15 k8s-aarch64-n0.zzz.xyz systemd[1]: ostree-finalize-staged.service: Stopping timed out. Aborting.

Nearly 2 minutes to "refresh SELinux policy" but then I don't know what's happening after "bootfs is sufficient" for another 2 minutes.

@jlebon
Copy link
Member

jlebon commented Oct 31, 2024

Some of the things we've discussed which I think would help a lot here are:

  1. move SELinux policy rebuild to boot time (I think to do this sanely it'd need to be in the initramfs)
  2. pre-copy the kernel and initramfs (and devicetrees) before shutdown to reduce I/O during finalization

That said, 1 is relevant only when you have a custom SELinux policy. Is that the case here? You can check e.g. ostree admin config-diff | grep selinux.

@AdmiralNemo
Copy link
Author

That said, 1 is relevant only when you have a custom SELinux policy. Is that the case here? You can check e.g. ostree admin config-diff | grep selinux.

Yes, I have a custom module I have to load to get collectd to work.

@dustymabe
Copy link
Member

dustymabe commented Oct 31, 2024

  • move SELinux policy rebuild to boot time (I think to do this sanely it'd need to be in the initramfs)

Is there a reason that couldn't be done when the update is staged (pre-shutdown) versus next boot?

  • pre-copy the kernel and initramfs (and devicetrees) before shutdown to reduce I/O during finalization

hmm. would this have implications for opportunistic nature of ostreedev/ostree#2847

@jlebon
Copy link
Member

jlebon commented Oct 31, 2024

  • move SELinux policy rebuild to boot time (I think to do this sanely it'd need to be in the initramfs)

Is there a reason that couldn't be done when the update is staged (pre-shutdown) versus next boot?

The policy is defined in /etc so it gets back to the /etc-merge case. However, it would still be helpful to run semodule at staging time since it should be a no-op if nothing changed at finalization time (though I think even just checking if things changed is part of the cost).

  • pre-copy the kernel and initramfs (and devicetrees) before shutdown to reduce I/O during finalization

hmm. would this have implications for opportunistic nature of ostreedev/ostree#2847

The link is that we would only be able to do this pre-copy on systems with enough space in their bootfs because we don't want to pre-emptively delete a deployment at staging time.

That said, 1 is relevant only when you have a custom SELinux policy. Is that the case here? You can check e.g. ostree admin config-diff | grep selinux.

Yes, I have a custom module I have to load to get collectd to work.

Ahhh, gotcha. So yeah, this part is contributing to making finalization more expensive. Anyway, I think your current workaround is the best for now but we should definitely try to improve this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants