Bug 1672283

Summary: rpm-ostree install <pkg> wrongly said "success" on failure deployment
Product: [Fedora] Fedora Reporter: Victor Toso <victortoso>
Component: ostreeAssignee: Jonathan Lebon <jlebon>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 29CC: dustymabe, jlebon, jonathan, miabbott, rfairley, tagoh, walters
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ostree-2019.2-1.fc30 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-04-29 01:41:49 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Victor Toso 2019-02-04 13:07:29 UTC
Description of problem:
Trying to install meson with rpm-ostree, due failure to copy files from /etc, the image deployment failed but user is not aware of that till next reboot.

See upstream bug: https://github.com/projectatomic/rpm-ostree/issues/1567


Version-Release number of selected component (if applicable):
2019.1

How reproducible:
100% if you have something that breaks deployment :)
In my case, as mentioned below, some cups files were not present and that was enough.

Steps to Reproduce:
...

Actual results:
...

Expected results:
...

Additional info:

* Trying to install meson, nothing seems wrong

$ rpm-ostree install meson
Checking out tree 24963d8... done
Enabled rpm-md repositories: updates fedora
rpm-md repo 'updates' (cached); generated: 2019-02-02T03:06:38Z
rpm-md repo 'fedora' (cached); generated: 2018-10-24T22:20:15Z
Importing rpm-md... done
Resolving dependencies... done
Checking out packages... done
Running pre scripts... done
Running post scripts... done
Writing rpmdb... done
Writing OSTree commit... done
Staging deployment... done
Freed: 41.7 MB (pkgcache branches: 0)
Upgraded:
  fedora-toolbox 0.0.3-1.fc29 -> 0.0.4-1.fc29
  vim-common 2:8.1.818-1.fc29 -> 2:8.1.847-2.fc29
  vim-enhanced 2:8.1.818-1.fc29 -> 2:8.1.847-2.fc29
  vim-filesystem 2:8.1.818-1.fc29 -> 2:8.1.847-2.fc29
Added:
  meson-0.49.1-1.fc29.noarch
  ninja-build-1.8.2-5.fc29.x86_64
Run "systemctl reboot" to start a reboot

* rpm-ostree status points to it

$ rpm-ostree status
State: idle
Warning: failed to finalize previous deployment
         error: During /etc merge: Reading modified config file: fstatat(cups/ppd/AMS_Canon_Colour.ppd): No such file or directory
         check `journalctl -b -1 -u ostree-finalize-staged.service`

checking the requested info from jornal

$ journalctl -b -1 -u ostree-finalize-staged.service
-- Logs begin at Mon 2019-01-28 18:25:57 CET, end at Mon 2019-02-04 13:39:32 CET. --
Feb 04 13:33:21 wingsuit systemd[1]: Started OSTree Finalize Staged Deployment.
Feb 04 13:34:22 wingsuit systemd[1]: Stopping OSTree Finalize Staged Deployment...
Feb 04 13:34:22 wingsuit ostree[6525]: Finalizing staged deployment
Feb 04 13:34:23 wingsuit ostree[6525]: Copying /etc changes: 40 modified, 0 removed, 113 added
Feb 04 13:34:23 wingsuit ostree[6525]: error: During /etc merge: Reading modified config file: fstatat(cups/ppd/AMS_Canon_Colour.ppd): No such file or directory
Feb 04 13:34:23 wingsuit systemd[1]: ostree-finalize-staged.service: Control process exited, code=exited status=1
Feb 04 13:34:23 wingsuit systemd[1]: ostree-finalize-staged.service: Failed with result 'exit-code'.
Feb 04 13:34:23 wingsuit systemd[1]: Stopped OSTree Finalize Staged Deployment.

The problem around cups seems another bug somewhere. I could finally deploy then new image after stop and disabling cups-browsed and cups services.

Comment 1 Jonathan Lebon 2019-02-04 15:52:28 UTC
The actual error here is:

> During /etc merge: Reading modified config file: fstatat(cups/ppd/AMS_Canon_Colour.ppd): No such file or directory

The fact that `rpm-ostree install` didn't error out is unrelated. (The error that occurred in fact happened at `systemctl reboot` time, not at `rpm-ostree install` time. See https://github.com/ostreedev/ostree/pull/1503 and https://github.com/projectatomic/rpm-ostree/issues/40 for background).

Re. `meson` specifically, note that the pattern we try to encourage on Silverblue is to have all your development tools in a container and keep the base OS minimal. The less things there are, the more reliable critical operations like booting, rebooting, and upgrading are. See http://www.projectatomic.io/blog/2018/02/fedora-atomic-workstation/ for some more context there.

I'm going to close this as NOTABUG, but feel free to reopen if I misunderstood the intent. (Though note we much prefer keeping issues upstream! :))

Comment 2 Colin Walters 2019-02-04 16:17:32 UTC
I think we could do better to try to ensure more services are fully shut down before starting `ostree-finalize-staged.service`.  Maybe there's a different shutdown target or ordering we could use there.

Comment 3 Akira TAGOH 2019-04-12 06:01:53 UTC
I'm facing same issue here. so how can I recover that error to make things operational successfully? doing `systemctl restart ostree-finalize-staged` works as workaround to apply changes though, I want a solution not a workaround.

Comment 4 Jonathan Lebon 2019-04-12 17:44:23 UTC
> I'm facing same issue here.

What does `journalctl -b -1 -u ostree-finalize-staged.service` say? A similar cups issue?

Comment 5 Akira TAGOH 2019-04-15 05:15:33 UTC
(In reply to Jonathan Lebon from comment #4)
> What does `journalctl -b -1 -u ostree-finalize-staged.service` say? A
> similar cups issue?

Yes, same.

Jan 10 16:18:48 localhost.localdomain systemd[1]: Stopping OSTree Finalize Staged Deployment...
Jan 10 16:19:00 localhost.localdomain ostree[8152]: Finalizing staged deployment
Jan 10 16:19:06 localhost.localdomain ostree[8152]: Copying /etc changes: 22 modified, 0 removed, 113 added

Jan 10 16:19:06 localhost.localdomain ostree[8152]: error: During /etc merge: Reading modified config file:
 fstatat(cups/ppd/HKG_35F_Pearl.ppd): No such file or directory
Jan 10 16:19:06 localhost.localdomain systemd[1]: ostree-finalize-staged.service: Control process exited, c
ode=exited status=1
Jan 10 16:19:06 localhost.localdomain systemd[1]: ostree-finalize-staged.service: Failed with result 'exit-
code'.
Jan 10 16:19:06 localhost.localdomain systemd[1]: Stopped OSTree Finalize Staged Deployment.
-- Reboot --

Comment 6 Jonathan Lebon 2019-04-15 13:18:22 UTC
This is likely fixed by https://github.com/ostreedev/ostree/pull/1840. Will re-open this bug to track that patch making it into the stable repos.

Comment 7 Akira TAGOH 2019-04-16 08:05:50 UTC
Aha. I got the point. indeed, no error happened if I do `systemctl stop cups` prior to reboot. so yeah, that fix should works. I'm looking forward to see it is released soon.

Comment 8 Fedora Update System 2019-04-26 16:48:35 UTC
ostree-2019.2-1.fc30 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-e42181e4da

Comment 9 Fedora Update System 2019-04-27 22:30:39 UTC
ostree-2019.2-1.fc30 has been pushed to the Fedora 30 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-e42181e4da

Comment 10 Fedora Update System 2019-04-29 01:41:49 UTC
ostree-2019.2-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report.