Improve logging of failable deliverables

The pungi.global.log should show subvariant for each failed deliverable
(if available). When the compose finishes, there is a new log file in
logs/global/deliverables.json containing details about all deliverables
as triples of (variant, arch, subvariant).

 * `required` lists all deliverables that can not fail
 * `attempted` lists all failable deliverables that were started
 * `failed` is a subset of `attempted` and only contains deliverables
   that failed

If the compose fails, the lists may be incomplete.

Signed-off-by: Lubomír Sedlář <lsedlar@redhat.com>

pungi/compose.py

@@ -25,6 +25,7 @@ import os
 import time
 import tempfile
 import shutil
+import json
 
 import kobo.log
 from productmd.composeinfo import ComposeInfo
@@ -135,8 +136,10 @@ class Compose(kobo.log.LoggingBase):
 
         # Stores list of deliverables that failed, but did not abort the
         # compose.
-        # {Variant.uid: {Arch: [deliverable]}}
+        # {deliverable: [(Variant.uid, arch, subvariant)]}
         self.failed_deliverables = {}
+        self.attempted_deliverables = {}
+        self.required_deliverables = {}
 
     get_compose_dir = staticmethod(get_compose_dir)
 
@@ -238,11 +241,16 @@ class Compose(kobo.log.LoggingBase):
         return self._status_file
 
     def _log_failed_deliverables(self):
-        for variant, variant_data in self.failed_deliverables.iteritems():
+        for kind, data in self.failed_deliverables.iteritems():
-            for arch, deliverables in variant_data.iteritems():
+            for variant, arch, subvariant in data:
-                for deliverable in deliverables:
+                self.log_info('Failed %s on variant <%s>, arch <%s>, subvariant <%s>.'
-                    self.log_info('Failed %s on variant <%s>, arch <%s>.'
+                              % (kind, variant, arch, subvariant))
-                                  % (deliverable, variant, arch))
+        log = os.path.join(self.paths.log.topdir('global'), 'deliverables.json')
+        with open(log, 'w') as f:
+            json.dump({'required': self.required_deliverables,
+                       'failed': self.failed_deliverables,
+                       'attempted': self.attempted_deliverables},
+                      f, indent=4)
 
     def write_status(self, stat_msg):
         if stat_msg not in ("STARTED", "FINISHED", "DOOMED"):
@@ -257,7 +265,8 @@ class Compose(kobo.log.LoggingBase):
 
         if stat_msg == 'FINISHED' and self.failed_deliverables:
             stat_msg = 'FINISHED_INCOMPLETE'
-            self._log_failed_deliverables()
+
+        self._log_failed_deliverables()
 
         with open(self.status_file, "w") as f:
             f.write(stat_msg + "\n")
@@ -308,12 +317,25 @@ class Compose(kobo.log.LoggingBase):
         Variant can be None.
         """
         failable = get_arch_variant_data(self.conf, 'failable_deliverables', arch, variant)
-        if deliverable in failable:
+        return deliverable in failable
-            # Store failed deliverable for later logging.
+
-            variant_uid = variant.uid if variant else ''
+    def attempt_deliverable(self, variant, arch, kind, subvariant=None):
-            self.failed_deliverables.setdefault(variant_uid, {}).setdefault(arch, []).append(deliverable)
+        """Log information about attempted deliverable."""
-            return True
+        variant_uid = variant.uid if variant else ''
-        return False
+        self.attempted_deliverables.setdefault(kind, []).append(
+            (variant_uid, arch, subvariant))
+
+    def require_deliverable(self, variant, arch, kind, subvariant=None):
+        """Log information about attempted deliverable."""
+        variant_uid = variant.uid if variant else ''
+        self.required_deliverables.setdefault(kind, []).append(
+            (variant_uid, arch, subvariant))
+
+    def fail_deliverable(self, variant, arch, kind, subvariant=None):
+        """Log information about failed deliverable."""
+        variant_uid = variant.uid if variant else ''
+        self.failed_deliverables.setdefault(kind, []).append(
+            (variant_uid, arch, subvariant))
 
     @property
     def image_release(self):

pungi/phases/createiso.py

@@ -183,7 +183,7 @@ class CreateIsoThread(WorkerThread):
 
     def process(self, item, num):
         compose, cmd, variant, arch = item
-        with failable(compose, variant, arch, 'iso', 'Creating ISO'):
+        with failable(compose, variant, arch, 'iso'):
             self.worker(compose, cmd, variant, arch, num)
 
     def worker(self, compose, cmd, variant, arch, num):

pungi/phases/image_build.py

@@ -144,7 +144,7 @@ class CreateImageBuildThread(WorkerThread):
         compose, cmd = item
         variant = cmd["image_conf"]["image-build"]["variant"]
         subvariant = cmd["image_conf"]["image-build"].get("subvariant", variant.uid)
-        with failable(compose, variant, '*', 'image-build'):
+        with failable(compose, variant, '*', 'image-build', subvariant):
             self.worker(num, compose, variant, subvariant, cmd)
 
     def worker(self, num, compose, variant, subvariant, cmd):

pungi/phases/live_images.py

@@ -205,7 +205,7 @@ class CreateLiveImageThread(WorkerThread):
 
     def process(self, item, num):
         compose, cmd, variant, arch = item
-        with failable(compose, variant, arch, 'live', 'Creating live images'):
+        with failable(compose, variant, arch, 'live', cmd.get('subvariant')):
             self.worker(compose, cmd, variant, arch, num)
 
     def worker(self, compose, cmd, variant, arch, num):

pungi/phases/livemedia_phase.py

@@ -158,7 +158,7 @@ class LiveMediaThread(WorkerThread):
         compose, variant, config = item
         subvariant = config.pop('subvariant')
         self.num = num
-        with failable(compose, variant, '*', 'live-media'):
+        with failable(compose, variant, '*', 'live-media', subvariant):
             self.worker(compose, variant, subvariant, config)
 
     def _get_log_file(self, compose, variant, subvariant, config):

pungi/phases/ostree_installer.py

@@ -42,7 +42,7 @@ class OstreeInstallerThread(WorkerThread):
     def process(self, item, num):
         compose, variant, arch, config = item
         self.num = num
-        with util.failable(compose, variant, arch, 'ostree-installer', 'Ostree installer'):
+        with util.failable(compose, variant, arch, 'ostree-installer'):
             self.worker(compose, variant, arch, config)
 
     def worker(self, compose, variant, arch, config):

pungi/util.py

@@ -459,17 +459,26 @@ def process_args(fmt, args):
 
 
 @contextlib.contextmanager
-def failable(compose, variant, arch, deliverable, msg=None):
+def failable(compose, variant, arch, deliverable, subvariant=None):
     """If a deliverable can fail, log a message and go on as if it succeeded."""
-    msg = msg or deliverable.capitalize()
+    msg = deliverable.replace('-', ' ').capitalize()
+    can_fail = compose.can_fail(variant, arch, deliverable)
+    if can_fail:
+        compose.attempt_deliverable(variant, arch, deliverable, subvariant)
+    else:
+        compose.require_deliverable(variant, arch, deliverable, subvariant)
     try:
         yield
     except Exception as exc:
-        if not compose.can_fail(variant, arch, deliverable):
+        if not can_fail:
             raise
         else:
-            compose.log_info('[FAIL] %s (variant %s, arch %s) failed, but going on anyway.'
+            compose.fail_deliverable(variant, arch, deliverable, subvariant)
-                             % (msg, variant.uid if variant else 'None', arch))
+            ident = 'variant %s, arch %s' % (variant.uid if variant else 'None', arch)
+            if subvariant:
+                ident += ', subvariant %s' % subvariant
+            compose.log_info('[FAIL] %s (%s) failed, but going on anyway.'
+                             % (msg, ident))
             compose.log_info(str(exc))
             tb = traceback.format_exc()
             compose.log_debug(tb)

tests/helpers.py

@@ -64,6 +64,9 @@ class DummyCompose(object):
         self.old_composes = []
         self.config_dir = '/home/releng/config'
         self.notifier = None
+        self.attempt_deliverable = mock.Mock()
+        self.fail_deliverable = mock.Mock()
+        self.require_deliverable = mock.Mock()
 
     def get_variants(self, arch=None, types=None, recursive=None):
         return [v for v in self.variants.values() if not arch or arch in v.arches]

tests/test_compose.py

@@ -336,14 +336,14 @@ class StatusTest(unittest.TestCase):
         }
 
         variant = mock.Mock(uid='Server')
-        self.compose.can_fail(variant, 'x86_64', 'live')
+        self.compose.fail_deliverable(variant, 'x86_64', 'live')
-        self.compose.can_fail(None, '*', 'build-image')
+        self.compose.fail_deliverable(None, '*', 'build-image')
 
         self.compose.write_status('FINISHED')
 
         self.logger.log.assert_has_calls(
-            [mock.call(20, 'Failed build-image on variant <>, arch <*>.'),
+            [mock.call(20, 'Failed build-image on variant <>, arch <*>, subvariant <None>.'),
-             mock.call(20, 'Failed live on variant <Server>, arch <x86_64>.')],
+             mock.call(20, 'Failed live on variant <Server>, arch <x86_64>, subvariant <None>.')],
             any_order=True)
 
         with open(os.path.join(self.tmp_dir, 'STATUS'), 'r') as f:

tests/test_createiso_phase.py

@@ -357,7 +357,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             t.process((compose, cmd, compose.variants['Server'], 'x86_64'), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Creating ISO (variant Server, arch x86_64) failed, but going on anyway.'),
+            mock.call('[FAIL] Iso (variant Server, arch x86_64) failed, but going on anyway.'),
             mock.call('BOOM')
         ])
 
@@ -399,7 +399,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             t.process((compose, cmd, compose.variants['Server'], 'x86_64'), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Creating ISO (variant Server, arch x86_64) failed, but going on anyway.'),
+            mock.call('[FAIL] Iso (variant Server, arch x86_64) failed, but going on anyway.'),
             mock.call('Runroot task failed: 1234. See {} for more details.'.format(
                 self.topdir + '/logs/x86_64/createiso-image-name.x86_64.log'))
         ])
@@ -479,7 +479,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             t.process((compose, cmd, compose.variants['Server'], 'x86_64'), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Creating ISO (variant Server, arch x86_64) failed, but going on anyway.'),
+            mock.call('[FAIL] Iso (variant Server, arch x86_64) failed, but going on anyway.'),
             mock.call('BOOM')
         ])
 

tests/test_imagebuildphase.py

@@ -540,7 +540,7 @@ class TestCreateImageBuildThread(PungiTestCase):
             t.process((compose, cmd), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Image-build (variant Client, arch *) failed, but going on anyway.'),
+            mock.call('[FAIL] Image build (variant Client, arch *, subvariant Client) failed, but going on anyway.'),
             mock.call('ImageBuild task failed: 1234. See %s for more details.'
                       % (os.path.join(self.topdir,
                                       'logs/amd64-x86_64/imagebuild-Client-Client-docker.amd64-x86_64.log'))),
@@ -591,7 +591,7 @@ class TestCreateImageBuildThread(PungiTestCase):
             t.process((compose, cmd), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Image-build (variant Client, arch *) failed, but going on anyway.'),
+            mock.call('[FAIL] Image build (variant Client, arch *, subvariant Client) failed, but going on anyway.'),
             mock.call('BOOM'),
         ])
 

tests/test_liveimagesphase.py

@@ -598,7 +598,7 @@ class TestCreateLiveImageThread(PungiTestCase):
             t.process((compose, cmd, compose.variants['Client'], 'amd64'), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Creating live images (variant Client, arch amd64) failed, but going on anyway.'),
+            mock.call('[FAIL] Live (variant Client, arch amd64, subvariant Client) failed, but going on anyway.'),
             mock.call('LiveImage task failed: 123. See %s/logs/amd64/liveimage-None-None-xyz.amd64.log for more details.'
                       % self.topdir)
         ])
@@ -639,7 +639,7 @@ class TestCreateLiveImageThread(PungiTestCase):
             t.process((compose, cmd, compose.variants['Client'], 'amd64'), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Creating live images (variant Client, arch amd64) failed, but going on anyway.'),
+            mock.call('[FAIL] Live (variant Client, arch amd64, subvariant Client) failed, but going on anyway.'),
             mock.call('BOOM')
         ])
 

tests/test_livemediaphase.py

@@ -418,7 +418,7 @@ class TestLiveMediaThread(PungiTestCase):
             t.process((compose, compose.variants['Server'], config), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Live-media (variant Server, arch *) failed, but going on anyway.'),
+            mock.call('[FAIL] Live media (variant Server, arch *, subvariant KDE) failed, but going on anyway.'),
             mock.call('Live media task failed: 1234. See %s for more details.'
                       % (os.path.join(self.topdir, 'logs/amd64-x86_64/livemedia-Server-KDE.amd64-x86_64.log')))
         ])
@@ -460,7 +460,7 @@ class TestLiveMediaThread(PungiTestCase):
             t.process((compose, compose.variants['Server'], config), 1)
 
         compose.log_info.assert_has_calls([
-            mock.call('[FAIL] Live-media (variant Server, arch *) failed, but going on anyway.'),
+            mock.call('[FAIL] Live media (variant Server, arch *, subvariant KDE) failed, but going on anyway.'),
             mock.call('BOOM')
         ])