ostree-finalize-staged.service takes much longer on reboot than 'ostree admin finalize-staged'

[trgeiger]

For at least several weeks, probably months, anytime I have an update on my laptop, my system hangs on ostree-finalize-staged.service for about 5 or 6 minutes before it will reboot, even for incredibly small changes like editing a kernel parameter with 'rpm-ostree kargs --editor.'

If I perform an update and manually run 'ostree admin finalize-staged' it takes maybe 5 or 10 seconds and then the reboot is very fast. I don't see any obvious errors in my journal and haven't been able to figure out what exactly would be taking so long on reboot that wouldn't be an issue when run manually.

[cgwalters]

Can you paste a bit of the output from the journal? The two big possible culprits are grub2-mkconfig and selinux policy recompilation.

[trgeiger]

Of course. I just had an update that took about 3 minutes to reboot after updating. I took logs from that here (in reversed chronology):

Nov 30 13:32:34 fedora ostree[125912]: Finished writing deployment
Nov 30 13:32:34 fedora ostree[125912]: Bootloader updated; bootconfig swap: yes; bootversion: boot.0.1, deployment count change: 0
Nov 30 13:32:34 fedora ostree[125912]: Completed freeze/thaw cycle for system root in 38 ms
Nov 30 13:32:34 fedora ostree[125912]: Starting freeze/thaw cycle for system root
Nov 30 13:32:34 fedora ostree[125912]: Completed syncfs() for system root in 15 ms
Nov 30 13:32:34 fedora ostree[125912]: Starting syncfs() for system root
Nov 30 13:30:42 fedora ostree[125912]: bootfs is sufficient for calculated new size: 225.9 MB
Nov 30 13:30:42 fedora ostree[125912]: Finalized deployment
Nov 30 13:30:42 fedora ostree[125912]: Refreshed SELinux policy in 34229 ms
Nov 30 13:30:07 fedora ostree[125912]: Refreshing SELinux policy
Nov 30 13:30:06 fedora ostree[125912]: Copying /etc changes: 23 modified, 1 removed, 92 added
Nov 30 13:30:04 fedora ostree[125912]: Finalizing staged deployment

I can't tell what's happening in that 2min gap between 13:30 and 13:32.

I then rolled back and updated once again, then ran ostree admin finalize-staged --verbose which took about 5 seconds with no additional time during reboot and have those logs here:

OT: root_is_ostree_booted: 1
OT: remounted /sysroot writable
OT: using fuse: 0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment ef8b201aa0ec1aab91ec8ea01e6cbb088cd69677552126cadb96bd4c33f0045b.0 unlocked=0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment 842a724a33989c33e65840ff5a205cb78e5b72cb335808f9afdc4949788c2b67.1 unlocked=0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment 334505ee630a80b445a7e5fa2cd22f6b874819aad7b4b8c97c34323a3e226a6e.0 unlocked=0
Copying /etc changes: 23 modified, 1 removed, 92 added
OT: Using bootloader configuration: auto
OT: Found static bootupd config
OT: Didn't find $sysroot/ostree/boot.0 symlink; assuming subbootversion 0
OT: Didn't find $sysroot/ostree/boot.0 symlink; assuming subbootversion 0
OT: Using bootloader: (none)
Bootloader updated; bootconfig swap: yes; bootversion: boot.0.1, deployment count change: 0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment b317f3a223b30f5ba4bc17a335c5be625240bb77296e05596b6723a36899b259.0 unlocked=0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment ef8b201aa0ec1aab91ec8ea01e6cbb088cd69677552126cadb96bd4c33f0045b.0 unlocked=0
OT: Target rootdev key backing-root-device-inode found
OT: Deployment 334505ee630a80b445a7e5fa2cd22f6b874819aad7b4b8c97c34323a3e226a6e.0 unlocked=0
OT: Preparing transaction in repository 0x61fad223e220
OT: Pushing lock non-blocking with timeout 300
OT: Opening repo lock file
OT: Push lock: state=unlocked, depth=0
OT: Locking repo shared
OT: Using new tmpdir staging-16b0c1bf-1d8b-41b2-a486-229c5352968d-BPKrpI
OT: Committing transaction in repository 0x61fad223e220
OT: txn commit staging-16b0c1bf-1d8b-41b2-a486-229c5352968d-BPKrpI
OT: Popping lock non-blocking with timeout 300
OT: Pop lock: state=shared, depth=1
OT: Unlocking repo

I suspected some SELinux relabeling problem before I opened this issue so I had already checked against the default policy and reset everything but the problem has persisted.

[trgeiger]

I've been messing with this a bit more and I think the issue is actually unrelated to ostree, it just happened to be expressed as a hanging ostree-finalize-staged service on shutdown. A botched tuned profile was improperly setting some sysctl values and that seems to have caused the issues.