From f6ffdce83004acdb2325d966ad348dfe63fb55f8 Mon Sep 17 00:00:00 2001

From: Jaroslav Mracek <jmracek@redhat.com>

Date: Mon, 3 Jun 2019 19:26:55 +0200

Subject: [PATCH 1/5] [transaction] Set an error for first tsi in unknown state

 (RhBug:1737328)

It should prevent "TransactionItem state is not set" in case of multiple

same NEVRASs and single with an error.

https://bugzilla.redhat.com/show_bug.cgi?id=1737328

---

 dnf/yum/rpmtrans.py | 4 ++++

 1 file changed, 4 insertions(+)

diff --git a/dnf/yum/rpmtrans.py b/dnf/yum/rpmtrans.py

index 6a60b5a08..50d8b81cb 100644

--- a/dnf/yum/rpmtrans.py

+++ b/dnf/yum/rpmtrans.py

@@ -386,6 +386,10 @@ class RPMTransaction(object):

         msg = "Error unpacking rpm package %s" % tsi.pkg

         for display in self.displays:

             display.error(msg)

+        for tsi1 in transaction_list:

+            if tsi1.state == libdnf.transaction.TransactionItemState_UNKNOWN:

+                tsi1.state = libdnf.transaction.TransactionItemState_ERROR

+                return

         tsi.state = libdnf.transaction.TransactionItemState_ERROR

     def _scriptError(self, amount, total, key):

-- 

2.21.0

From c07beb11b8f085a4ced74502c70d48b4db4e4099 Mon Sep 17 00:00:00 2001

From: Daniel Mach <dmach@redhat.com>

Date: Wed, 5 Jun 2019 08:29:03 +0200

Subject: [PATCH 2/5] [history] Don't store failed transactions as succeeded.

 (RhBug:1737328)

---

 dnf/base.py       |  7 ++++---

 dnf/db/history.py | 16 ++++++++++------

 2 files changed, 14 insertions(+), 9 deletions(-)

diff --git a/dnf/base.py b/dnf/base.py

index 7a388ecf4..add64036b 100644

--- a/dnf/base.py

+++ b/dnf/base.py

@@ -987,7 +987,7 @@ class Base(object):

             # particular element failed and if not, decide that is the

             # case.

             failed = [el for el in self._ts if el.Failed()]

-            if len(failed) > 0:

+            if failed:

                 for te in failed:

                     te_nevra = dnf.util._te_nevra(te)

                     for tsi in self._transaction:

@@ -996,6 +996,7 @@ class Base(object):

                 errstring = _('Errors occurred during transaction.')

                 logger.debug(errstring)

+                self.history.end(rpmdbv)

             else:

                 login = dnf.util.get_effective_login()

                 msg = _("Failed to obtain the transaction lock "

@@ -1006,7 +1007,7 @@ class Base(object):

         else:

             if self._record_history():

                 herrors = [ucd(x) for x in errors]

-                self.history.end(rpmdbv, 2, errors=herrors)

+                self.history.end(rpmdbv)

             logger.critical(_("Transaction couldn't start:"))

             for e in errors:

@@ -1069,7 +1070,7 @@ class Base(object):

             count = display_banner(tsi.pkg, count)

         rpmdbv = rpmdb_sack._rpmdb_version()

-        self.history.end(rpmdbv, 0)

+        self.history.end(rpmdbv)

         timer()

         self._trans_success = True

diff --git a/dnf/db/history.py b/dnf/db/history.py

index dc9c53b70..7f22f97c1 100644

--- a/dnf/db/history.py

+++ b/dnf/db/history.py

@@ -486,14 +486,18 @@ class SwdbInterface(object):

             self.swdb.log_error(self._tid, error)

     '''

-    # TODO: rename to end_transaction?

-    def end(self, end_rpmdb_version="", return_code=0, errors=None):

-        assert return_code or not errors

-        # TODO: fix return_code

-        return_code = not bool(return_code)

+    def end(self, end_rpmdb_version="", return_code=None, errors=None):

         if not hasattr(self, '_tid'):

             return  # Failed at beg() time

+        if return_code is None:

+            # return_code/state auto-detection

+            return_code = libdnf.transaction.TransactionState_DONE

+            for tsi in self.rpm:

+                if tsi.state == libdnf.transaction.TransactionItemState_ERROR:

+                    return_code = libdnf.transaction.TransactionState_ERROR

+                    break

+

         for file_descriptor, line in self._output:

             self.swdb.addConsoleOutputLine(file_descriptor, line)

         self._output = []

@@ -501,7 +505,7 @@ class SwdbInterface(object):

         self.swdb.endTransaction(

             int(time.time()),

             str(end_rpmdb_version),

-            bool(return_code)

+            return_code,

         )

         # Closing and cleanup is done in the close() method.

-- 

2.21.0

From 5302f0fbf977e6447b5a00adabb34b1c01fe7e55 Mon Sep 17 00:00:00 2001

From: Daniel Mach <dmach@redhat.com>

Date: Wed, 5 Jun 2019 21:10:05 +0200

Subject: [PATCH 3/5] [transaction] Add RPMCALLBACK_INST_{START,STOP} callback

 handlers. (RhBug:1737328)

---

 dnf/yum/rpmtrans.py | 23 ++++++++++++++++++-----

 1 file changed, 18 insertions(+), 5 deletions(-)

diff --git a/dnf/yum/rpmtrans.py b/dnf/yum/rpmtrans.py

index 50d8b81cb..0834a8c82 100644

--- a/dnf/yum/rpmtrans.py

+++ b/dnf/yum/rpmtrans.py

@@ -262,6 +262,10 @@ class RPMTransaction(object):

                 return self._instOpenFile(key)

             elif what == rpm.RPMCALLBACK_INST_CLOSE_FILE:

                 self._instCloseFile(key)

+            elif what == rpm.RPMCALLBACK_INST_START:

+                self._inst_start(key)

+            elif what == rpm.RPMCALLBACK_INST_STOP:

+                self._inst_stop(key)

             elif what == rpm.RPMCALLBACK_INST_PROGRESS:

                 self._instProgress(amount, total, key)

             elif what == rpm.RPMCALLBACK_UNINST_START:

@@ -321,12 +325,17 @@ class RPMTransaction(object):

             return self.fd.fileno()

     def _instCloseFile(self, key):

-        transaction_list = self._extract_cbkey(key)

         self.fd.close()

         self.fd = None

+    def _inst_start(self, key):

+        pass

+

+    def _inst_stop(self, key):

         if self.test or not self.trans_running:

             return

+

+        transaction_list = self._extract_cbkey(key)

         for tsi in transaction_list:

             if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

                 tsi.state = libdnf.transaction.TransactionItemState_DONE

@@ -376,6 +385,10 @@ class RPMTransaction(object):

     def _cpioError(self, key):

         transaction_list = self._extract_cbkey(key)

+        for tsi in transaction_list:

+            if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

+                tsi.state = libdnf.transaction.TransactionItemState_ERROR

+                break

         msg = "Error in cpio payload of rpm package %s" % transaction_list[0].pkg

         for display in self.displays:

             display.error(msg)

@@ -386,11 +399,11 @@ class RPMTransaction(object):

         msg = "Error unpacking rpm package %s" % tsi.pkg

         for display in self.displays:

             display.error(msg)

-        for tsi1 in transaction_list:

-            if tsi1.state == libdnf.transaction.TransactionItemState_UNKNOWN:

-                tsi1.state = libdnf.transaction.TransactionItemState_ERROR

+

+        for tsi in transaction_list:

+           if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

+                tsi.state = libdnf.transaction.TransactionItemState_ERROR

                 return

-        tsi.state = libdnf.transaction.TransactionItemState_ERROR

     def _scriptError(self, amount, total, key):

         # "amount" carries the failed scriptlet tag,

-- 

2.21.0

From a3cc8343ff418cca386a0a11f331ebe08e70bae6 Mon Sep 17 00:00:00 2001

From: Jaroslav Mracek <jmracek@redhat.com>

Date: Thu, 13 Jun 2019 12:02:07 +0200

Subject: [PATCH 4/5] Change synchronization of rpm transaction to swdb

 (RhBug:1737328)

Originally the state of transaction element was changed by callbacks,

but this approach cannot ensure that all elements will be marked

correctly in case of error when rpm could skip some of elements.

The new approach only synchronize the states of all elements in

transaction after transaction is finished.

https://bugzilla.redhat.com/show_bug.cgi?id=1737328

---

 dnf/base.py         | 21 +++++----------------

 dnf/util.py         | 36 ++++++++++++++++++++++++++++++++++++

 dnf/yum/rpmtrans.py | 22 +++-------------------

 3 files changed, 44 insertions(+), 35 deletions(-)

diff --git a/dnf/base.py b/dnf/base.py

index add64036b..237ad397d 100644

--- a/dnf/base.py

+++ b/dnf/base.py

@@ -978,6 +978,7 @@ class Base(object):

                 os.nice(onice)

             except:

                 pass

+        dnf.util._sync_rpm_trans_with_swdb(self._ts, self._transaction)

         if errors is None:

             pass

@@ -987,17 +988,7 @@ class Base(object):

             # particular element failed and if not, decide that is the

             # case.

             failed = [el for el in self._ts if el.Failed()]

-            if failed:

-                for te in failed:

-                    te_nevra = dnf.util._te_nevra(te)

-                    for tsi in self._transaction:

-                        if str(tsi) == te_nevra:

-                            tsi.state = libdnf.transaction.TransactionItemState_ERROR

-

-                errstring = _('Errors occurred during transaction.')

-                logger.debug(errstring)

-                self.history.end(rpmdbv)

-            else:

+            if not failed:

                 login = dnf.util.get_effective_login()

                 msg = _("Failed to obtain the transaction lock "

                         "(logged in as: %s).")

@@ -1005,13 +996,11 @@ class Base(object):

                 msg = _('Could not run transaction.')

                 raise dnf.exceptions.Error(msg)

         else:

-            if self._record_history():

-                herrors = [ucd(x) for x in errors]

-                self.history.end(rpmdbv)

-

             logger.critical(_("Transaction couldn't start:"))

             for e in errors:

-                logger.critical(e[0])  # should this be 'to_unicoded'?

+                logger.critical(ucd(e[0]))

+            if self._record_history() and not self._ts.isTsFlagSet(rpm.RPMTRANS_FLAG_TEST):

+                self.history.end(rpmdbv)

             msg = _("Could not run transaction.")

             raise dnf.exceptions.Error(msg)

diff --git a/dnf/util.py b/dnf/util.py

index 2f1abe626..9d0288e5a 100644

--- a/dnf/util.py

+++ b/dnf/util.py

@@ -396,6 +396,42 @@ def _te_nevra(te):

     return nevra + te.V() + '-' + te.R() + '.' + te.A()

+def _sync_rpm_trans_with_swdb(rpm_transaction, swdb_transaction):

+    revert_actions = {libdnf.transaction.TransactionItemAction_DOWNGRADED,

+                      libdnf.transaction.TransactionItemAction_OBSOLETED,

+                      libdnf.transaction.TransactionItemAction_REMOVE,

+                      libdnf.transaction.TransactionItemAction_UPGRADED,

+                      libdnf.transaction.TransactionItemAction_REINSTALLED}

+    cached_tsi = [tsi for tsi in swdb_transaction]

+    el_not_found = False

+    error = False

+    for rpm_el in rpm_transaction:

+        te_nevra = _te_nevra(rpm_el)

+        tsi = rpm_el.Key()

+        if tsi is None or not hasattr(tsi, "pkg"):

+            for tsi_candidate in cached_tsi:

+                if tsi_candidate.state != libdnf.transaction.TransactionItemState_UNKNOWN:

+                    continue

+                if tsi_candidate.action not in revert_actions:

+                    continue

+                if str(tsi_candidate) == te_nevra:

+                    tsi = tsi_candidate

+                    break

+        if tsi is None or not hasattr(tsi, "pkg"):

+            logger.critical(_("TransactionItem not found for key: {}").format(te_nevra))

+            el_not_found = True

+            continue

+        if rpm_el.Failed():

+            tsi.state = libdnf.transaction.TransactionItemState_ERROR

+            error = True

+        else:

+            tsi.state = libdnf.transaction.TransactionItemState_DONE

+    if error:

+        logger.debug(_('Errors occurred during transaction.'))

+

+    return el_not_found

+

+

 class tmpdir(object):

     def __init__(self):

         prefix = '%s-' % dnf.const.PREFIX

diff --git a/dnf/yum/rpmtrans.py b/dnf/yum/rpmtrans.py

index 0834a8c82..8a5bd4731 100644

--- a/dnf/yum/rpmtrans.py

+++ b/dnf/yum/rpmtrans.py

@@ -336,10 +336,7 @@ class RPMTransaction(object):

             return

         transaction_list = self._extract_cbkey(key)

-        for tsi in transaction_list:

-            if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

-                tsi.state = libdnf.transaction.TransactionItemState_DONE

-                break

+        tsi = transaction_list[0]

         for display in self.displays:

             display.filelog(tsi.pkg, tsi.action)

@@ -370,10 +367,7 @@ class RPMTransaction(object):

     def _unInstStop(self, key):

         transaction_list = self._extract_cbkey(key)

-        for tsi in transaction_list:

-            if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

-                tsi.state = libdnf.transaction.TransactionItemState_DONE

-                break

+        tsi = transaction_list[0]

         for display in self.displays:

             display.filelog(tsi.pkg, tsi.action)

@@ -385,26 +379,16 @@ class RPMTransaction(object):

     def _cpioError(self, key):

         transaction_list = self._extract_cbkey(key)

-        for tsi in transaction_list:

-            if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

-                tsi.state = libdnf.transaction.TransactionItemState_ERROR

-                break

         msg = "Error in cpio payload of rpm package %s" % transaction_list[0].pkg

         for display in self.displays:

             display.error(msg)

     def _unpackError(self, key):

         transaction_list = self._extract_cbkey(key)

-        tsi = transaction_list[0]

-        msg = "Error unpacking rpm package %s" % tsi.pkg

+        msg = "Error unpacking rpm package %s" % transaction_list[0].pkg

         for display in self.displays:

             display.error(msg)

-        for tsi in transaction_list:

-           if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

-                tsi.state = libdnf.transaction.TransactionItemState_ERROR

-                return

-

     def _scriptError(self, amount, total, key):

         # "amount" carries the failed scriptlet tag,

         # "total" carries fatal/non-fatal status

-- 

2.21.0

From 91aa07fe7b7f01727f2eb5d231fdeb16bd82a872 Mon Sep 17 00:00:00 2001

From: Jaroslav Mracek <jmracek@redhat.com>

Date: Tue, 25 Jun 2019 11:44:37 +0200

Subject: [PATCH 5/5] Add detailed debug login for swdb/rpm transaction

 (RhBug:1737328)

The logging is required to investigate the issue with tsi.state unknown.

The logging will be triggered only when transaction element

synchronization failed.

---

 dnf/util.py | 25 +++++++++++++++++++++++--

 1 file changed, 23 insertions(+), 2 deletions(-)

diff --git a/dnf/util.py b/dnf/util.py

index 9d0288e5a..71f61ab52 100644

--- a/dnf/util.py

+++ b/dnf/util.py

@@ -396,6 +396,23 @@ def _te_nevra(te):

     return nevra + te.V() + '-' + te.R() + '.' + te.A()

+def _log_rpm_trans_with_swdb(rpm_transaction, swdb_transaction):

+    logger.debug("Logging transaction elements")

+    for rpm_el in rpm_transaction:

+        tsi = rpm_el.Key()

+        tsi_state = None

+        if tsi is not None:

+            tsi_state = tsi.state

+        msg = "RPM element: '{}', Key(): '{}', Key state: '{}', Failed() '{}': ".format(

+            _te_nevra(rpm_el), tsi, tsi_state, rpm_el.Failed())

+        logger.debug(msg)

+    for tsi in swdb_transaction:

+        msg = "SWDB element: '{}', State: '{}', Action: '{}', From repo: '{}', Reason: '{}', " \

+              "Get reason: '{}'".format(str(tsi), tsi.state, tsi.action, tsi.from_repo, tsi.reason,

+                                        tsi.get_reason())

+        logger.debug(msg)

+

+

 def _sync_rpm_trans_with_swdb(rpm_transaction, swdb_transaction):

     revert_actions = {libdnf.transaction.TransactionItemAction_DOWNGRADED,

                       libdnf.transaction.TransactionItemAction_OBSOLETED,

@@ -426,10 +443,14 @@ def _sync_rpm_trans_with_swdb(rpm_transaction, swdb_transaction):

             error = True

         else:

             tsi.state = libdnf.transaction.TransactionItemState_DONE

+    for tsi in cached_tsi:

+        if tsi.state == libdnf.transaction.TransactionItemState_UNKNOWN:

+            logger.critical(_("TransactionSWDBItem not found for key: {}").format(str(tsi)))

+            el_not_found = True

     if error:

         logger.debug(_('Errors occurred during transaction.'))

-

-    return el_not_found

+    if el_not_found:

+        _log_rpm_trans_with_swdb(rpm_transaction, cached_tsi)

 class tmpdir(object):

-- 

2.21.0