Bug 1724779 - Incorrect logging of post-transaction scripts
Summary: Incorrect logging of post-transaction scripts
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: dnf
Version: 39
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
Assignee: rpm-software-management
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1720234 2120346 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-27 18:50 UTC by secondary
Modified: 2023-08-16 08:08 UTC (History)
15 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-11-30 18:22:30 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description secondary 2019-06-27 18:50:06 UTC
Description of problem:

The information logged by DNF for scriptlets run between the "Cleanup" and "Verifying" sections could not be more incorrect. Totally foobar. Specifically, I believe this applies to: %posttrans, %transfiletriggerin, and %transfiletriggerpostun scriptlets.

1. Incorrect package. DNF uses the name of the most recently processed package. In the example below, "gpxsee" rather than "glusterfs".
2. Incorrect scriptlet name. In this example, "%triggerin" rather than "%transfiletriggerin".
3. Hidden output. Any output that could be used to track down the failure is hidden.
4. The final summary combines the first two problems and is completely misleading. Rather than:
   > Error in <unknown> scriptlet in rpm package gpxsee
It should be:
   > Error in %transfiletriggerin scriptlet in rpm package systemd triggered by rpm package glusterfs


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

dnf.noarch == 4.2.5-1.fc30


How reproducible:

Always. See also [1] for another example.


Steps to Reproduce:
1. Install multiple packages. One package must have a scriptlet which runs after the transaction, and that package must not be the final transaction.

Actual results:

$ dnf reinstall blivet-data glusterfs glusterfs-api glusterfs-cli glusterfs-client-xlators glusterfs-fuse glusterfs-libs gpxsee libnfsidmap mutter nfs-utils python3-blivet python3-cloudpickle scantailor 
...
Running transaction check
Transaction check succeeded.
Running transaction test
Transaction test succeeded.
Running transaction
  Preparing        :
  Running scriptlet: glusterfs-libs-6.3-1.fc30.x86_64
  Reinstalling     : glusterfs-libs-6.3-1.fc30.x86_64
  Running scriptlet: glusterfs-6.3-1.fc30.x86_64
  Reinstalling     : glusterfs-6.3-1.fc30.x86_64
  Running scriptlet: glusterfs-6.3-1.fc30.x86_64
  Reinstalling     : glusterfs-client-xlators-6.3-1.fc30.x86_64
  Reinstalling     : libnfsidmap-1:2.4.1-0.fc30.x86_64
  Reinstalling     : blivet-data-1:3.1.4-1.fc30.noarch
  Reinstalling     : python3-blivet-1:3.1.4-1.fc30.noarch
  Running scriptlet: nfs-utils-1:2.4.1-0.fc30.x86_64
  Reinstalling     : nfs-utils-1:2.4.1-0.fc30.x86_64
  Running scriptlet: nfs-utils-1:2.4.1-0.fc30.x86_64
  Reinstalling     : glusterfs-api-6.3-1.fc30.x86_64
  Reinstalling     : glusterfs-fuse-6.3-1.fc30.x86_64
  Reinstalling     : glusterfs-cli-6.3-1.fc30.x86_64
  Reinstalling     : scantailor-0.9.11.1-24.fc30.x86_64
  Reinstalling     : python3-cloudpickle-1.2.1-1.fc30.noarch
  Reinstalling     : mutter-3.32.2-2.fc30.x86_64
  Reinstalling     : gpxsee-7.9-1.fc30.x86_64
  Cleanup          : glusterfs-fuse-6.3-1.fc30.x86_64
  Cleanup          : glusterfs-api-6.3-1.fc30.x86_64
  Cleanup          : glusterfs-6.3-1.fc30.x86_64
  Running scriptlet: glusterfs-6.3-1.fc30.x86_64
  Cleanup          : glusterfs-cli-6.3-1.fc30.x86_64
  Cleanup          : glusterfs-client-xlators-6.3-1.fc30.x86_64
  Running scriptlet: nfs-utils-1:2.4.1-0.fc30.x86_64
  Cleanup          : nfs-utils-1:2.4.1-0.fc30.x86_64
  Running scriptlet: nfs-utils-1:2.4.1-0.fc30.x86_64
  Cleanup          : python3-blivet-1:3.1.4-1.fc30.noarch
  Cleanup          : blivet-data-1:3.1.4-1.fc30.noarch
  Cleanup          : python3-cloudpickle-1.2.1-1.fc30.noarch
  Cleanup          : libnfsidmap-1:2.4.1-0.fc30.x86_64
  Cleanup          : glusterfs-libs-6.3-1.fc30.x86_64
  Cleanup          : scantailor-0.9.11.1-24.fc30.x86_64
  Cleanup          : mutter-3.32.2-2.fc30.x86_64
  Cleanup          : gpxsee-7.9-1.fc30.x86_64
  Running scriptlet: gpxsee-7.9-1.fc30.x86_64
warning: %triggerin(systemd-241-8.git9ef65cb.fc30.x86_64) scriptlet failed, exit status 65

Error in <unknown> scriptlet in rpm package gpxsee
  Verifying        : blivet-data-1:3.1.4-1.fc30.noarch
  Verifying        : blivet-data-1:3.1.4-1.fc30.noarch
  Verifying        : glusterfs-6.3-1.fc30.x86_64
  Verifying        : glusterfs-6.3-1.fc30.x86_64
  Verifying        : glusterfs-api-6.3-1.fc30.x86_64
  Verifying        : glusterfs-api-6.3-1.fc30.x86_64
  Verifying        : glusterfs-cli-6.3-1.fc30.x86_64
  Verifying        : glusterfs-cli-6.3-1.fc30.x86_64
  Verifying        : glusterfs-client-xlators-6.3-1.fc30.x86_64
  Verifying        : glusterfs-client-xlators-6.3-1.fc30.x86_64
  Verifying        : glusterfs-fuse-6.3-1.fc30.x86_64
  Verifying        : glusterfs-fuse-6.3-1.fc30.x86_64
  Verifying        : glusterfs-libs-6.3-1.fc30.x86_64
  Verifying        : glusterfs-libs-6.3-1.fc30.x86_64
  Verifying        : gpxsee-7.9-1.fc30.x86_64
  Verifying        : gpxsee-7.9-1.fc30.x86_64
  Verifying        : libnfsidmap-1:2.4.1-0.fc30.x86_64
  Verifying        : libnfsidmap-1:2.4.1-0.fc30.x86_64
  Verifying        : mutter-3.32.2-2.fc30.x86_64
  Verifying        : mutter-3.32.2-2.fc30.x86_64
  Verifying        : nfs-utils-1:2.4.1-0.fc30.x86_64
  Verifying        : nfs-utils-1:2.4.1-0.fc30.x86_64
  Verifying        : python3-blivet-1:3.1.4-1.fc30.noarch
  Verifying        : python3-blivet-1:3.1.4-1.fc30.noarch
  Verifying        : python3-cloudpickle-1.2.1-1.fc30.noarch
  Verifying        : python3-cloudpickle-1.2.1-1.fc30.noarch
  Verifying        : scantailor-0.9.11.1-24.fc30.x86_64
  Verifying        : scantailor-0.9.11.1-24.fc30.x86_64

Reinstalled:
  ...

Complete!


Expected results:

(see description of problem)


Additional info:

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1644642

Comment 1 Panu Matilainen 2019-06-28 10:54:44 UTC
Looks like a dupe of bug 1720234

Comment 2 Panu Matilainen 2019-06-28 11:12:40 UTC
At any rate, this is a cosmetical issue.

Comment 3 secondary 2019-06-28 12:49:52 UTC
Eh not really as it is preventing legitimate bugs from being diagnosed. My link (bug 1644642) and now your link (bug 1720234). Also (total conjecture) its easy to imagine this being some sort of pointer mismanagement.

Comment 4 amatej 2019-08-30 13:51:02 UTC
There is indeed a number of problems here.

Going through your original list:
1. This is a problem in DNF, I will fix this.
2. This warning line is from rpm, so it has to be fixed there.
3. Here DNF is at fault again. Although rpm gives as the "key" argument to the callback just the name of the package (I think its this: https://github.com/rpm-software-management/rpm/blob/master/python/rpmts-py.c#L530). It may be more useful to get the full NEVRA, so we don't have to search for the package after that, but I don't know whether this would break anything else.
4. Here we could also use help from rpm since it passes the value for the rpmtag in the "amount" parameter of the callback, however names for these trigger rpmtags are marked as internal (such as RPMTAG_TRANSFILETRIGGERIN in this example) and don't seem to be accessible from python rpm api. The second part of the message is wrong in DNF once again.

While writing tests for this I also discovered that when scriptlet defined with FILETRIGGERIN runs rpm passes to dnf name of the package that triggered this not the name of the package whose the FILETRIGGERIN scriplet is. I have also tested with triggerin and transfiletriggerpostun which seem to be fine, don't know about the others.

At the same time I think that for all the [TRANS]FILETRIGGER* scriptlets wrong value for "amount" gets passed. For example instead of value for RPMTAG_TRANSFILETRIGGERPOSTUN we get RPMTAG_TRIGGERPOSTUN.
(values from https://github.com/rpm-software-management/rpm/blob/8390fa8515f499994646cf3bd113423744dc7bd9/lib/rpmtag.h#L174)

Panu can you help with this?

I created PR for the DNF part: https://github.com/rpm-software-management/dnf/pull/1471
And some tests: https://github.com/rpm-software-management/ci-dnf-stack/pull/616

Comment 5 Panu Matilainen 2019-10-10 08:44:06 UTC
(In reply to amatej from comment #4)
> 3. Here DNF is at fault again. Although rpm gives as the "key" argument to
> the callback just the name of the package (I think its this:
> https://github.com/rpm-software-management/rpm/blob/master/python/rpmts-py.
> c#L530). It may be more useful to get the full NEVRA, so we don't have to
> search for the package after that, but I don't know whether this would break
> anything else.

This is an ancient, unfortunate misdesign of the python callback, and hard to change because yes it would break all python clients. You'd find life much saner if the callback handling was pushed to libdnf side.

> 4. Here we could also use help from rpm since it passes the value for the
> rpmtag in the "amount" parameter of the callback, however names for these
> trigger rpmtags are marked as internal (such as RPMTAG_TRANSFILETRIGGERIN in
> this example) and don't seem to be accessible from python rpm api. The
> second part of the message is wrong in DNF once again.

Yup, another old problem. The thing is, those tags need to be kept internal as that's exactly what they are, they only exist in the rpmbuild internals. One possibility could be defining an alternate set of symbols for the values used in script amount, and export those.

> While writing tests for this I also discovered that when scriptlet defined
> with FILETRIGGERIN runs rpm passes to dnf name of the package that triggered
> this not the name of the package whose the FILETRIGGERIN scriplet is. I have
> also tested with triggerin and transfiletriggerpostun which seem to be fine,
> don't know about the others.

I've looked at the code once or twice and couldn't see how this might be the case, but that doesn't mean it can't.
If you have a reproducer case for this, please file a separate bug on rpm with that reproducer.

> At the same time I think that for all the [TRANS]FILETRIGGER* scriptlets
> wrong value for "amount" gets passed. For example instead of value for
> RPMTAG_TRANSFILETRIGGERPOSTUN we get RPMTAG_TRIGGERPOSTUN.
> (values from
> https://github.com/rpm-software-management/rpm/blob/
> 8390fa8515f499994646cf3bd113423744dc7bd9/lib/rpmtag.h#L174)

This affects rpm's own debug logging too, and unfortunately not an easy fix due to the way file triggers are implemented. It'd be nice to get it fixed some day though.

Comment 6 Panu Matilainen 2019-10-10 09:36:27 UTC
> I've looked at the code once or twice and couldn't see how this might be the case, but that doesn't mean it can't.
> If you have a reproducer case for this, please file a separate bug on rpm with that reproducer.

Never mind, I found a reproducer in our own test-suite, it's just that rpm itself doesn't emit output for scriptlets so this has gone invisible all along. I'll have a look, this was supposed to be fixed already.

Comment 7 Panu Matilainen 2019-10-10 09:54:43 UTC
> I've looked at the code once or twice and couldn't see how this might be the case, but that doesn't mean it can't.

QED: https://github.com/rpm-software-management/rpm/pull/892

Comment 8 amatej 2019-10-17 07:30:00 UTC
*** Bug 1720234 has been marked as a duplicate of this bug. ***

Comment 9 amatej 2019-10-17 07:51:07 UTC
Ok, thank you. So we have decided to do an incomplete fix in the scope of DNF4. Also it seems the rpm problems are already known and I will leave them out from now on. (Alternate set of symbols for the internal tags would be nice in the future, maybe discuss with dmach.)

Final summary for DNF : 

Wrong message for running scriptlet (Running scriptlet: gpxsee-7.9-1.fc30.x86_64)
- wrong package -> this will be partially fixed now, only a name of the package will be shown because of the python API, DNF5 should do better because it will use the C rpm API using libdnf.

Wrong message to stderr for error in scriptlet (Error in <unknown> scriptlet in rpm package gpxsee)
- wrong format of the message, when some package triggered scriptlet of some other package -> will be fixed now.
- wrong scriptlet type (or unknown) -> part of the rpm problems
- wrong package names -> this should be fixed now.

The tests I created describe this behavior and should ensure we eventually get there because some of them will be marked as failing now.

Comment 10 Kevin Fenzi 2019-11-09 20:58:01 UTC
So, rawhide composes have been failing since this landed (failing to make live media). 

I see the following traceback: 

07:57:50,228 INF packaging: Configuring (running scriptlet for): samba-client-2:4.11.2-1.fc32.x86_6
4 1573035436 934aceaaccdc5254613f8dfa10682cab8f79f6252e735d52cc1e5aa3cd92273d
07:57:50,268 CRT dnf: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/dnf/yum/rpmtrans.py", line 291, in callback
    self._script_start(key)
  File "/usr/lib/python3.8/site-packages/dnf/yum/rpmtrans.py", line 439, in _script_start
    display.progress(pkg_or_key, action, 100, 100, complete, total)
  File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/dnfpayload.py", line 205, in progress
    nevra = "%s-%s.%s" % (package.name, package.evr, package.arch)
AttributeError: 'str' object has no attribute 'name'

07:57:50,287 INF packaging: Installed: audit-3.0-0.15.20191104git1c2f876.fc32.x86_64 1572899312 3c4
fa72b45db7e538d7fe4aa4049f2aef0c38e29169684351b8826002f388fe2

the install goes on a bit more then exits. 

Here's a kde live from last night (but they are all failing the same way): 

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

I'm not 100% sure dnf is to blame here, but to test that theory I did: 'koji untag-pkg f32 librepo-1.11.0-1.fc32  libdnf-0.37.2-1.fc32 dnf-4.2.15-1.fc32 dnf-plugins-extras-4.0.8-1.fc32 dnf-plugins-core-4.0.11-1.fc32' and am going to run another compose. If it works, we know, if not, I can tag them all back. If there is a fix in just one package let me know and I can tag the rest in for you to build against.

Comment 11 amatej 2019-11-11 08:22:51 UTC
I am pretty sure DNF is to blame here. I changed the input to the progress function to sometimes be only a string (because we only know the name of the package) but Anaconda seems to rely on the fact that it is a package object.

Comment 12 amatej 2019-11-11 14:07:43 UTC
We will revert the patch to fix the situation.

We have also decided that the best way to proceed with this bug is to keep the behavior broken for now and delay its fix to DNF5 where we will move from the Python rpm API to the C API.

Comment 13 Ben Cotton 2020-04-30 20:25:09 UTC
This message is a reminder that Fedora 30 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 30 on 2020-05-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '30'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 30 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 14 Ben Cotton 2020-08-11 15:26:26 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 33 development cycle.
Changing version to 33.

Comment 15 Tao Feng 2021-03-29 13:39:48 UTC
Any news about this?

Comment 16 amatej 2021-03-29 14:19:38 UTC
(In reply to Tao Feng from comment #15)
> Any news about this?

We are working on DNF5 in the dnf-5-devel branch of libdnf: https://github.com/rpm-software-management/libdnf/tree/dnf-5-devel which will have the DNF part of problems fixed.

It is a major rewrite though so it's going to take more time.

Comment 17 Ben Cotton 2021-11-04 14:49:40 UTC
This message is a reminder that Fedora 33 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 33 on 2021-11-30.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '33'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 33 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 18 Ben Cotton 2021-11-04 15:48:02 UTC
This message is a reminder that Fedora 33 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 33 on 2021-11-30.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '33'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 33 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 19 Ben Cotton 2021-11-30 18:22:30 UTC
Fedora 33 changed to end-of-life (EOL) status on 2021-11-30. Fedora 33 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 20 Ben Cotton 2022-02-08 21:24:01 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 36 development cycle.
Changing version to 36.

Comment 21 amatej 2022-08-29 13:50:25 UTC
*** Bug 2120346 has been marked as a duplicate of this bug. ***

Comment 22 Ben Cotton 2023-04-25 16:39:02 UTC
This message is a reminder that Fedora Linux 36 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 36 on 2023-05-16.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '36'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 36 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 23 Fedora Release Engineering 2023-08-16 08:08:21 UTC
This bug appears to have been reported against 'rawhide' during the Fedora Linux 39 development cycle.
Changing version to 39.


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