Bug 1624652 - [abrt] dnfdragora-updater: on_RPMProgress(): dnf_backend.py:223:on_RPMProgress:KeyError: 7
Summary: [abrt] dnfdragora-updater: on_RPMProgress(): dnf_backend.py:223:on_RPMProgres...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dnfdragora
Version: 29
Hardware: x86_64
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Björn 'besser82' Esser
QA Contact: Fedora Extras Quality Assurance
URL: https://retrace.fedoraproject.org/faf...
Whiteboard: abrt_hash:38702da474f40011901bf16cb0a...
Depends On:
Blocks: F29BetaFreezeException
TreeView+ depends on / blocked
 
Reported: 2018-09-02 21:33 UTC by Paul DeStefano
Modified: 2018-09-20 22:36 UTC (History)
7 users (show)

Fixed In Version: dnfdragora-1.0.1-13.git20180108.b0e8a66.fc29
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-09-20 22:36:00 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
File: backtrace (999 bytes, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: cgroup (331 bytes, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: cpuinfo (816 bytes, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: environ (1.33 KB, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: mountinfo (3.23 KB, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: namespaces (129 bytes, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details
File: open_fds (996 bytes, text/plain)
2018-09-02 21:33 UTC, Paul DeStefano
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1630113 0 unspecified CLOSED Transaction callbacks use action constants that aren't part of the callback API 2021-02-22 00:41:40 UTC

Internal Links: 1630113

Description Paul DeStefano 2018-09-02 21:33:04 UTC
Version-Release number of selected component:
dnfdragora-updater-1.0.1-12.git20180108.b0e8a66.fc29

Additional info:
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
runlevel:       N 5
type:           Python3
uid:            1000

Truncated backtrace:
dnf_backend.py:223:on_RPMProgress:KeyError: 7

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnfdaemon/client/__init__.py", line 187, in __call__
    return getattr(self.proxy, self.method)(*args)
  File "/usr/lib/python3.7/site-packages/dnfdaemon/client/__init__.py", line 228, in _on_g_signal
    self.handle_dbus_signals(proxy, sender, signal, args)
  File "/usr/lib/python3.7/site-packages/dnfdaemon/client/__init__.py", line 556, in handle_dbus_signals
    self.on_RPMProgress(*args)
  File "/usr/lib/python3.7/site-packages/dnfdragora/dnf_backend.py", line 223, in on_RPMProgress
    self.frontend.infobar.info_sub(const.RPM_ACTIONS[action] % name)
KeyError: 7

Local variables in innermost frame:
self: <dnfdragora.dnf_backend.DnfRootBackend object at 0x7fda65f7f320>
package: 'texlive-xetex,7,20180414,19.fc29,x86_64,@System'
action: 7
te_current: 0
te_total: 28
ts_current: 119
ts_total: 232
num: ' ( 119/232 )'
name: 'texlive-xetex-7:20180414-19.fc29.x86_64'

Comment 1 Paul DeStefano 2018-09-02 21:33:09 UTC
Created attachment 1480393 [details]
File: backtrace

Comment 2 Paul DeStefano 2018-09-02 21:33:10 UTC
Created attachment 1480394 [details]
File: cgroup

Comment 3 Paul DeStefano 2018-09-02 21:33:11 UTC
Created attachment 1480395 [details]
File: cpuinfo

Comment 4 Paul DeStefano 2018-09-02 21:33:12 UTC
Created attachment 1480396 [details]
File: environ

Comment 5 Paul DeStefano 2018-09-02 21:33:13 UTC
Created attachment 1480397 [details]
File: mountinfo

Comment 6 Paul DeStefano 2018-09-02 21:33:14 UTC
Created attachment 1480398 [details]
File: namespaces

Comment 7 Paul DeStefano 2018-09-02 21:33:15 UTC
Created attachment 1480399 [details]
File: open_fds

Comment 8 Paul Whalen 2018-09-13 01:33:17 UTC
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

Comment 9 Adam Williamson 2018-09-18 01:09:56 UTC
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

Comment 10 Adam Williamson 2018-09-18 01:16:04 UTC
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)...

Comment 11 Adam Williamson 2018-09-18 01:49:30 UTC
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...

Comment 12 Adam Williamson 2018-09-18 01:59:40 UTC
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.

Comment 13 Adam Williamson 2018-09-18 02:20:47 UTC
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.

Comment 15 Adam Williamson 2018-09-18 03:43:09 UTC
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.

Comment 16 Fedora Update System 2018-09-18 03:48:23 UTC
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

Comment 17 Fedora Update System 2018-09-18 06:17:50 UTC
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

Comment 18 Lukas Ruzicka 2018-09-20 14:00:48 UTC
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.

Comment 19 Fedora Update System 2018-09-20 22:36:00 UTC
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.


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