koji-wrapper: Log failed subtasks

If the parent task is successful, there can still be failed child tasks
for failable arches. We need to log those and potentially mark the
compose as incomplete.

Fixes: https://pagure.io/pungi/issue/874
Signed-off-by: Lubomír Sedlář <lsedlar@redhat.com>

pungi/phases/image_build.py

@@ -5,7 +5,7 @@ import os
 import time
 from kobo import shortcuts
 
-from pungi.util import makedirs, get_mtime, get_file_size, failable
+from pungi.util import makedirs, get_mtime, get_file_size, failable, log_failed_task
 from pungi.util import translate_path, get_repo_urls, version_generator
 from pungi.phases import base
 from pungi.linker import Linker
@@ -211,7 +211,10 @@ class CreateImageBuildThread(WorkerThread):
         # copy image to images/
         image_infos = []
 
-        paths = koji_wrapper.get_image_paths(output["task_id"])
+        paths = koji_wrapper.get_image_paths(
+            output["task_id"],
+            callback=lambda arch: log_failed_task(compose, variant, arch, 'image-build', subvariant)
+        )
 
         for arch, paths in paths.items():
             for path in paths:

pungi/phases/livemedia_phase.py

@@ -4,7 +4,7 @@ import os
 import time
 from kobo import shortcuts
 
-from pungi.util import makedirs, get_mtime, get_file_size, failable
+from pungi.util import makedirs, get_mtime, get_file_size, failable, log_failed_task
 from pungi.util import translate_path, get_repo_urls
 from pungi.phases.base import ConfigGuardedPhase, ImageConfigMixin, PhaseLoggerMixin
 from pungi.linker import Linker
@@ -132,7 +132,10 @@ class LiveMediaThread(WorkerThread):
         # collect results and update manifest
         image_infos = []
 
-        paths = koji_wrapper.get_image_paths(output['task_id'])
+        paths = koji_wrapper.get_image_paths(
+            output['task_id'],
+            callback=lambda arch: log_failed_task(compose, variant, arch, 'live-media', subvariant)
+        )
 
         for arch, paths in paths.items():
             for path in paths:

pungi/util.py

@@ -475,7 +475,6 @@ def failable(compose, can_fail, variant, arch, deliverable, subvariant=None, log
     """If a deliverable can fail, log a message and go on as if it succeeded."""
     if not logger:
         logger = compose._logger
-    msg = deliverable.replace('-', ' ').capitalize()
     if can_fail:
         compose.attempt_deliverable(variant, arch, deliverable, subvariant)
     else:
@@ -486,12 +485,18 @@ def failable(compose, can_fail, variant, arch, deliverable, subvariant=None, log
         if not can_fail:
             raise
         else:
+            log_failed_task(compose, variant, arch, deliverable, subvariant, logger=logger, exc=exc)
+
+
+def log_failed_task(compose, variant, arch, deliverable, subvariant, logger=None, exc=None):
+    logger = logger or compose._logger
+    msg = deliverable.replace('-', ' ').capitalize()
     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
-            logger.info('[FAIL] %s (%s) failed, but going on anyway.'
+    logger.info('[FAIL] %s (%s) failed, but going on anyway.' % (msg, ident))
-                        % (msg, ident))
+    if exc:
         logger.info(str(exc))
         tb = traceback.format_exc()
         logger.debug(tb)

pungi/wrappers/kojiwrapper.py

@@ -348,10 +348,13 @@ class KojiWrapper(object):
         retcode, _ = self._wait_for_task(task_id, logfile=log_file, max_retries=max_retries)
         return retcode
 
-    def get_image_paths(self, task_id):
+    def get_image_paths(self, task_id, callback=None):
         """
         Given an image task in Koji, get a mapping from arches to a list of
         paths to results of the task.
+
+        If callback is given, it will be called once with arch of every failed
+        subtask.
         """
         result = {}
 
@@ -364,7 +367,9 @@ class KojiWrapper(object):
 
             if child_task['state'] != koji.TASK_STATES['CLOSED']:
                 # The subtask is failed, which can happen with the can_fail
-                # option. Let's ignore it then.
+                # option. If given, call the callback, and go to next child.
+                if callback:
+                    callback(child_task['arch'])
                 continue
 
             is_scratch = child_task['request'][-1].get('scratch', False)

tests/fixtures/task_children_25643870.json

@@ -0,0 +1,445 @@
+[
+  {
+    "weight": 2.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      "Fedora-Container-Base",
+      "Rawhide",
+      "20180311.n.1",
+      "s390x",
+      {
+        "dest_tag": 3430,
+        "build_tag": 3428,
+        "build_tag_name": "f29-build",
+        "dest_tag_name": "f29-pending",
+        "id": 2032,
+        "name": "f29"
+      },
+      3428,
+      {
+        "dist": false,
+        "create_event": 31767365,
+        "creation_time": "2018-03-11 22:43:36.652788",
+        "state": 1,
+        "create_ts": 1520808216.65279,
+        "id": 874515
+      },
+      "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/s390x/os",
+      {
+        "kickstart": "fedora-docker-base.ks",
+        "disk_size": "5",
+        "format": [
+          "docker"
+        ],
+        "repo": [
+          "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/$arch/os"
+        ],
+        "release": "20180311.n.1",
+        "optional_arches": [
+          "aarch64",
+          "armhfp",
+          "ppc64le",
+          "s390x",
+          "x86_64"
+        ],
+        "ksurl": "git+https://pagure.io/fedora-kickstarts.git?#d9cf0e73bd1ec4df2abb4758e2c28ec72546de8d",
+        "factory_parameter": [
+          [
+            "dockerversion",
+            "1.10.1"
+          ],
+          [
+            "docker_cmd",
+            "[ \"/bin/bash\" ]"
+          ],
+          [
+            "docker_env",
+            "[ \"DISTTAG=f29container\", \"FGC=f29\" ]"
+          ],
+          [
+            "docker_label",
+            "{ \"name\": \"fedora\", \"license\": \"MIT\", \"vendor\": \"Fedora Project\", \"version\": \"29\"}"
+          ]
+        ],
+        "distro": "Fedora-22"
+      }
+    ],
+    "start_time": "2018-03-11 23:08:23.928109",
+    "start_ts": 1520809703.92811,
+    "waiting": null,
+    "awaited": false,
+    "label": "s390x",
+    "priority": 19,
+    "completion_time": "2018-03-12 00:08:03.441278",
+    "state": 5,
+    "create_time": "2018-03-11 23:08:10.964055",
+    "create_ts": 1520809690.96406,
+    "owner": 3445,
+    "host_id": 309,
+    "method": "createImage",
+    "completion_ts": 1520813283.44128,
+    "arch": "s390x",
+    "id": 25643898
+  },
+  {
+    "weight": 2.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      "Fedora-Container-Base",
+      "Rawhide",
+      "20180311.n.1",
+      "armhfp",
+      {
+        "dest_tag": 3430,
+        "build_tag": 3428,
+        "build_tag_name": "f29-build",
+        "dest_tag_name": "f29-pending",
+        "id": 2032,
+        "name": "f29"
+      },
+      3428,
+      {
+        "dist": false,
+        "create_event": 31767365,
+        "creation_time": "2018-03-11 22:43:36.652788",
+        "state": 1,
+        "create_ts": 1520808216.65279,
+        "id": 874515
+      },
+      "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/armhfp/os",
+      {
+        "kickstart": "fedora-docker-base.ks",
+        "disk_size": "5",
+        "format": [
+          "docker"
+        ],
+        "repo": [
+          "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/$arch/os"
+        ],
+        "release": "20180311.n.1",
+        "optional_arches": [
+          "aarch64",
+          "armhfp",
+          "ppc64le",
+          "s390x",
+          "x86_64"
+        ],
+        "ksurl": "git+https://pagure.io/fedora-kickstarts.git?#d9cf0e73bd1ec4df2abb4758e2c28ec72546de8d",
+        "factory_parameter": [
+          [
+            "dockerversion",
+            "1.10.1"
+          ],
+          [
+            "docker_cmd",
+            "[ \"/bin/bash\" ]"
+          ],
+          [
+            "docker_env",
+            "[ \"DISTTAG=f29container\", \"FGC=f29\" ]"
+          ],
+          [
+            "docker_label",
+            "{ \"name\": \"fedora\", \"license\": \"MIT\", \"vendor\": \"Fedora Project\", \"version\": \"29\"}"
+          ]
+        ],
+        "distro": "Fedora-22"
+      }
+    ],
+    "start_time": "2018-03-11 23:08:17.214930",
+    "start_ts": 1520809697.21493,
+    "waiting": null,
+    "awaited": false,
+    "label": "armhfp",
+    "priority": 19,
+    "completion_time": "2018-03-12 00:02:17.565792",
+    "state": 2,
+    "create_time": "2018-03-11 23:08:10.666517",
+    "create_ts": 1520809690.66652,
+    "owner": 3445,
+    "host_id": 197,
+    "method": "createImage",
+    "completion_ts": 1520812937.56579,
+    "arch": "armhfp",
+    "id": 25643896
+  },
+  {
+    "weight": 2.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      "Fedora-Container-Base",
+      "Rawhide",
+      "20180311.n.1",
+      "aarch64",
+      {
+        "dest_tag": 3430,
+        "build_tag": 3428,
+        "build_tag_name": "f29-build",
+        "dest_tag_name": "f29-pending",
+        "id": 2032,
+        "name": "f29"
+      },
+      3428,
+      {
+        "dist": false,
+        "create_event": 31767365,
+        "creation_time": "2018-03-11 22:43:36.652788",
+        "state": 1,
+        "create_ts": 1520808216.65279,
+        "id": 874515
+      },
+      "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/aarch64/os",
+      {
+        "kickstart": "fedora-docker-base.ks",
+        "disk_size": "5",
+        "format": [
+          "docker"
+        ],
+        "repo": [
+          "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/$arch/os"
+        ],
+        "release": "20180311.n.1",
+        "optional_arches": [
+          "aarch64",
+          "armhfp",
+          "ppc64le",
+          "s390x",
+          "x86_64"
+        ],
+        "ksurl": "git+https://pagure.io/fedora-kickstarts.git?#d9cf0e73bd1ec4df2abb4758e2c28ec72546de8d",
+        "factory_parameter": [
+          [
+            "dockerversion",
+            "1.10.1"
+          ],
+          [
+            "docker_cmd",
+            "[ \"/bin/bash\" ]"
+          ],
+          [
+            "docker_env",
+            "[ \"DISTTAG=f29container\", \"FGC=f29\" ]"
+          ],
+          [
+            "docker_label",
+            "{ \"name\": \"fedora\", \"license\": \"MIT\", \"vendor\": \"Fedora Project\", \"version\": \"29\"}"
+          ]
+        ],
+        "distro": "Fedora-22"
+      }
+    ],
+    "start_time": "2018-03-11 23:08:15.697731",
+    "start_ts": 1520809695.69773,
+    "waiting": null,
+    "awaited": false,
+    "label": "aarch64",
+    "priority": 19,
+    "completion_time": "2018-03-11 23:17:42.421352",
+    "state": 2,
+    "create_time": "2018-03-11 23:08:10.517265",
+    "create_ts": 1520809690.51727,
+    "owner": 3445,
+    "host_id": 287,
+    "method": "createImage",
+    "completion_ts": 1520810262.42135,
+    "arch": "aarch64",
+    "id": 25643894
+  },
+  {
+    "weight": 2.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      "Fedora-Container-Base",
+      "Rawhide",
+      "20180311.n.1",
+      "x86_64",
+      {
+        "dest_tag": 3430,
+        "build_tag": 3428,
+        "build_tag_name": "f29-build",
+        "dest_tag_name": "f29-pending",
+        "id": 2032,
+        "name": "f29"
+      },
+      3428,
+      {
+        "dist": false,
+        "create_event": 31767365,
+        "creation_time": "2018-03-11 22:43:36.652788",
+        "state": 1,
+        "create_ts": 1520808216.65279,
+        "id": 874515
+      },
+      "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/x86_64/os",
+      {
+        "kickstart": "fedora-docker-base.ks",
+        "disk_size": "5",
+        "format": [
+          "docker"
+        ],
+        "repo": [
+          "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/$arch/os"
+        ],
+        "release": "20180311.n.1",
+        "optional_arches": [
+          "aarch64",
+          "armhfp",
+          "ppc64le",
+          "s390x",
+          "x86_64"
+        ],
+        "ksurl": "git+https://pagure.io/fedora-kickstarts.git?#d9cf0e73bd1ec4df2abb4758e2c28ec72546de8d",
+        "factory_parameter": [
+          [
+            "dockerversion",
+            "1.10.1"
+          ],
+          [
+            "docker_cmd",
+            "[ \"/bin/bash\" ]"
+          ],
+          [
+            "docker_env",
+            "[ \"DISTTAG=f29container\", \"FGC=f29\" ]"
+          ],
+          [
+            "docker_label",
+            "{ \"name\": \"fedora\", \"license\": \"MIT\", \"vendor\": \"Fedora Project\", \"version\": \"29\"}"
+          ]
+        ],
+        "distro": "Fedora-22"
+      }
+    ],
+    "start_time": "2018-03-11 23:08:22.407649",
+    "start_ts": 1520809702.40765,
+    "waiting": null,
+    "awaited": false,
+    "label": "x86_64",
+    "priority": 19,
+    "completion_time": "2018-03-11 23:11:53.713226",
+    "state": 2,
+    "create_time": "2018-03-11 23:08:11.123381",
+    "create_ts": 1520809691.12338,
+    "owner": 3445,
+    "host_id": 154,
+    "method": "createImage",
+    "completion_ts": 1520809913.71323,
+    "arch": "x86_64",
+    "id": 25643900
+  },
+  {
+    "weight": 2.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      "Fedora-Container-Base",
+      "Rawhide",
+      "20180311.n.1",
+      "ppc64le",
+      {
+        "dest_tag": 3430,
+        "build_tag": 3428,
+        "build_tag_name": "f29-build",
+        "dest_tag_name": "f29-pending",
+        "id": 2032,
+        "name": "f29"
+      },
+      3428,
+      {
+        "dist": false,
+        "create_event": 31767365,
+        "creation_time": "2018-03-11 22:43:36.652788",
+        "state": 1,
+        "create_ts": 1520808216.65279,
+        "id": 874515
+      },
+      "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/ppc64le/os",
+      {
+        "kickstart": "fedora-docker-base.ks",
+        "disk_size": "5",
+        "format": [
+          "docker"
+        ],
+        "repo": [
+          "http://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20180311.n.1/compose/Everything/$arch/os"
+        ],
+        "release": "20180311.n.1",
+        "optional_arches": [
+          "aarch64",
+          "armhfp",
+          "ppc64le",
+          "s390x",
+          "x86_64"
+        ],
+        "ksurl": "git+https://pagure.io/fedora-kickstarts.git?#d9cf0e73bd1ec4df2abb4758e2c28ec72546de8d",
+        "factory_parameter": [
+          [
+            "dockerversion",
+            "1.10.1"
+          ],
+          [
+            "docker_cmd",
+            "[ \"/bin/bash\" ]"
+          ],
+          [
+            "docker_env",
+            "[ \"DISTTAG=f29container\", \"FGC=f29\" ]"
+          ],
+          [
+            "docker_label",
+            "{ \"name\": \"fedora\", \"license\": \"MIT\", \"vendor\": \"Fedora Project\", \"version\": \"29\"}"
+          ]
+        ],
+        "distro": "Fedora-22"
+      }
+    ],
+    "start_time": "2018-03-11 23:08:29.886127",
+    "start_ts": 1520809709.88613,
+    "waiting": null,
+    "awaited": false,
+    "label": "ppc64le",
+    "priority": 19,
+    "completion_time": "2018-03-11 23:09:19.227037",
+    "state": 5,
+    "create_time": "2018-03-11 23:08:10.767363",
+    "create_ts": 1520809690.76736,
+    "owner": 3445,
+    "host_id": 234,
+    "method": "createImage",
+    "completion_ts": 1520809759.22704,
+    "arch": "ppc64le",
+    "id": 25643897
+  },
+  {
+    "weight": 1.0,
+    "parent": 25643870,
+    "channel_id": 12,
+    "request": [
+      3430,
+      1056936,
+      false,
+      null,
+      true
+    ],
+    "start_time": "2018-03-12 00:08:17.895312",
+    "start_ts": 1520813297.89531,
+    "waiting": null,
+    "awaited": false,
+    "label": "tag",
+    "priority": 19,
+    "completion_time": "2018-03-12 00:08:18.571567",
+    "state": 2,
+    "create_time": "2018-03-12 00:08:17.715494",
+    "create_ts": 1520813297.71549,
+    "owner": 3445,
+    "host_id": 157,
+    "method": "tagBuild",
+    "completion_ts": 1520813298.57157,
+    "arch": "noarch",
+    "id": 25644779
+  }
+]

tests/test_koji_wrapper.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python2
 # -*- coding: utf-8 -*-
 
+import json
 import mock
 try:
     import unittest2 as unittest
@@ -15,6 +16,8 @@ sys.path.insert(0, os.path.join(os.path.dirname(__file__), ".."))
 
 from pungi.wrappers.kojiwrapper import KojiWrapper, get_buildroot_rpms
 
+from .helpers import FIXTURE_DIR
+
 
 class DumbMock(object):
     def __init__(self, **kwargs):
@@ -22,6 +25,12 @@ class DumbMock(object):
             setattr(self, key, value)
 
 
+def mock_imagebuild_path(id):
+    if isinstance(id, int):
+        return '/koji/imagebuild/' + str(id)
+    return '/koji/imagebuild/' + str(hash(str(id)))
+
+
 class KojiWrapperBaseTestCase(unittest.TestCase):
     def setUp(self):
         _, self.tmpfile = tempfile.mkstemp()
@@ -38,7 +47,7 @@ class KojiWrapperBaseTestCase(unittest.TestCase):
                     pathinfo=mock.Mock(
                         work=mock.Mock(return_value='/koji'),
                         taskrelpath=mock.Mock(side_effect=lambda id: 'task/' + str(id)),
-                        imagebuild=mock.Mock(side_effect=lambda id: '/koji/imagebuild/' + str(id)),
+                        imagebuild=mock.Mock(side_effect=mock_imagebuild_path),
                     )
                 )
             )
@@ -287,6 +296,30 @@ class KojiWrapperTest(KojiWrapperBaseTestCase):
                                '/koji/task/12387277/libvirt-raw-xz-x86_64.xml',
                                '/koji/task/12387277/Fedora-Cloud-Base-23-20160103.x86_64.raw.xz'])
 
+    def test_get_image_paths_failed_subtask(self):
+
+        failed = set()
+
+        def failed_callback(arch):
+            failed.add(arch)
+
+        with open(os.path.join(FIXTURE_DIR, 'task_children_25643870.json')) as f:
+            getTaskChildren_data = json.load(f)
+
+        with open(os.path.join(FIXTURE_DIR, 'children_task_results_25643870.json')) as f:
+            getTaskResult_data = json.load(f)
+
+        self.koji.koji_proxy = mock.Mock(
+            getTaskChildren=mock.Mock(return_value=getTaskChildren_data),
+            getTaskResult=mock.Mock(side_effect=lambda task_id: getTaskResult_data.get(str(task_id))),
+            getImageBuild=mock.Mock(side_effect=lambda name: {}),
+        )
+
+        result = self.koji.get_image_paths(25643870, callback=failed_callback)
+
+        self.assertItemsEqual(result.keys(), ['aarch64', 'armhfp', 'x86_64'])
+        self.assertItemsEqual(failed, ['ppc64le', 's390x'])
+
 
 class LiveMediaTestCase(KojiWrapperBaseTestCase):
     def test_get_live_media_cmd_minimal(self):

tests/test_livemediaphase.py

@@ -493,7 +493,7 @@ class TestLiveMediaThread(PungiTestCase):
                                      'version': 'Rawhide',
                                      'can_fail': []})])
         self.assertEqual(get_image_paths.mock_calls,
-                         [mock.call(1234)])
+                         [mock.call(1234, callback=mock.ANY)])
         self.assertTrue(os.path.isdir(self.topdir + '/compose/Server/x86_64/iso'))
         self.assertTrue(os.path.isdir(self.topdir + '/compose/Server/amd64/iso'))
         link = Linker.return_value.link