Bug 1615992 - dnf 3.3.0-1 cannot record scriptlet errors in livemedia creation
Summary: dnf 3.3.0-1 cannot record scriptlet errors in livemedia creation
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dnf
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Daniel Mach
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-08-14 16:56 UTC by Kevin Fenzi
Modified: 2019-03-02 17:57 UTC (History)
12 users (show)

Fixed In Version: dnf-3.3.0-2.fc29 dnf-3.5.1-1.fc29
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-09-20 22:35:16 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Kevin Fenzi 2018-08-14 16:56:56 UTC
today's (2018-08-14) rawhide compose failed because the kde live media didn't compose: 

https://koji.fedoraproject.org/koji/taskinfo?taskID=29063497

11:38:47,810 INF packaging: Configuring (running scriptlet for): pulseaudio-12.2-1.fc29.x86_64 1531762933 ed9691ba0bc895d0e2842404bb6ec6651f3b4fb87b0c277339c8b5007086522c
11:38:47,837 INF packaging: Configuring (running scriptlet for): kernel-core-4.18.0-1.fc29.x86_64 1534178946 be1e505f49c7a531798e39cc18bf06df5a3d9061e51f98d0db71df8eab6aacc3
11:40:07,220 CRT dnf: Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 275, in callback
    self._scriptStop()
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 413, in _scriptStop
    self._scriptout()
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 211, in _scriptout
    self.base.history.log_scriptlet_output(msgs)
  File "/usr/lib/python3.7/site-packages/dnf/db/history.py", line 471, in log_scriptlet_output
    self.swdb.addConsoleOutputLine(1, line)
  File "/usr/lib64/python3.7/site-packages/libdnf/transaction.py", line 802, in addConsoleOutputLine
    return _transaction.Swdb_addConsoleOutputLine(self, fileDescriptor, line)
RuntimeError: C++ std::exception: Step: attempt to write a readonly database in

        INSERT INTO
            console_output (
                trans_id,
                file_descriptor,
                line
            )
        VALUES
            (1, 1, 'dracut: No ''/dev/log'' or ''logger'' included for syslog logging');

11:40:07,223 INF packaging: Configuring (running scriptlet for): firewalld-0.6.1-1.fc29.noarch 1533930809 829d4b44d0ce9c5b7defe3306e12356691be7c494dfe433e3375f9677db46844

2018-08-14 11:35:30,975 INFO pylorax: Installing p11-kit-trust.x86_64 (201/1629)
2018-08-14 11:40:19,614 ERROR pylorax: Running anaconda failed: process '['anaconda', '--kickstart', '/chroot_tmpdir/koji-image-f29-build-29063497.ks', '--cmdline', '--loglevel', 'debug', '--dirinstall', '--remotelog', '127.0.0.1:37273']' exited with status 1
2018-08-14 11:40:19,614 INFO livemedia-creator: Shutting down log processing
2018-08-14 11:40:21,109 ERROR pylorax: Install failed: novirt_install failed
2018-08-14 11:40:21,110 INFO pylorax: Removing bad disk image
2018-08-14 11:40:21,731 ERROR pylorax: ERROR: Image creation failed: novirt_install failed
2018-08-14 11:40:21,731 ERROR livemedia-creator: Image creation failed: novirt_install failed

This could be a dracut bug too...

Comment 1 Adam Williamson 2018-08-15 21:23:42 UTC
We see this same basic failure on every single live image compose, just with different packages and different messages in each. It seems too much to believe that all these scriptlet outputs suddenly appeared overnight, a dnf behaviour change is much more plausible.

In 20180813.n.0 compose many live images succeeded. In 20180814.n.0 and 20180815.n.1 every single attempt has failed, most with this kind of error (the others fail for some other reason and were probably failing before too).

To make a direct comparison, here's 20180813.n.0 Workstation x86_64: https://koji.fedoraproject.org/koji/taskinfo?taskID=29046089

and here's 20180814.n.0 Workstation x86_64:
https://koji.fedoraproject.org/koji/taskinfo?taskID=29063609

note in the 20180814.n.0 anaconda-packaging.log the traceback:
https://kojipkgs.fedoraproject.org//work/tasks/3609/29063609/anaconda-packaging.log

11:42:55,322 INF packaging: Configuring (running scriptlet for): nss-3.38.0-4.fc29.x86_64 1532100094 eba1b62963f402f43d8e5b33dcb1cda084712dd0f65ecef41365ee2ef48f21d0
11:42:55,487 CRT dnf: Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 275, in callback
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 413, in _scriptStop
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 211, in _scriptout
  File "/usr/lib/python3.7/site-packages/dnf/db/history.py", line 471, in log_scriptlet_output
  File "/usr/lib64/python3.7/site-packages/libdnf/transaction.py", line 802, in addConsoleOutputLine
RuntimeError: C++ std::exception: Step: attempt to write a readonly database in

        INSERT INTO
            console_output (
                trans_id,
                file_descriptor,
                line
            )
        VALUES
            (1, 1, 'Setting system policy to DEFAULT');

while in the 20180813.n.0 anaconda-packaging.log:
https://kojipkgs.fedoraproject.org//work/tasks/6089/29046089/anaconda-packaging.log

there is no such traceback, despite the version of nss that's installed being identical.

Marking as an automatic blocker per https://fedoraproject.org/wiki/QA:SOP_blocker_bug_process#Automatic_blockers , "Bugs which entirely prevent the composition of one or more of the release-blocking images required to be built for a currently-pending (pre-)release".

Comment 2 Adam Williamson 2018-08-15 21:32:09 UTC
libdnf 054b9209738b0f31d094e424f2a79a3aa5233a45 seems a bit odd here. It does this:

-        exec("PRAGMA journal_mode = TRUNCATE; PRAGMA locking_mode = EXCLUSIVE; PRAGMA foreign_keys = ON;");
+        exec("PRAGMA journal_mode = TRUNCATE; PRAGMA locking_mode = DEFAULT; PRAGMA foreign_keys = ON;");

only per https://sqlite.org/pragma.html#pragma_locking_mode , 'DEFAULT' isn't a thing. Only 'EXCLUSIVE' and 'NORMAL'. Dunno how that could cause this, really, but it looks odd.

Comment 3 Adam Williamson 2018-08-15 21:34:37 UTC
The other obvious suspect here is 13f61f693c11e25962e8c07554a7d86541638164 - that "RuntimeError: C++ std::exception:" rather looks like it comes from that code.

Comment 4 Kevin Fenzi 2018-08-16 17:23:23 UTC
In order to get composes out, I have: 

koji untag-pkg f30 dnf-3.3.0-1.fc29  libdnf-0.17.1-1.fc29 libdnf-0.17.2-1.fc29
koji untag-pkg f29 dnf-3.3.0-1.fc29  libdnf-0.17.1-1.fc29 libdnf-0.17.2-1.fc29

So, please make sure this is addressed in the next builds.

Comment 5 Daniel Mach 2018-08-27 14:41:06 UTC
The root cause is the way how Anaconda (and possibly also other tools) use DNF and how DNF works with the history database.

When a connection to the history DB is initiated, DNF gets *forked* incl. the db connection via multiprocessing. DNF and libdnf were never designed to be thread-safe (or fork-safe).
If a process with an opened connection gets forked, weird stuff happens.
If it gets forked with a connection that is not opened yet, it may get opened from both processes and we end up with the read-only error as reported in this bug.

Ideally the whole DNF object or the history db connection should live in a separate process and communicate via some API, but that's proably a long-term plan not achievable in F29 time frame.

Comment 6 Daniel Mach 2018-08-28 18:54:01 UTC
Fixed in dnf-3.3.0-2.fc29
Unfortunately I couldn't build it due to missing libdnf-0.17.2-1.fc29 in the build root.
Could you tag it back and trigger a new dnf build from f29 branch?

Comment 7 Kevin Fenzi 2018-08-28 20:12:13 UTC
Fedora 29 is now under bodhi (like stable releases), so the process there is the same: create a buildroot override then build any additional builds and then submit an update. Note however that f29 is in freeze for Beta, so updates will need a Freeze Exception or approved blocker to be able to to stable. 

That said, I see no rawhide/f30 builds. You only want this to go to f29 for some reason?

Comment 8 Daniel Mach 2018-08-29 05:45:30 UTC
Yes, I want this only in f29 as it's a single backported change.
Rawhide/f30 will most likely get a new upstream release,
which will go to f29 once it's more tested.

Comment 9 Daniel Mach 2018-08-29 05:47:54 UTC
BTW, I couldn't create the override, Bodhi complains about Nvr: invalid build.
Maybe it's because it's untagged.

Comment 10 Fedora Update System 2018-08-29 16:38:13 UTC
dnf-3.3.0-2.fc29 libdnf-0.17.2-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-f16a71bc92

Comment 11 Kevin Fenzi 2018-08-29 16:39:24 UTC
I've tagged libdnf in, made an overridem built dnf and submitted an update with both of them in it. 

Let me know if you need anything further there...

Comment 12 Fedora Update System 2018-09-02 02:56:34 UTC
dnf-3.3.0-2.fc29, libdnf-0.17.2-1.fc29 has been pushed to the Fedora 29 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-2018-f16a71bc92

Comment 13 Adam Williamson 2018-09-04 22:09:28 UTC
So, as we untagged 3.3 / 0.17.1 from f29 and it got Beta frozen in that state, we do not actually need to push it out during the Beta freeze to fix this bug. I'm dropping the AcceptedBlocker metadata.

Daniel, if you think it would be best to ship F29 Beta with these updated packages - rather than with the versions it currently has, which are dnf-3.2.0-2.fc29 and libdnf-0.17.0-2.fc29 - please nominate some bug that is fixed by those versions as a blocker or freeze exception issue. Thanks!

Comment 14 Fedora Update System 2018-09-14 03:06:03 UTC
dnf-3.5.1-1.fc29 dnf-plugins-core-3.0.3-1.fc29 libdnf-0.19.1-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-f16a71bc92

Comment 15 Fedora Update System 2018-09-14 19:59:52 UTC
anaconda-29.24.3-1.fc29, dnf-3.5.1-1.fc29, dnf-plugins-core-3.0.3-1.fc29, libdnf-0.19.1-2.fc29, lorax-29.12-2.fc29 has been pushed to the Fedora 29 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-2018-f16a71bc92

Comment 16 Fedora Update System 2018-09-18 17:09:47 UTC
anaconda-29.24.3-1.fc29 dnf-3.5.1-1.fc29 dnf-plugins-core-3.0.3-1.fc29 libdnf-0.19.1-2.fc29 lorax-29.12-2.fc29 python-blivet-3.1.0-2.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-f16a71bc92

Comment 17 Fedora Update System 2018-09-20 16:16:01 UTC
anaconda-29.24.3-1.fc29, dnf-3.5.1-1.fc29, dnf-plugins-core-3.0.3-1.fc29, libdnf-0.19.1-3.fc29, lorax-29.12-2.fc29, python-blivet-3.1.0-2.fc29 has been pushed to the Fedora 29 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-2018-f16a71bc92

Comment 18 Fedora Update System 2018-09-20 22:35:16 UTC
anaconda-29.24.3-1.fc29, dnf-3.5.1-1.fc29, dnf-plugins-core-3.0.3-1.fc29, libdnf-0.19.1-3.fc29, lorax-29.12-2.fc29, python-blivet-3.1.0-2.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.