Bug 1624652

Created attachment 1480393 [details]
File: backtrace

Created attachment 1480394 [details]
File: cgroup

Created attachment 1480395 [details]
File: cpuinfo

Created attachment 1480396 [details]
File: environ

Created attachment 1480397 [details]
File: mountinfo

Created attachment 1480398 [details]
File: namespaces

Created attachment 1480399 [details]
File: open_fds

Similar problem has been detected:

Update with dnfdragora

reporter:       libreport-2.9.5
cmdline:        /usr/bin/python3 /usr/bin/dnfdragora-updater
crash_function: on_RPMProgress
exception_type: KeyError
executable:     /usr/bin/dnfdragora-updater
interpreter:    python3-3.7.0-9.fc29.armv7hl
kernel:         4.18.5-300.fc29.armv7hl
package:        dnfdragora-updater-1.0.1-12.git20180108.b0e8a66.fc29
reason:         dnf_backend.py:223:on_RPMProgress:KeyError: 7
runlevel:       N 5
type:           Python3
uid:            1000

Similar problem has been detected:

Don't know yet.

reporter:       libreport-2.9.5
cmdline:        /usr/bin/python3 /usr/bin/dnfdragora-updater
crash_function: on_RPMProgress
exception_type: KeyError
executable:     /usr/bin/dnfdragora-updater
interpreter:    python3-3.7.0-9.fc29.x86_64
kernel:         4.18.5-300.fc29.x86_64
package:        dnfdragora-updater-1.0.1-12.git20180108.b0e8a66.fc29
reason:         dnf_backend.py:223:on_RPMProgress:KeyError: 7
runlevel:       N 5
type:           Python3
uid:            1000

The code here is expecting the 'action' passed in by the dbus signal handler to be a word like 'update' or 'install' or 'erase', but it's actually just the number 7 (probably an enumerator getting passed up from somewhere)...

It seems the values of some constants changed, and some more were added. Here's a simple test script:

#!/usr/bin/python3

import dnf.callback
actions = {
    dnf.callback.PKG_CLEANUP: 'cleanup',
    dnf.callback.PKG_DOWNGRADE: 'downgrade',
    dnf.callback.PKG_REMOVE: 'erase',
    dnf.callback.PKG_INSTALL: 'install',
    dnf.callback.PKG_OBSOLETE: 'obsolete',
    dnf.callback.PKG_REINSTALL: 'reinstall',
    dnf.callback.PKG_UPGRADE: 'update',
    dnf.callback.PKG_VERIFY: 'verify',
    dnf.callback.PKG_SCRIPTLET: 'scriptlet',
    dnf.callback.TRANS_PREPARATION: 'preptrans',
    dnf.callback.TRANS_POST: 'posttrans'
}
print(actions)

On Fedora 28 (DNF 2), that prints this:

{1: 'cleanup', 2: 'downgrade', 3: 'erase', 4: 'install', 5: 'obsolete', 6: 'reinstall', 7: 'update', 8: 'verify', 10: 'scriptlet', 9: 'preptrans', 11: 'posttrans'}

On Fedora 29 with DNF 3.5.1 and libdnf 0.19.1, it prints this:

{101: 'cleanup', 2: 'downgrade', 8: 'erase', 1: 'install', 4: 'obsolete', 9: 'reinstall', 6: 'update', 102: 'verify', 103: 'scriptlet', 201: 'preptrans', 202: 'posttrans'}

The commit that changed things seems to be this one in dnf:

https://github.com/rpm-software-management/dnf/commit/8198019c0

prior to that, the constants in dnf.callback were pulled in from dnf.yum.rpmtrans.TransactionDisplay , which was part of dnf/yum/rpmtrans.py , and the values were actually set there (as 1 thru 11). After that commit, dnf.callback gets them from dnf.transaction. dnf.transaction defines a few itself, as the three-digit values:

# per-package actions - additional
PKG_CLEANUP = 101
PKG_VERIFY = 102
PKG_SCRIPTLET = 103

# transaction-wide actions
TRANS_PREPARATION = 201
TRANS_POST = 202

and pulls the others from libdnf:

PKG_DOWNGRADE = libdnf.transaction.TransactionItemAction_DOWNGRADE
PKG_DOWNGRADED = libdnf.transaction.TransactionItemAction_DOWNGRADED
PKG_INSTALL = libdnf.transaction.TransactionItemAction_INSTALL
PKG_OBSOLETE = libdnf.transaction.TransactionItemAction_OBSOLETE
PKG_OBSOLETED = libdnf.transaction.TransactionItemAction_OBSOLETED
PKG_REINSTALL = libdnf.transaction.TransactionItemAction_REINSTALL
PKG_REINSTALLED = libdnf.transaction.TransactionItemActionREINSTALLED
PKG_REMOVE = libdnf.transaction.TransactionItemAction_REMOVE
PKG_UPGRADE = libdnf.transaction.TransactionItemAction_UPGRADE
PKG_UPGRADED = libdnf.transaction.TransactionItemAction_UPGRADED

which enumerates them here:

https://github.com/rpm-software-management/libdnf/blob/master/libdnf/transaction/Types.hpp#L45-L57

with rather different values to the ones previously used in dnf.yum.rpmtrans.TransactionDisplay :

enum class TransactionItemAction : int {
    INSTALL = 1,       // a new package that was installed on the system
    DOWNGRADE = 2,     // an older package version that replaced previously installed version
    DOWNGRADED = 3,    // an original package version that was replaced
    OBSOLETE = 4,      //
    OBSOLETED = 5,     //
    UPGRADE = 6,       //
    UPGRADED = 7,      //
    REMOVE = 8,        // a package that was removed from the system
    REINSTALL = 9,     // a package that was reinstalled with the identical version
    REINSTALLED = 10,  // a package that was reinstalled with the identical version (old repo, for example)
    REASON_CHANGE = 11 // a package was kept on the system but it's reason has changed
};

That 'test script' was based on the TransactionProgress.__init__ method in dnfdaemon/server/__init__.py ... now I look more closely, it looks like that simply needs updating, as it just doesn't *cover* all the constants that now exist and which might wind up going into that function somehow (I'm not sure how it actually gets called). 7 is UPGRADED in the new dnf/libdnf, and that's just not in the dict at all. That means it doesn't get translated to a string when the progress() method does this (where self.actions is the dict in question):

            if action in self.actions:
                action = self.actions[action]
            self.base.RPMProgress(
                pkg_id, action, te_current, te_total, ts_current, ts_total)

so that self.base.RPMProgress() call just gets the bare '7' as the action arg.  When dndragora *receives* the message that sends out, it falls over on it, because it assumes it will be able to look up action in its 'const.RPM_ACTIONS' dict...where '7' is not a key.

I'll work up a patch for this...

Hmm...there may in fact be a dnf/libdnf bug lurking here. UPGRADED isn't included in the callback constants, so why is something callback-y getting UPGRADED as the action? That smells fishy.

Reported https://bugzilla.redhat.com/show_bug.cgi?id=1630113 for what I think is bad behaviour by dnf here. I'm working on a patch for dnfdragora / dnfdaemon to handle it.

https://github.com/manatools/dnfdaemon/pull/25
https://github.com/manatools/dnfdragora/pull/116

Proposing as a Beta FE issue. I think the dnf transaction actually completes OK when this happens, but the crash happens and is caught by abrt on nearly every dnfdragora operation (on very simple ones, it seems the additional callback actions sometimes don't show up, so the crash doesn't happen). Obviously it'd be good to fix that for Beta.

dnfdaemon-0.3.19-4.fc29 dnfdragora-1.0.1-13.git20180108.b0e8a66.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-d3ef63b0f6

dnfdaemon-0.3.19-4.fc29, dnfdragora-1.0.1-13.git20180108.b0e8a66.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-d3ef63b0f6

With the latest releases of dnddragora and dnfdaemon, I could see no problem with running dnfdragora or updating packages with it. 
Also, no abrt messages were reported during dnfdragora operations.
I am setting this bug to verified.

dnfdaemon-0.3.19-4.fc29, dnfdragora-1.0.1-13.git20180108.b0e8a66.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.