Notice when update package should have been installed but wasn't

We hit an interesting case in update testing recently:

https://bodhi.fedoraproject.org/updates/FEDORA-2018-115068f60e

An earlier version of that update failed testing. When we dug
into it a bit, we found that the test was failing because an
earlier version of the `pki-server` package was installed than
the version that was in the update; when asked (as part of
FreeIPA deployment) to install it, dnf had noticed that there
were dependency issues with the version of the package from the
update, but it happened to be able to install the version from
the frozen 'stable' repo...so it just went ahead and did that.

In this case, the 'missed' package resulted in a test failure,
but it'd actually be possible for this to happen and the test
to complete; we really ought to notice when this happens, and
treat it as a test failure.

So what this attempts to do is: at the end of all update tests,
check for all installed packages with the same name as a package
from the update, and compare their full NEVR to the one of the
package from the update. If a package with the same name as one
of the update packages is installed, but does not appear to be
the *same NEVR*, we fail, and upload the lists of packages for
manual investigation as to what the heck's going on.

Signed-off-by: Adam Williamson <awilliam@redhat.com>

lib/utils.pm

@@ -438,6 +438,11 @@ sub _repo_setup_updates {
     # source packages and epochs
     assert_script_run 'rpm -qp *.rpm --qf "%{SOURCERPM} %{EPOCH} %{NAME}-%{VERSION}-%{RELEASE}\n" | sort -u > /var/log/updatepkgs.txt';
     upload_logs "/var/log/updatepkgs.txt";
+    # also log just the binary package names: this is so we can check
+    # later whether any package from the update *should* have been
+    # installed, but was not
+    assert_script_run 'rpm -qp *.rpm --qf "%{NAME} " > /var/log/updatepkgnames.txt';
+    upload_logs "/var/log/updatepkgnames.txt";
     # HOTFIX 2018-11: an authselect change broke FreeIPA, grab the
     # pending update that fixes that (F28 and F29)
     if (get_var("VERSION") eq "29") {

tests/_advisory_post.pm

@@ -21,6 +21,32 @@ sub run {
     # we'll try and upload the output even if comm 'failed', as it
     # does in fact still write it in some cases
     upload_logs "/var/log/testedpkgs.txt", failok=>1;
+
+    # now, try and figure out if we have a different version of any
+    # package from the update installed - this indicates a problem,
+    # it likely means a dep issue meant dnf installed an older version
+    # from the frozen release repo
+    script_run 'touch /tmp/installedupdatepkgs.txt';
+    script_run 'for pkg in $(cat /var/log/updatepkgnames.txt); do rpm -q $pkg && rpm -q $pkg --qf "%{SOURCERPM} %{EPOCH} %{NAME}-%{VERSION}-%{RELEASE}\n" >> /tmp/installedupdatepkgs.txt; done';
+    script_run 'sort -u -o /tmp/installedupdatepkgs.txt /tmp/installedupdatepkgs.txt';
+    # now, /tmp/installedupdatepkgs.txt is a sorted list of installed packages
+    # with the same name as packages from the update, in the same form as
+    # /var/log/updatepkgs.txt; so if any line appears in installedupdatepkgs.txt
+    # but not updatepkgs.txt, we have a problem.
+    if (script_run 'comm -23 /tmp/installedupdatepkgs.txt /var/log/updatepkgs.txt > /var/log/installednotupdatedpkgs.txt') {
+        # occasionally, for some reason, it's unhappy about sorting;
+        # we shouldn't fail the test in this case, just upload the
+        # files so we can see why...
+        upload_logs "/tmp/installedupdatepkgs.txt", failok=>1;
+        upload_logs "/var/log/updatepkgs.txt", failok=>1;
+    }
+    # this exits 1 if the file is zero-length, 0 if it's longer
+    # if it's 0, that's *BAD*: we want to upload the file and fail
+    unless (script_run 'test -s /var/log/installednotupdatedpkgs.txt') {
+        upload_logs "/var/log/installednotupdatedpkgs.txt", failok=>1;
+        upload_logs "/var/log/updatepkgs.txt", failok=>1;
+        die "Package(s) from update not installed when it should have been! See installednotupdatedpkgs.txt";
+    }
 }
 
 sub test_flags {