Bug 1672947 - dnf prints tracebacks RuntimeError: TransactionItem not found for key
Summary: dnf prints tracebacks RuntimeError: TransactionItem not found for key
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dnf
Version: rawhide
Hardware: Unspecified
OS: Unspecified
medium
low
Target Milestone: ---
Assignee: rpm-software-management
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1680160 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-02-06 10:02 UTC by Brendan Shephard
Modified: 2019-04-29 02:15 UTC (History)
12 users (show)

Fixed In Version: dnf-4.2.5-1.fc29
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-04-29 02:15:09 UTC
Type: Bug


Attachments (Terms of Use)
dnf history sqlite (3.34 MB, application/x-sqlite3)
2019-02-15 04:32 UTC, Brendan Shephard
no flags Details
Installed RPM's ( rpm -qa ) (92.22 KB, text/plain)
2019-02-15 04:33 UTC, Brendan Shephard
no flags Details
enabled repos (4.40 KB, text/plain)
2019-02-15 04:34 UTC, Brendan Shephard
no flags Details
dnf.log (16.47 MB, text/plain)
2019-02-15 04:55 UTC, Brendan Shephard
no flags Details

Description Brendan Shephard 2019-02-06 10:02:39 UTC
Description of problem:
Tracebacks are printed to the users console for the Runtime error:
RuntimeError: TransactionItem not found for key

This would be better logged and not spewed onto stdout.

Version-Release number of selected component (if applicable):
dnf-4.0.10-1.fc30.noarch

How reproducible:
If package is missing an attribute.

Steps to Reproduce:
1. dnf upgrade -y
2.
3.

Actual results:
Everything installs, but the console is flooded with tracebacks (seen below)

Expected results:
dnf would report the error and log the traceback

Additional info:
2019-02-06T07:59:22Z CRITICAL Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 272, in callback
    self._uninst_progress(amount, total, key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 356, in _uninst_progress
    transaction_list = self._extract_cbkey(key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 244, in _extract_cbkey
    raise RuntimeError("TransactionItem not found for key: %s" % cbkey)
RuntimeError: TransactionItem not found for key: libcap

2019-02-06T07:59:22Z CRITICAL Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 272, in callback
    self._uninst_progress(amount, total, key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 356, in _uninst_progress
    transaction_list = self._extract_cbkey(key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 244, in _extract_cbkey
    raise RuntimeError("TransactionItem not found for key: %s" % cbkey)
RuntimeError: TransactionItem not found for key: libcap

2019-02-06T07:59:22Z CRITICAL Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 272, in callback
    self._uninst_progress(amount, total, key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 356, in _uninst_progress
    transaction_list = self._extract_cbkey(key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 244, in _extract_cbkey
    raise RuntimeError("TransactionItem not found for key: %s" % cbkey)
RuntimeError: TransactionItem not found for key: libcap

2019-02-06T07:59:22Z CRITICAL Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 270, in callback
    self._unInstStop(key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 363, in _unInstStop
    transaction_list = self._extract_cbkey(key)
  File "/usr/lib/python3.7/site-packages/dnf/yum/rpmtrans.py", line 244, in _extract_cbkey
    raise RuntimeError("TransactionItem not found for key: %s" % cbkey)
RuntimeError: TransactionItem not found for key: libcap



I grabbed these from the log file because I did the update in multi-user mode and couldn't copy paste from my console. But it's the same tracebacks that I was seeing dnf filling my screen with.

Comment 1 Brendan Shephard 2019-02-06 10:04:13 UTC
I understand why we're raising the Runtime error. But can we maybe just do something like this instead?

    def _extract_cbkey(self, cbkey):
        """Obtain the package related to the calling callback."""

        try:
            if hasattr(cbkey, "pkg"):
                tsi = cbkey
                return [tsi]

            te = self._te_list[self._te_index]
            te_nevra = dnf.util._te_nevra(te)
            if self._tsi_cache:
                if str(self._tsi_cache[0]) == te_nevra:
                    return self._tsi_cache
            items = []
            for tsi in self.base.transaction:
                if tsi.action == libdnf.transaction.TransactionItemAction_REINSTALL:
                    # skip REINSTALL in order to return REINSTALLED
                    continue
                if str(tsi) == te_nevra:
                    items.append(tsi)
            if items:
                self._tsi_cache = items
                return items
            raise RuntimeError("TransactionItem not found for key: %s" % cbkey)
        except RuntimeError as err:
            logger.error(err)

Comment 2 Daniel Mach 2019-02-11 11:57:32 UTC
Brendan,
could you provide more information for reproducing the issue?
* /var/lib/dnf/history.sqlite
* list if installed RPMs: rpm -qa
* list of enabled repos: LC_ALL=C dnf repolist --enabled -v | egrep '^Repo-|^$'

Eventually if you could create a Dockerfile with a minimal reproducer in docker/podman.

Comment 3 Brendan Shephard 2019-02-15 04:32:47 UTC
Created attachment 1535031 [details]
dnf history sqlite

There is an updated version of the traceback in the last dnf transaction - I will provide the dnf.log separately, but it did it during the last transaction which is:
 132 | upgrade -y               | 2019-02-15 14:16 | E, I, U        |  242 EE

Comment 4 Brendan Shephard 2019-02-15 04:33:22 UTC
Created attachment 1535032 [details]
Installed RPM's ( rpm -qa )

Comment 5 Brendan Shephard 2019-02-15 04:34:44 UTC
Created attachment 1535033 [details]
enabled repos

Comment 6 Brendan Shephard 2019-02-15 04:36:02 UTC
Working on a podman reproducer. Still not sure what's causing it, I just noticed it again today and thought it was a good time to grab the fresh info. 

I'll keep working on reproducing it in a container.

Comment 7 Brendan Shephard 2019-02-15 04:55:29 UTC
Created attachment 1535034 [details]
dnf.log

Comment 8 Ludovic Hirlimann [:Paul-muadib] 2019-02-23 11:45:07 UTC
*** Bug 1680160 has been marked as a duplicate of this bug. ***

Comment 9 Brendan Shephard 2019-02-23 11:49:08 UTC
We have an instance of this issue being reported again Fedora 29: https://bugzilla.redhat.com/show_bug.cgi?id=1680160


From what I can see, we're looking at this function:
https://github.com/rpm-software-management/dnf/blob/master/dnf/yum/rpmtrans.py#L222-L244

90% of the time, it appears to exit during the first if statement. But in the events where it makes it past, it seems to have nothing to push to the items list:

        items = []
        for tsi in self.base.transaction:
            if tsi.action == libdnf.transaction.TransactionItemAction_REINSTALL:   
                # skip REINSTALL in order to return REINSTALLED
                continue
            if str(tsi) == te_nevra:
                items.append(tsi)  <<< ---- Seems like nothing happens here so items is still null.
        if items:                 
            self._tsi_cache = items
            return items
        raise RuntimeError("TransactionItem not found for key: %s" % cbkey)

So it must be this part that is failing:

        te = self._te_list[self._te_index]
        te_nevra = dnf.util._te_nevra(te)


We can try: except: it to remove the traceback from stdout and send it to logger instead. On my original BZ, I suggested a pretty broad try, except, but we could be more specific and just wrap it around the final if statement which should improve user experience.

Ultimately, this error doesn't seem to be fatal. But it would be nice to understand what is failing. I haven't started digging into _te_nevra() yet so that's all I have at the moment.

Comment 10 Daniel Mach 2019-03-08 15:22:12 UTC
I had no luck reproducing the issue.

From my previous experience, it's almost impossible to fix such issues without the reproducer.
The code is mix of old YUM's code with new transaction/history code patched into it.
We're planning to do couple rewrites to make it saner and make sure we have tests for the important parts.

Comment 11 Brendan Shephard 2019-03-08 22:18:33 UTC
(In reply to Daniel Mach from comment #10)
> I had no luck reproducing the issue.
> 
> From my previous experience, it's almost impossible to fix such issues
> without the reproducer.
> The code is mix of old YUM's code with new transaction/history code patched
> into it.
> We're planning to do couple rewrites to make it saner and make sure we have
> tests for the important parts.

Yeah, I haven't been able to get a consistent reproducer. I saw it happen a couple more times, which seemed to be if I left my laptop for a week or more and then did dnf upgrade. Which I assumed was the difference in package versions. But when I pull the exact same versions of those package into a podman container and run the update I wasn't seeing it.

It seems fairly cosmetic to be honest. I haven't experienced any failures or issues as a result of the traceback. Unless there is some other information we think would be useful here, I think we can close this one with insufficient data.

Comment 12 Daniel Mach 2019-03-12 13:11:05 UTC
I found a reproducer that may (or may not) be related to this bug.
It was related to how dnf computes obsoletes when upgrading multilib packages:
https://github.com/rpm-software-management/dnf/pull/1354

If the problem strikes back after this PR is released,
I'm hoping in getting a better reproducer and I'll look into it again.

Comment 13 Fedora Update System 2019-04-25 16:43:31 UTC
dnf-4.2.5-1.fc29 libdnf-0.31.0-2.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2019-2612a121ba

Comment 14 Fedora Update System 2019-04-26 22:10:09 UTC
dnf-4.2.5-1.fc29, libdnf-0.31.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-2019-2612a121ba

Comment 15 Fedora Update System 2019-04-29 02:15:09 UTC
dnf-4.2.5-1.fc29, libdnf-0.31.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.