Refactor checking for failable deliverables

This uses a new common function that will ensure consistent logging
without duplicating the functionality all over the place.

A couple tests are updated to verify that correct data is logged.

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

pungi/phases/atomic_installer.py

@@ -2,7 +2,6 @@
 
 import os
 from kobo.threads import ThreadPool, WorkerThread
-import traceback
 import shutil
 from productmd import images
 
@@ -41,17 +40,8 @@ class AtomicInstallerThread(WorkerThread):
     def process(self, item, num):
         compose, variant, arch, config = item
         self.num = num
-        try:
+        with util.failable(compose, variant, arch, 'atomic_installer', 'Atomic'):
             self.worker(compose, variant, arch, config)
-        except Exception as exc:
-            if not compose.can_fail(variant, arch, 'atomic_installer'):
-                raise
-            else:
-                msg = ('[FAIL] Atomic for variant %s, arch %s, failed, but going on anyway.\n%s'
-                       % (variant.uid, arch, exc))
-                self.pool.log_info(msg)
-                tb = traceback.format_exc()
-                self.pool.log_debug(tb)
 
     def worker(self, compose, variant, arch, config):
         msg = 'Atomic phase for variant %s, arch %s' % (variant.uid, arch)

pungi/phases/buildinstall.py

@@ -22,7 +22,6 @@ import pipes
 import tempfile
 import shutil
 import re
-import traceback
 
 from kobo.threads import ThreadPool, WorkerThread
 from kobo.shortcuts import run
@@ -30,7 +29,7 @@ from productmd.images import Image
 
 from pungi.arch import get_valid_arches
 from pungi.util import get_buildroot_rpms, get_volid, get_arch_variant_data
-from pungi.util import get_file_size, get_mtime
+from pungi.util import get_file_size, get_mtime, failable
 from pungi.wrappers.lorax import LoraxWrapper
 from pungi.wrappers.kojiwrapper import KojiWrapper
 from pungi.wrappers.iso import IsoWrapper
@@ -191,19 +190,10 @@ class BuildinstallPhase(PhaseBase):
                 # TODO: label is not used
                 label = ""
                 volid = get_volid(self.compose, arch, variant, escape_spaces=False, disc_type=disc_type)
-                try:
+                msg = 'Copying results of buildinstall'
+                with failable(self.compose, variant, arch, 'buildinstall', msg):
                     tweak_buildinstall(buildinstall_dir, os_tree, arch, variant.uid, label, volid, kickstart_file)
                     link_boot_iso(self.compose, arch, variant)
-                except Exception as exc:
-                    if not self.compose.can_fail(variant, arch, 'buildinstall'):
-                        raise
-                    else:
-                        tb = traceback.format_exc()
-                        self.pool.log_info(
-                            '[FAIL] Copying results of buildinstall for variant %s arch %s failed, '
-                            'but going on anyway.\n%s'
-                            % (variant.uid, arch, exc))
-                        self.pool.log_debug(tb)
 
 
 def get_kickstart_file(compose):
@@ -392,17 +382,8 @@ class BuildinstallThread(WorkerThread):
     def process(self, item, num):
         # The variant is None unless lorax is used as buildinstall method.
         compose, arch, variant, cmd = item
-        try:
+        with failable(compose, variant, arch, 'buildinstall'):
             self.worker(compose, arch, variant, cmd, num)
-        except Exception as exc:
-            if not compose.can_fail(variant, arch, 'buildinstall'):
-                raise
-            else:
-                tb = traceback.format_exc()
-                self.pool.log_info(
-                    '[FAIL] Buildinstall for variant %s arch %s failed, but going on anyway.\n%s'
-                    % (variant.uid if variant else 'None', arch, exc))
-                self.pool.log_debug(tb)
 
     def worker(self, compose, arch, variant, cmd, num):
         runroot = compose.conf.get("runroot", False)

pungi/phases/createiso.py

@@ -20,7 +20,6 @@ import time
 import pipes
 import random
 import shutil
-import traceback
 
 import productmd.treeinfo
 from productmd.images import Image
@@ -32,7 +31,7 @@ from pungi.wrappers.createrepo import CreaterepoWrapper
 from pungi.wrappers.kojiwrapper import KojiWrapper
 from pungi.wrappers.jigdo import JigdoWrapper
 from pungi.phases.base import PhaseBase
-from pungi.util import makedirs, get_volid, get_arch_variant_data
+from pungi.util import makedirs, get_volid, get_arch_variant_data, failable
 from pungi.media_split import MediaSplitter
 from pungi.compose_metadata.discinfo import read_discinfo, write_discinfo
 
@@ -219,17 +218,8 @@ class CreateIsoThread(WorkerThread):
 
     def process(self, item, num):
         compose, cmd, variant, arch = item
-        try:
+        with failable(compose, variant, arch, 'iso', 'Creating ISO'):
             self.worker(compose, cmd, num)
-        except Exception as exc:
-            if not compose.can_fail(variant, arch, 'iso'):
-                raise
-            else:
-                msg = ('[FAIL] Creating iso for variant %s, arch %s failed, but going on anyway.\n%s'
-                       % (variant.uid, arch, exc))
-                self.pool.log_info(msg)
-                tb = traceback.format_exc()
-                self.pool.log_debug(tb)
 
     def worker(self, compose, cmd, num):
         mounts = [compose.topdir]

pungi/phases/image_build.py

@@ -4,9 +4,8 @@ import copy
 import os
 import time
 from kobo import shortcuts
-import traceback
 
-from pungi.util import get_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size
+from pungi.util import get_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size, failable
 from pungi.phases.base import PhaseBase
 from pungi.linker import Linker
 from pungi.paths import translate_path
@@ -145,17 +144,8 @@ class CreateImageBuildThread(WorkerThread):
         compose, cmd = item
         variant = cmd["image_conf"]["image-build"]["variant"]
         subvariant = cmd["image_conf"]["image-build"].get("subvariant", variant.uid)
-        try:
+        with failable(compose, variant, '*', 'image-build'):
             self.worker(num, compose, variant, subvariant, cmd)
-        except Exception as exc:
-            if not compose.can_fail(cmd["image_conf"]["image-build"]['variant'], '*', 'image-build'):
-                raise
-            else:
-                msg = ('[FAIL] image-build for variant %s (%s) failed, but going on anyway.\n%s'
-                       % (variant.uid, subvariant, exc))
-                self.pool.log_info(msg)
-                tb = traceback.format_exc()
-                self.pool.log_debug(tb)
 
     def worker(self, num, compose, variant, subvariant, cmd):
         arches = cmd["image_conf"]["image-build"]['arches'].split(',')

pungi/phases/live_images.py

@@ -20,7 +20,6 @@ import sys
 import time
 import pipes
 import shutil
-import traceback
 
 from kobo.threads import ThreadPool, WorkerThread
 from kobo.shortcuts import run, save_to_file, force_list
@@ -29,7 +28,7 @@ from productmd.images import Image
 from pungi.wrappers.kojiwrapper import KojiWrapper
 from pungi.wrappers.iso import IsoWrapper
 from pungi.phases.base import PhaseBase
-from pungi.util import get_arch_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size
+from pungi.util import get_arch_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size, failable
 from pungi.paths import translate_path
 
 
@@ -206,17 +205,8 @@ class CreateLiveImageThread(WorkerThread):
 
     def process(self, item, num):
         compose, cmd, variant, arch = item
-        try:
+        with failable(compose, variant, arch, 'live', 'Creating live images'):
             self.worker(compose, cmd, variant, arch, num)
-        except Exception as exc:
-            if not compose.can_fail(variant, arch, 'live'):
-                raise
-            else:
-                msg = ('[FAIL] Creating live image for variant %s, arch %s failed, but going on anyway.\n%s'
-                       % (variant.uid, arch, exc))
-                self.pool.log_info(msg)
-                tb = traceback.format_exc()
-                self.pool.log_debug(tb)
 
     def worker(self, compose, cmd, variant, arch, num):
         self.basename = '%(name)s-%(version)s-%(release)s' % cmd

pungi/phases/livemedia_phase.py

@@ -3,9 +3,8 @@
 import os
 import time
 from kobo import shortcuts
-import traceback
 
-from pungi.util import get_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size
+from pungi.util import get_variant_data, resolve_git_url, makedirs, get_mtime, get_file_size, failable
 from pungi.phases.base import PhaseBase
 from pungi.linker import Linker
 from pungi.paths import translate_path
@@ -159,17 +158,8 @@ class LiveMediaThread(WorkerThread):
         compose, variant, config = item
         subvariant = config.pop('subvariant')
         self.num = num
-        try:
+        with failable(compose, variant, '*', 'live-media'):
             self.worker(compose, variant, subvariant, config)
-        except Exception as exc:
-            if not compose.can_fail(variant, '*', 'live-media'):
-                raise
-            else:
-                msg = ('[FAIL] live-media for variant %s (%s) failed, but going on anyway.\n%s'
-                       % (variant.uid, subvariant, exc))
-                self.pool.log_info(msg)
-                tb = traceback.format_exc()
-                self.pool.log_debug(tb)
 
     def _get_log_file(self, compose, variant, subvariant, config):
         arches = '-'.join(config['arches'])

pungi/util.py

@@ -24,6 +24,8 @@ import errno
 import pipes
 import re
 import urlparse
+import contextlib
+import traceback
 
 from kobo.shortcuts import run, force_list
 from productmd.common import get_major_version
@@ -455,3 +457,20 @@ def process_args(fmt, args):
     ['--opt=foo', '--opt=bar']
     """
     return [fmt.format(val) for val in force_list(args or [])]
+
+
+@contextlib.contextmanager
+def failable(compose, variant, arch, deliverable, msg=None):
+    """If a deliverable can fail, log a message and go on as if it succeeded."""
+    msg = msg or deliverable.capitalize()
+    try:
+        yield
+    except Exception as exc:
+        if not compose.can_fail(variant, arch, deliverable):
+            raise
+        else:
+            compose.log_info('[FAIL] %s (variant %s, arch %s) failed, but going on anyway.'
+                             % (msg, variant.uid if variant else 'None', arch))
+            compose.log_info(str(exc))
+            tb = traceback.format_exc()
+            compose.log_debug(tb)

tests/test_atomic_installer_phase.py

@@ -228,10 +228,9 @@ class AtomicThreadTest(helpers.PungiTestCase):
         t = atomic.AtomicInstallerThread(pool)
 
         t.process((compose, compose.variants['Everything'], 'x86_64', cfg), 1)
-        pool.log_info.assert_has_calls([
+        compose.log_info.assert_has_calls([
-            mock.call('[BEGIN] Atomic phase for variant Everything, arch x86_64'),
+            mock.call('[FAIL] Atomic (variant Everything, arch x86_64) failed, but going on anyway.'),
-            mock.call('[FAIL] Atomic for variant Everything, arch x86_64, failed, but going on anyway.\n'
+            mock.call('BOOM')
-                      'BOOM')
         ])
 
     @mock.patch('productmd.images.Image')
@@ -267,10 +266,9 @@ class AtomicThreadTest(helpers.PungiTestCase):
         t = atomic.AtomicInstallerThread(pool)
 
         t.process((compose, compose.variants['Everything'], 'x86_64', cfg), 1)
-        pool.log_info.assert_has_calls([
+        compose.log_info.assert_has_calls([
-            mock.call('[BEGIN] Atomic phase for variant Everything, arch x86_64'),
+            mock.call('[FAIL] Atomic (variant Everything, arch x86_64) failed, but going on anyway.'),
-            mock.call('[FAIL] Atomic for variant Everything, arch x86_64, failed, but going on anyway.\n'
+            mock.call('Runroot task failed: 1234. See %s/logs/x86_64/atomic/runroot.log for more details.'
-                      'Runroot task failed: 1234. See %s/logs/x86_64/atomic/runroot.log for more details.'
                       % self.topdir)
         ])
 

tests/test_buildinstall.py

@@ -557,10 +557,10 @@ class BuildinstallThreadTestCase(PungiTestCase):
         with mock.patch('time.sleep'):
             t.process((compose, 'x86_64', None, cmd), 0)
 
-        pool.log_info.assert_has_calls([
+        compose.log_info.assert_has_calls([
-            mock.call('[BEGIN] Running buildinstall for arch x86_64'),
+            mock.call('[FAIL] Buildinstall (variant None, arch x86_64) failed, but going on anyway.'),
-            mock.call('[FAIL] Buildinstall for variant None arch x86_64 failed, but going on anyway.\n'
+            mock.call('Runroot task failed: 1234. See %s/logs/x86_64/buildinstall.x86_64.log for more details.'
-                      'Runroot task failed: 1234. See %s/logs/x86_64/buildinstall.x86_64.log for more details.' % self.topdir)
+                      % self.topdir)
         ])
 
     @mock.patch('pungi.phases.buildinstall.KojiWrapper')
@@ -593,10 +593,9 @@ class BuildinstallThreadTestCase(PungiTestCase):
         with mock.patch('time.sleep'):
             t.process((compose, 'x86_64', compose.variants['Server'], cmd), 0)
 
-        pool.log_info.assert_has_calls([
+        compose.log_info.assert_has_calls([
-            mock.call('[BEGIN] Running buildinstall for arch x86_64'),
+            mock.call('[FAIL] Buildinstall (variant Server, arch x86_64) failed, but going on anyway.'),
-            mock.call('[FAIL] Buildinstall for variant Server arch x86_64 failed, but going on anyway.\n'
+            mock.call('Runroot task failed: 1234. See %s/logs/x86_64/buildinstall-Server.x86_64.log for more details.' % self.topdir)
-                      'Runroot task failed: 1234. See %s/logs/x86_64/buildinstall-Server.x86_64.log for more details.' % self.topdir)
         ])
 
 

tests/test_imagebuildphase.py

@@ -536,12 +536,15 @@ class TestCreateImageBuildThread(PungiTestCase):
         }
 
         t = CreateImageBuildThread(pool)
-        with mock.patch('os.stat') as stat:
+        with mock.patch('time.sleep'):
-            with mock.patch('os.path.getsize') as getsize:
+            t.process((compose, cmd), 1)
-                with mock.patch('time.sleep'):
+
-                    getsize.return_value = 1024
+        compose.log_info.assert_has_calls([
-                    stat.return_value.st_mtime = 13579
+            mock.call('[FAIL] Image-build (variant Client, arch *) failed, but going on anyway.'),
-                    t.process((compose, cmd), 1)
+            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'))),
+        ])
 
     @mock.patch('pungi.phases.image_build.KojiWrapper')
     @mock.patch('pungi.phases.image_build.Linker')
@@ -584,12 +587,13 @@ class TestCreateImageBuildThread(PungiTestCase):
         koji_wrapper.run_blocking_cmd.side_effect = boom
 
         t = CreateImageBuildThread(pool)
-        with mock.patch('os.stat') as stat:
+        with mock.patch('time.sleep'):
-            with mock.patch('os.path.getsize') as getsize:
+            t.process((compose, cmd), 1)
-                with mock.patch('time.sleep'):
+
-                    getsize.return_value = 1024
+        compose.log_info.assert_has_calls([
-                    stat.return_value.st_mtime = 13579
+            mock.call('[FAIL] Image-build (variant Client, arch *) failed, but going on anyway.'),
-                    t.process((compose, cmd), 1)
+            mock.call('BOOM'),
+        ])
 
 
 if __name__ == "__main__":

tests/test_liveimagesphase.py

@@ -581,6 +581,8 @@ class TestCreateLiveImageThread(PungiTestCase):
             'specfile': None,
             'ksurl': None,
             'subvariant': 'Client',
+            'release': 'xyz',
+            'type': 'live',
         }
 
         koji_wrapper = KojiWrapper.return_value
@@ -595,6 +597,12 @@ class TestCreateLiveImageThread(PungiTestCase):
         with mock.patch('time.sleep'):
             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('LiveImage task failed: 123. See %s/logs/amd64/liveimage-None-None-xyz.amd64.log for more details.'
+                      % self.topdir)
+        ])
+
     @mock.patch('shutil.copy2')
     @mock.patch('pungi.phases.live_images.run')
     @mock.patch('pungi.phases.live_images.KojiWrapper')
@@ -619,6 +627,8 @@ class TestCreateLiveImageThread(PungiTestCase):
             'specfile': None,
             'ksurl': None,
             'subvariant': 'Client',
+            'release': 'xyz',
+            'type': 'live',
         }
 
         koji_wrapper = KojiWrapper.return_value
@@ -628,6 +638,11 @@ class TestCreateLiveImageThread(PungiTestCase):
         with mock.patch('time.sleep'):
             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('BOOM')
+        ])
+
 
 if __name__ == "__main__":
     unittest.main()

tests/test_livemediaphase.py

@@ -377,8 +377,10 @@ class TestLiveMediaThread(PungiTestCase):
             self.assertEqual('live', image.type)
             self.assertEqual('KDE', image.subvariant)
 
+    @mock.patch('pungi.phases.livemedia_phase.get_mtime')
+    @mock.patch('pungi.phases.livemedia_phase.get_file_size')
     @mock.patch('pungi.phases.livemedia_phase.KojiWrapper')
-    def test_handle_koji_fail(self, KojiWrapper):
+    def test_handle_koji_fail(self, KojiWrapper, get_file_size, get_mtime):
         compose = DummyCompose(self.topdir, {
             'koji_profile': 'koji',
             'failable_deliverables': [
@@ -408,17 +410,23 @@ class TestLiveMediaThread(PungiTestCase):
             'retcode': 1,
             'output': None,
         }
+        get_file_size.return_value = 1024
+        get_mtime.return_value.st_mtime = 13579
 
         t = LiveMediaThread(pool)
-        with mock.patch('os.stat') as stat:
+        with mock.patch('time.sleep'):
-            with mock.patch('os.path.getsize') as getsize:
+            t.process((compose, compose.variants['Server'], config), 1)
-                with mock.patch('time.sleep'):
-                    getsize.return_value = 1024
-                    stat.return_value.st_mtime = 13579
-                    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('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')))
+        ])
+
+    @mock.patch('pungi.phases.livemedia_phase.get_mtime')
+    @mock.patch('pungi.phases.livemedia_phase.get_file_size')
     @mock.patch('pungi.phases.livemedia_phase.KojiWrapper')
-    def test_handle_exception(self, KojiWrapper):
+    def test_handle_exception(self, KojiWrapper, get_file_size, get_mtime):
         compose = DummyCompose(self.topdir, {
             'koji_profile': 'koji',
             'failable_deliverables': [
@@ -444,14 +452,17 @@ class TestLiveMediaThread(PungiTestCase):
 
         run_blocking_cmd = KojiWrapper.return_value.run_blocking_cmd
         run_blocking_cmd.side_effect = boom
+        get_file_size.return_value = 1024
+        get_mtime.return_value.st_mtime = 13579
 
         t = LiveMediaThread(pool)
-        with mock.patch('os.stat') as stat:
+        with mock.patch('time.sleep'):
-            with mock.patch('os.path.getsize') as getsize:
+            t.process((compose, compose.variants['Server'], config), 1)
-                with mock.patch('time.sleep'):
+
-                    getsize.return_value = 1024
+        compose.log_info.assert_has_calls([
-                    stat.return_value.st_mtime = 13579
+            mock.call('[FAIL] Live-media (variant Server, arch *) failed, but going on anyway.'),
-                    t.process((compose, compose.variants['Server'], config), 1)
+            mock.call('BOOM')
+        ])
 
 
 if __name__ == "__main__":