From 18b6020ac5b5bc21d90ce2bc8da4cae68f68b0a8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Lubom=C3=ADr=20Sedl=C3=A1=C5=99?= Date: Wed, 13 Apr 2016 13:44:17 +0200 Subject: [PATCH] Improve logging of failable deliverables MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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ář --- pungi/compose.py | 48 +++++++++++++++++++++++--------- pungi/phases/createiso.py | 2 +- pungi/phases/image_build.py | 2 +- pungi/phases/live_images.py | 2 +- pungi/phases/livemedia_phase.py | 2 +- pungi/phases/ostree_installer.py | 2 +- pungi/util.py | 19 +++++++++---- tests/helpers.py | 3 ++ tests/test_compose.py | 8 +++--- tests/test_createiso_phase.py | 6 ++-- tests/test_imagebuildphase.py | 4 +-- tests/test_liveimagesphase.py | 4 +-- tests/test_livemediaphase.py | 4 +-- 13 files changed, 70 insertions(+), 36 deletions(-) diff --git a/pungi/compose.py b/pungi/compose.py index f7641295..e63e77b0 100644 --- a/pungi/compose.py +++ b/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 arch, deliverables in variant_data.iteritems(): - for deliverable in deliverables: - self.log_info('Failed %s on variant <%s>, arch <%s>.' - % (deliverable, variant, arch)) + for kind, data in self.failed_deliverables.iteritems(): + for variant, arch, subvariant in data: + self.log_info('Failed %s on variant <%s>, arch <%s>, subvariant <%s>.' + % (kind, variant, arch, subvariant)) + 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: - # Store failed deliverable for later logging. - variant_uid = variant.uid if variant else '' - self.failed_deliverables.setdefault(variant_uid, {}).setdefault(arch, []).append(deliverable) - return True - return False + return deliverable in failable + + def attempt_deliverable(self, variant, arch, kind, subvariant=None): + """Log information about attempted deliverable.""" + variant_uid = variant.uid if variant else '' + 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): diff --git a/pungi/phases/createiso.py b/pungi/phases/createiso.py index d375e75d..6fd5ce93 100644 --- a/pungi/phases/createiso.py +++ b/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): diff --git a/pungi/phases/image_build.py b/pungi/phases/image_build.py index 7a95b6f6..dc856aeb 100644 --- a/pungi/phases/image_build.py +++ b/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): diff --git a/pungi/phases/live_images.py b/pungi/phases/live_images.py index e4af2da1..43e7c24e 100644 --- a/pungi/phases/live_images.py +++ b/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): diff --git a/pungi/phases/livemedia_phase.py b/pungi/phases/livemedia_phase.py index b0f15c3c..0e6b892b 100644 --- a/pungi/phases/livemedia_phase.py +++ b/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): diff --git a/pungi/phases/ostree_installer.py b/pungi/phases/ostree_installer.py index 934c3041..ad962174 100644 --- a/pungi/phases/ostree_installer.py +++ b/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): diff --git a/pungi/util.py b/pungi/util.py index 6a6ccf35..7498ed7c 100644 --- a/pungi/util.py +++ b/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.' - % (msg, variant.uid if variant else 'None', arch)) + compose.fail_deliverable(variant, arch, deliverable, subvariant) + 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) diff --git a/tests/helpers.py b/tests/helpers.py index 799b5eb1..42556965 100644 --- a/tests/helpers.py +++ b/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] diff --git a/tests/test_compose.py b/tests/test_compose.py index 8cd0e537..c40c9d1d 100755 --- a/tests/test_compose.py +++ b/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.can_fail(None, '*', 'build-image') + self.compose.fail_deliverable(variant, 'x86_64', 'live') + 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 live on variant , arch .')], + [mock.call(20, 'Failed build-image on variant <>, arch <*>, subvariant .'), + mock.call(20, 'Failed live on variant , arch , subvariant .')], any_order=True) with open(os.path.join(self.tmp_dir, 'STATUS'), 'r') as f: diff --git a/tests/test_createiso_phase.py b/tests/test_createiso_phase.py index d705cf73..46156814 100755 --- a/tests/test_createiso_phase.py +++ b/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') ]) diff --git a/tests/test_imagebuildphase.py b/tests/test_imagebuildphase.py index 34c8254b..9607cb56 100755 --- a/tests/test_imagebuildphase.py +++ b/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'), ]) diff --git a/tests/test_liveimagesphase.py b/tests/test_liveimagesphase.py index 2f7451ab..019567d3 100755 --- a/tests/test_liveimagesphase.py +++ b/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') ]) diff --git a/tests/test_livemediaphase.py b/tests/test_livemediaphase.py index 1948e288..f301052e 100755 --- a/tests/test_livemediaphase.py +++ b/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') ])