Description of problem: I am observing this behavior since last 2 weeks now. Whenever I use "rpm-ostree upgrade" and reboot and runs "rpm-ostree status" it always prints 2 lines in red Warning: failed to finalize previous deployment check `journalctl -b -1 -u ostree-finalize-staged.service` Then when I reboot again, and check output of "rpm-ostree status" these lines go es away.Also, [parag@f31sb ~]$ journalctl -b -1 -u ostree-finalize-staged.service -- Logs begin at Mon 2019-07-15 08:11:39 IST, end at Wed 2019-09-11 20:25:06 IST. -- Sep 11 20:12:41 f31sb systemd[1]: Started OSTree Finalize Staged Deployment. Sep 11 20:14:19 f31sb systemd[1]: Stopping OSTree Finalize Staged Deployment... Sep 11 20:14:19 f31sb ostree[11220]: Finalizing staged deployment Version-Release number of selected component (if applicable): [parag@f31sb ~]$ rpm -qa rpm rpm-ostree rpm-4.15.0-0.beta.2.module_f31+5103+45c9cb69.x86_64 rpm-ostree-2019.5.7.gcac5aa41-3.fc31.x86_64 How reproducible: always Steps to Reproduce: 1. just "rpm-ostree upgrade" 2. reboot and run "rpm-ostree status" 3. observe 2 red lines as stated above Actual results: Warning: failed to finalize previous deployment Expected results: warning should not come. Additional info:
Hmm, and the system upgraded OK otherwise? If so, it's likely that the code that searches the journal for error messages is getting it wrong. Could you share the full journal logs for one of the boots (and reboots) in which you `rpm-ostree upgrade` and reboot? (E.g.: reboot, run rpm-ostree upgrade, reboot, then collect the journals for `-b -1 -o json-pretty` and `-b 0 -o json-pretty`).
Running `journalctl -u ostree-finalize-staged.service` (i.e. without the `-b` so we gather all boots) would likely help.
Created attachment 1614147 [details] rpm-ostree journal system upgraded successfully. I pick one of the F31 SB VM, started it. Then ran rpm-ostree upgrade on it then reboot then journalctl -u ostree-finalize-staged.service > rpmostree-journal.txt I am attaching this file here. Please note this system uses Hindi language as default locale.
Hm, no error messages in there. Odd.
But I keep reproducing it every time. on this test machine I layered few more packages now, reboot and again I see that warning message.
> Created attachment 1614147 [details] `-u ostree-finalize-staged.service` is not reliable unfortunately (see https://github.com/systemd/systemd/issues/2913). E.g. I'm not seeing the "Finalizing staged deployment" and "Bootloader updated" messages (the latter being the message ID we look for to know the finalization was successful). Can you retry but with `SYSLOG_IDENTIFIER=ostree -o json-pretty`?
Created attachment 1614296 [details] json output used this command $ journalctl -o verbose SYSLOG_IDENTIFIER=ostree -o json-pretty > journalctl-json-pretty.txt
Hmm, indeed the "Bootloader updated"/"Transaction complete" messages are missing. I'm not sure offhand why that is. Maybe let's cast a wider net and just include all the messages in case there are any other subtle errors happening elsewhere? (I.e. without the SYSLOG_IDENTIFIER=ostree filter, but maybe in that case, only upload the logs for just one or two boots?). Hmm, long stretch, though wondering if this could somehow be ostree-finalize-staged.service running so late now that journald doesn't have a chance to write out to disk before rebooting. Do you have any /var mounts? Do your reboot logs end with "Journal stopped"?
I am too confused to not found "Bootloder updated"/"Transaction complete" messages. But let me describe my system working again 1) I start my system, when I see notification that updates are available, I use "rpm-ostree upgrade" command 3) This command work as usual without any extra message on the gnome-terminal 4) I reboot and can see bootloader enter for new ostree and let my system boot into it 5) I login and check "rpm-ostree status" (even after I check it say after 1 hr) output, I still see "failed to finalize previous deployment" 6) Then i reboot and login and again check "rpm-ostree status", there is no warning Yes on my host system I have extra /var/junk partition which mounts successfully always and I can use it. You are right that my reboot logs showing "Journal stopped" messages. e.g. See ==================================================================================== Sep 13 09:08:30 f31sb systemd[1]: Shutting down. Sep 13 09:08:30 f31sb lvm[8535]: 3 logical volume(s) in volume group "fedora" unmonitored Sep 13 09:08:30 f31sb systemd[1]: Hardware watchdog 'iTCO_wdt', version 0 Sep 13 09:08:30 f31sb systemd[1]: Set hardware watchdog to 10min. Sep 13 09:08:30 f31sb kernel: watchdog: watchdog0: watchdog did not stop! Sep 13 09:08:30 f31sb kernel: printk: systemd-shutdow: 70 output lines suppressed due to ratelimiting Sep 13 09:08:30 f31sb systemd-shutdown[1]: Syncing filesystems and block devices. Sep 13 09:08:30 f31sb systemd-shutdown[1]: Sending SIGTERM to remaining processes... Sep 13 09:08:30 f31sb systemd-journald[718]: Journal stopped -- Reboot -- Sep 13 09:08:44 localhost kernel: microcode: microcode updated early to revision 0xb4, date = 2019-04-01 Sep 13 09:08:44 localhost kernel: Linux version 5.3.0-0.rc6.git0.1.fc31.x86_64 (mockbuild.fedoraproject.org) (gcc version 9.1.1 20190605 (Red Hat 9.1.1-2) (GCC)) #1 SMP Mon Aug 26 13:01:25 UTC 2019 ====================================================================================== So on this host system, I had few reboots but "Journal stopped" message appeared only once. I guess it appeared when I reboot after upgrade? To cross-verify this I am now starting my F31 SB VM and upgrading it 1) I start my VM and without going for upgrade executed [parag@localhost ~]$ journalctl --since=today SYSLOG_IDENTIFIER=systemd-journald -- Logs begin at Tue 2019-08-20 10:07:12 IST, end at Fri 2019-09-13 10:49:27 IST. -- Sep 13 10:31:59 localhost systemd-journald[299]: Journal started Sep 13 10:31:59 localhost systemd-journald[299]: Runtime Journal (/run/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 8.0M, max 99.3M, 91.3M free. Sep 13 10:32:00 localhost systemd-journald[299]: Journal stopped Sep 13 10:32:01 localhost.localdomain systemd-journald[299]: Received SIGTERM from PID 1 (systemd). Sep 13 10:32:01 localhost.localdomain systemd-journald[659]: Journal started Sep 13 10:32:01 localhost.localdomain systemd-journald[659]: Runtime Journal (/run/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 8.0M, max 99.3M, 91.3M free. Sep 13 10:32:01 localhost.localdomain systemd-journald[659]: Time spent on flushing to /var is 92.813ms for 995 entries. Sep 13 10:32:01 localhost.localdomain systemd-journald[659]: System Journal (/var/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 192.0M, max 1.1G, 970.0M free. [parag@localhost ~]$ 2) rpm-ostree upgrade executed, also executed "rpm-ostree status" whose output was normal 3) Reboot, checked "rpm-ostree status" command output which showed that warning (2 red lines) 4) now let's check journal command again which just added below lines to journal ================================================================================ -- Reboot -- Sep 13 10:56:11 localhost systemd-journald[298]: Journal started Sep 13 10:56:11 localhost systemd-journald[298]: Runtime Journal (/run/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 8.0M, max 99.3M, 91.3M free. Sep 13 10:56:12 localhost systemd-journald[298]: Journal stopped Sep 13 10:56:13 localhost.localdomain systemd-journald[298]: Received SIGTERM from PID 1 (systemd). Sep 13 10:56:13 localhost.localdomain systemd-journald[659]: Journal started Sep 13 10:56:13 localhost.localdomain systemd-journald[659]: Runtime Journal (/run/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 8.0M, max 99.3M, 91.3M free. Sep 13 10:56:13 localhost.localdomain systemd-journald[659]: Time spent on flushing to /var is 53.765ms for 992 entries. Sep 13 10:56:13 localhost.localdomain systemd-journald[659]: System Journal (/var/log/journal/3bc6eaeb8e4142b4afabded586da3e8a) is 192.0M, max 1.1G, 970.0M free. ================================================================================ 5) Then reboot this system to repeat above 3 and 4 steps. I got same output as above 4 step. In conclusion, I got one system with extra /var mount and another no extra /var mount. But both the systems showing "Journal stopped" messages but that became pattern. I am not sure how it can be related to not finalizing previous deployment warning. I am also attaching one text file here from this F31 VM which includes above journal messages.
Created attachment 1614705 [details] 13th Sept journal logs Do ask anymore logs if needed. Thank you.
OK, just wanted to verify you didn't have e.g. /var/log or /var/log/journal themselves as separate mounts and there was some funkiness going on with systemd not being able to write everything back. > Created attachment 1614705 [details] > 13th Sept journal logs I meant the full logs, i.e. `journalctl --since=today --output=json-pretty` (or similar, so that it covers the boot where finalization ran). Is the F31 VM where you're seeing this mostly OOTB? If so, I can try to see if I can reproduce this.
Created attachment 1616218 [details] 18th Sept journal logs
Created attachment 1616219 [details] gzipped 18th Sept journal logs ah but you need logs till when it finalizes tree. So it took me like 1) Start system, run "rpm-ostree upgrade" 2) reboot 3) "rpm-ostree status" showed warning 4) reboot 5) now no warning and now at this stage this log file is created. This time I gzipped the txt file.
also, this VM do not have any extra partition. Filesystem Size Used Avail Use% Mounted on devtmpfs 963M 0 963M 0% /dev tmpfs 994M 0 994M 0% /dev/shm tmpfs 994M 1.3M 993M 1% /run /dev/mapper/fedora-root 12G 6.8G 4.1G 63% /sysroot tmpfs 994M 80K 994M 1% /tmp /dev/vda1 976M 142M 768M 16% /boot tmpfs 199M 0 199M 0% /run/user/1000 tmpfs 199M 5.7M 194M 3% /run/user/42 I can reproduce this issue on host as well as guest F31 SB systems.
Further debugging, I also found grub menu entries are doubled. e.g. Fedora 31.20190917.n.2 (Workstation Edition) (ostree) Fedora 31.20190916.n.0 (Workstation Edition) (ostree) Fedora 31.20190917.n.2 (Workstation Edition) (ostree) Fedora 31.20190916.n.0 (Workstation Edition) (ostree) but first entry looks normal (5 lines) when pressed 'e' but the second entry contains (15 lines)
Does running `ostree admin finalize-staged` and rebooting help for you?
BTW I think this bug is reproducible on any fresh SB31 install.
Yes it works. I installed new ostree update, executed `ostree admin finalize-staged` and rebooted. Then `rpm-ostree status` did not show any warning. But boot loader still did shown duplicate boot entries.
(In reply to Jens Petersen from comment #17) > BTW I think this bug is reproducible on any fresh SB31 install. I mean after any ostree deployment transaction.
From my testing, the simplest workaround after an ostree transaction, eg: $ rpm-ostree install zsh seems to be to run: $ sudo ostree admin finalize-staged $ reboot Then no warning is seen in rpm-ostree status.
> Blocks: 1644940 Hmm, not sure if it's bad enough to warrant a freeze exception. Note that (AFAICT) it still does update; it's just that it throws a spurious (albeit scary) warning after reboot. > BTW I think this bug is reproducible on any fresh SB31 install. Thanks for checking this. Investigating now.
OK, I can confirm this happens OOTB on SB31. Though it doesn't happen everytime. It does not reproduce on an f31 FCOS I built. Will dig deeper.
Third problem discovered now that since last 2-3 days everytime I install new ostree and reboot, it never reaches to grub and my laptop goes in hang condition. Then I need to power down and hard start the T480s laptop and it succeeds.
(In reply to Jonathan Lebon from comment #22) > OK, I can confirm this happens OOTB on SB31. Though it doesn't happen > everytime. It does not reproduce on an f31 FCOS I built. Thanks! It can break toolbox for example.
FEDORA-2019-5f32602fd4 has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-5f32602fd4
ostree-2019.4-1.fc31, rpm-ostree-2019.6-1.fc31 has been pushed to the Fedora 31 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-5f32602fd4
Jonathan, I am unable to conclude if the duplicate boot loader entries in grub is considered as bug and which component to report it? After updating to this new fix, I still see for each installed ostree there are 2 entries in grub.
> I am unable to conclude if the duplicate boot loader entries in grub is considered as bug and which component to report it? After updating to this new fix, I still see for each installed ostree there are 2 entries in grub. Should probably be a separate bug report, because that one might actually be worth an exception given how confusing it is. But anyway, should be fixed by: https://pagure.io/workstation-ostree-config/pull-request/156
ostree-2019.4-2.fc31, rpm-ostree-2019.6-1.fc31 has been pushed to the Fedora 31 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-5f32602fd4
ostree-2019.4-2.fc31, rpm-ostree-2019.6-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.
FEDORA-2020-df95a90cce has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-df95a90cce
FEDORA-2020-df95a90cce has been pushed to the Fedora 31 testing repository. In short time you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-df95a90cce` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-df95a90cce See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2020-df95a90cce has been pushed to the Fedora 31 stable repository. If problem still persists, please make note of it in this bug report.
This issue appearance on fedora silverblue 33.20201127.0 again. [junjie@xps ~]$ rpm-ostree status State: idle Warning: failed to finalize previous deployment error: During /etc merge: While computing configuration diff: Error reading from file: Input/output error check `journalctl -b -1 -u ostree-finalize-staged.service` Deployments: ● ostree://fedora:fedora/33/x86_64/silverblue Version: 33.20201127.0 (2020-11-27T00:41:09Z) BaseCommit: 474dce288460e1e75b15f7ef5d5e21aa1c20650c7f4bf814dba04ecdb6d89729 GPGSignature: Valid signature by 963A2BEB02009608FE67EA4249FD77499570FF31 LayeredPackages: google-chrome-stable [junjie@xps ~]$ journalctl -b -1 -u ostree-finalize-staged.service -- Logs begin at Fri 2020-10-23 16:46:17 CST, end at Sat 2020-11-28 20:20:59 CST. -- Nov 28 19:58:34 xps systemd[1]: Finished OSTree Finalize Staged Deployment. Nov 28 19:59:10 xps systemd[1]: Stopping OSTree Finalize Staged Deployment... Nov 28 19:59:10 xps ostree[9140]: Finalizing staged deployment Nov 28 19:59:10 xps ostree[9140]: error: During /etc merge: While computing configuration diff: Error reading from file> Nov 28 19:59:10 xps systemd[1]: ostree-finalize-staged.service: Control process exited, code=exited, status=1/FAILURE Nov 28 19:59:10 xps systemd[1]: ostree-finalize-staged.service: Failed with result 'exit-code'. Nov 28 19:59:10 xps systemd[1]: Stopped OSTree Finalize Staged Deployment. [junjie@xps ~]$ rpm -q rpm-ostree ostree warning: Found bdb Packages database while attempting sqlite backend: using bdb backend. rpm-ostree-2020.8-1.fc33.x86_64 ostree-2020.8-1.fc33.x86_64 [junjie@xps ~]$ rpm-ostree upgrade --preview ⠄ Receiving metadata objects: 0/(estimating) -/s 0 bytes... Receiving metadata objects: 0/(estimating) -/s 0 bytes... done Enabled rpm-md repositories: fedora-cisco-openh264 updates fedora google-chrome Updating metadata for 'fedora-cisco-openh264'... done rpm-md repo 'fedora-cisco-openh264'; generated: 2020-08-25T19:10:34Z Updating metadata for 'updates'... done rpm-md repo 'updates'; generated: 2020-11-27T00:49:07Z Updating metadata for 'fedora'... done rpm-md repo 'fedora'; generated: 2020-10-19T23:27:19Z Updating metadata for 'google-chrome'... done rpm-md repo 'google-chrome'; generated: 2020-11-19T20:41:45Z Importing rpm-md... done AvailableUpdate: Version: 33.20201128.0 (2020-11-28T01:16:50Z) Commit: 11a57ff749420f5e88c3f481616201dd8955f08f1749bee98ff3cf63808a7e14 GPGSignature: 1 signature Signature made Sat 28 Nov 2020 09:16:54 AM CST using RSA key ID 49FD77499570FF31 Good signature from "Fedora <fedora-33-primary>" Upgraded: c-ares 1.16.1-3.fc33 -> 1.17.0-1.fc33 cups-filters 1.28.5-1.fc33 -> 1.28.5-3.fc33 cups-filters-libs 1.28.5-1.fc33 -> 1.28.5-3.fc33 gtkmm30 3.24.2-3.fc33 -> 3.24.2-4.fc33 hplip 3.20.9-2.fc33 -> 3.20.9-4.fc33 hplip-common 3.20.9-2.fc33 -> 3.20.9-4.fc33 hplip-libs 3.20.9-2.fc33 -> 3.20.9-4.fc33 libgcrypt 1.8.6-4.fc33 -> 1.8.7-1.fc33 libsane-airscan 0.99.18-1.fc33 -> 0.99.21-1.fc33 libsane-hpaio 3.20.9-2.fc33 -> 3.20.9-4.fc33 pam 1.4.0-8.fc33 -> 1.4.0-9.fc33 qpdf-libs 10.0.3-1.fc33 -> 10.0.4-1.fc33 sane-airscan 0.99.18-1.fc33 -> 0.99.21-1.fc33 thermald 2.3-2.fc33 -> 2.4-1.fc33
> During /etc merge: While computing configuration diff: Error reading from file: Input/output error This is a different issue. If it's reproducible, please file a separate bug for this.