[buildinstall] Improve logging

This patch fixes how logs are stored if lorax is used as buildinstall
method. The logs for each variant are in a separate file now. If failure
is allowed, the global log will now show why it failed.

A couple tests are added as well.

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

pungi/phases/buildinstall.py

@@ -132,23 +132,27 @@ class BuildinstallPhase(PhaseBase):
                 for variant in self.compose.get_variants(arch=arch, types=['variant']):
                     volid = get_volid(self.compose, arch, variant=variant, disc_type="boot")
                     commands.append(
-                        self._get_lorax_cmd(repo_baseurl, output_dir, variant, arch, buildarch, volid)
+                        (variant,
+                         self._get_lorax_cmd(repo_baseurl, output_dir, variant, arch, buildarch, volid))
                     )
             elif buildinstall_method == "buildinstall":
-                commands.append(lorax.get_buildinstall_cmd(product,
+                commands.append(
-                                                           version,
+                    (None,
-                                                           release,
+                     lorax.get_buildinstall_cmd(product,
-                                                           repo_baseurl,
+                                                version,
-                                                           output_dir,
+                                                release,
-                                                           is_final=self.compose.supported,
+                                                repo_baseurl,
-                                                           buildarch=buildarch,
+                                                output_dir,
-                                                           volid=volid))
+                                                is_final=self.compose.supported,
+                                                buildarch=buildarch,
+                                                volid=volid))
+                )
             else:
                 raise ValueError("Unsupported buildinstall method: %s" % buildinstall_method)
 
-            for cmd in commands:
+            for (variant, cmd) in commands:
                 self.pool.add(BuildinstallThread(self.pool))
-                self.pool.queue_put((self.compose, arch, cmd))
+                self.pool.queue_put((self.compose, arch, variant, cmd))
 
         self.pool.start()
 
@@ -357,22 +361,25 @@ def symlink_boot_iso(compose, arch, variant):
 
 class BuildinstallThread(WorkerThread):
     def process(self, item, num):
-        compose, arch, cmd = item
+        # The variant is None unless lorax is used as buildinstall method.
+        compose, arch, variant, cmd = item
         try:
-            self.worker(compose, arch, cmd, num)
+            self.worker(compose, arch, variant, cmd, num)
-        except Exception:
+        except Exception as exc:
-            if not compose.can_fail(None, arch, 'buildinstall'):
+            if not compose.can_fail(variant, arch, 'buildinstall'):
                 raise
             else:
                 self.pool.log_info(
-                    '[FAIL] Buildinstall for arch %s failed, but going on anyway.' % arch)
+                    '[FAIL] Buildinstall for variant %s arch %s failed, but going on anyway.\n%s'
+                    % (variant.uid if variant else 'None', arch, exc))
 
-    def worker(self, compose, arch, cmd, num):
+    def worker(self, compose, arch, variant, cmd, num):
         runroot = compose.conf.get("runroot", False)
         buildinstall_method = compose.conf["buildinstall_method"]
-        log_file = compose.paths.log.log_file(arch, "buildinstall")
+        log_filename = ('buildinstall-%s' % variant.uid) if variant else 'buildinstall'
+        log_file = compose.paths.log.log_file(arch, log_filename)
 
-        msg = "Runnging buildinstall for arch %s" % arch
+        msg = "Running buildinstall for arch %s" % arch
 
         output_dir = compose.paths.work.buildinstall_dir(arch)
         if os.path.isdir(output_dir):
@@ -399,7 +406,10 @@ class BuildinstallThread(WorkerThread):
             runroot_tag = compose.conf["runroot_tag"]
 
             koji_wrapper = KojiWrapper(compose.conf["koji_profile"])
-            koji_cmd = koji_wrapper.get_runroot_cmd(runroot_tag, arch, cmd, channel=runroot_channel, use_shell=True, task_id=True, packages=packages, mounts=[compose.topdir])
+            koji_cmd = koji_wrapper.get_runroot_cmd(runroot_tag, arch, cmd,
+                                                    channel=runroot_channel,
+                                                    use_shell=True, task_id=True,
+                                                    packages=packages, mounts=[compose.topdir])
 
             # avoid race conditions?
             # Kerberos authentication failed: Permission denied in replay cache code (-1765328215)
@@ -408,13 +418,14 @@ class BuildinstallThread(WorkerThread):
             output = koji_wrapper.run_runroot_cmd(koji_cmd, log_file=log_file)
             task_id = int(output["task_id"])
             if output["retcode"] != 0:
-                raise RuntimeError("Runroot task failed: %s. See %s for more details." % (output["task_id"], log_file))
+                raise RuntimeError("Runroot task failed: %s. See %s for more details."
+                                   % (output["task_id"], log_file))
 
         else:
             # run locally
             run(cmd, show_cmd=True, logfile=log_file)
 
-        log_file = compose.paths.log.log_file(arch, "buildinstall-RPMs")
+        log_file = compose.paths.log.log_file(arch, log_filename + '-RPMs')
         rpms = get_buildroot_rpms(compose, task_id)
         open(log_file, "w").write("\n".join(rpms))
 

tests/test_buildinstall.py

@@ -10,12 +10,14 @@ import sys
 
 sys.path.insert(0, os.path.join(os.path.dirname(__file__), ".."))
 
-from pungi.phases.buildinstall import BuildinstallPhase
+from pungi.phases.buildinstall import BuildinstallPhase, BuildinstallThread
+from pungi.util import get_arch_variant_data
 
 
 class _DummyCompose(object):
     def __init__(self, config):
         self.conf = config
+        self.topdir = '/topdir'
         self.paths = mock.Mock(
             compose=mock.Mock(
                 topdir=mock.Mock(return_value='/a/b'),
@@ -24,6 +26,9 @@ class _DummyCompose(object):
             work=mock.Mock(
                 arch_repo=mock.Mock(return_value='file:///a/b/'),
                 buildinstall_dir=mock.Mock(side_effect=lambda x: '/buildinstall_dir/' + x),
+            ),
+            log=mock.Mock(
+                log_file=mock.Mock(side_effect=lambda arch, filename: '/log/%s.%s.log' % (filename, arch)),
             )
         )
         self._logger = mock.Mock()
@@ -41,6 +46,10 @@ class _DummyCompose(object):
     def get_variants(self, arch, types):
         return self.variants.get(arch, [])
 
+    def can_fail(self, variant, arch, deliverable):
+        failable = get_arch_variant_data(self.conf, 'failable_deliverables', arch, variant)
+        return deliverable in failable
+
 
 class TestBuildinstallPhase(unittest.TestCase):
 
@@ -349,5 +358,165 @@ class TestCopyFiles(unittest.TestCase):
             any_order=True
         )
 
+
+class BuildinstallThreadTestCase(unittest.TestCase):
+
+    @mock.patch('pungi.phases.buildinstall.KojiWrapper')
+    @mock.patch('pungi.phases.buildinstall.get_buildroot_rpms')
+    @mock.patch('pungi.phases.buildinstall.open')
+    @mock.patch('pungi.phases.buildinstall.run')
+    def test_buildinstall_thread_with_lorax_in_runroot(self, run, mock_open,
+                                                       get_buildroot_rpms, KojiWrapperMock):
+        compose = _DummyCompose({
+            'buildinstall_method': 'lorax',
+            'runroot': True,
+            'runroot_tag': 'rrt',
+            'koji_profile': 'koji',
+        })
+
+        get_buildroot_rpms.return_value = ['bash', 'zsh']
+        pool = mock.Mock()
+        cmd = mock.Mock()
+
+        get_runroot_cmd = KojiWrapperMock.return_value.get_runroot_cmd
+
+        run_runroot_cmd = KojiWrapperMock.return_value.run_runroot_cmd
+        run_runroot_cmd.return_value = {
+            'output': 'Foo bar baz',
+            'retcode': 0,
+            'task_id': 1234,
+        }
+
+        t = BuildinstallThread(pool)
+
+        with mock.patch('time.sleep'):
+            t.process((compose, 'x86_64', compose.variants['x86_64'][0], cmd), 0)
+
+        get_runroot_cmd.assert_has_calls([
+            mock.call('rrt', 'x86_64', cmd, channel=None,
+                      use_shell=True, task_id=True,
+                      packages=['strace', 'lorax'], mounts=['/topdir'])
+        ])
+        run_runroot_cmd(get_runroot_cmd.return_value, log_file='/log/buildinstall-Server.x86_64.log')
+        mock_open.return_value.write.assert_has_calls([
+            mock.call('bash\nzsh')
+        ])
+
+    @mock.patch('pungi.phases.buildinstall.KojiWrapper')
+    @mock.patch('pungi.phases.buildinstall.get_buildroot_rpms')
+    @mock.patch('pungi.phases.buildinstall.open')
+    @mock.patch('pungi.phases.buildinstall.run')
+    def test_buildinstall_thread_with_buildinstall_in_runroot(self, run, mock_open,
+                                                              get_buildroot_rpms, KojiWrapperMock):
+        compose = _DummyCompose({
+            'buildinstall_method': 'buildinstall',
+            'runroot': True,
+            'runroot_tag': 'rrt',
+            'koji_profile': 'koji',
+        })
+
+        get_buildroot_rpms.return_value = ['bash', 'zsh']
+        pool = mock.Mock()
+        cmd = mock.Mock()
+
+        get_runroot_cmd = KojiWrapperMock.return_value.get_runroot_cmd
+
+        run_runroot_cmd = KojiWrapperMock.return_value.run_runroot_cmd
+        run_runroot_cmd.return_value = {
+            'output': 'Foo bar baz',
+            'retcode': 0,
+            'task_id': 1234,
+        }
+
+        t = BuildinstallThread(pool)
+
+        with mock.patch('time.sleep'):
+            t.process((compose, 'x86_64', None, cmd), 0)
+
+        get_runroot_cmd.assert_has_calls([
+            mock.call('rrt', 'x86_64', cmd, channel=None,
+                      use_shell=True, task_id=True,
+                      packages=['strace', 'anaconda'], mounts=['/topdir'])
+        ])
+        run_runroot_cmd(get_runroot_cmd.return_value, log_file='/log/buildinstall.x86_64.log')
+        mock_open.return_value.write.assert_has_calls([
+            mock.call('bash\nzsh')
+        ])
+
+    @mock.patch('pungi.phases.buildinstall.KojiWrapper')
+    @mock.patch('pungi.phases.buildinstall.get_buildroot_rpms')
+    @mock.patch('pungi.phases.buildinstall.open')
+    @mock.patch('pungi.phases.buildinstall.run')
+    def test_buildinstall_fail_exit_code(self, run, mock_open,
+                                         get_buildroot_rpms, KojiWrapperMock):
+        compose = _DummyCompose({
+            'buildinstall_method': 'buildinstall',
+            'runroot': True,
+            'runroot_tag': 'rrt',
+            'koji_profile': 'koji',
+            'failable_deliverables': [
+                ('^.+$', {'*': ['buildinstall']})
+            ],
+        })
+
+        get_buildroot_rpms.return_value = ['bash', 'zsh']
+        pool = mock.Mock()
+        cmd = mock.Mock()
+
+        run_runroot_cmd = KojiWrapperMock.return_value.run_runroot_cmd
+        run_runroot_cmd.return_value = {
+            'output': 'Foo bar baz',
+            'retcode': 1,
+            'task_id': 1234,
+        }
+
+        t = BuildinstallThread(pool)
+
+        with mock.patch('time.sleep'):
+            t.process((compose, 'x86_64', None, cmd), 0)
+
+        pool.log_info.assert_has_calls([
+            mock.call('[BEGIN] Running buildinstall for arch x86_64'),
+            mock.call('[FAIL] Buildinstall for variant None arch x86_64 failed, but going on anyway.\nRunroot task failed: 1234. See /log/buildinstall.x86_64.log for more details.')
+        ])
+
+    @mock.patch('pungi.phases.buildinstall.KojiWrapper')
+    @mock.patch('pungi.phases.buildinstall.get_buildroot_rpms')
+    @mock.patch('pungi.phases.buildinstall.open')
+    @mock.patch('pungi.phases.buildinstall.run')
+    def test_lorax_fail_exit_code(self, run, mock_open,
+                                  get_buildroot_rpms, KojiWrapperMock):
+        compose = _DummyCompose({
+            'buildinstall_method': 'lorax',
+            'runroot': True,
+            'runroot_tag': 'rrt',
+            'koji_profile': 'koji',
+            'failable_deliverables': [
+                ('^.+$', {'*': ['buildinstall']})
+            ],
+        })
+
+        get_buildroot_rpms.return_value = ['bash', 'zsh']
+        pool = mock.Mock()
+        cmd = mock.Mock()
+
+        run_runroot_cmd = KojiWrapperMock.return_value.run_runroot_cmd
+        run_runroot_cmd.return_value = {
+            'output': 'Foo bar baz',
+            'retcode': 1,
+            'task_id': 1234,
+        }
+
+        t = BuildinstallThread(pool)
+
+        with mock.patch('time.sleep'):
+            t.process((compose, 'x86_64', compose.variants['x86_64'][0], cmd), 0)
+
+        pool.log_info.assert_has_calls([
+            mock.call('[BEGIN] Running buildinstall for arch x86_64'),
+            mock.call('[FAIL] Buildinstall for variant Server arch x86_64 failed, but going on anyway.\nRunroot task failed: 1234. See /log/buildinstall-Server.x86_64.log for more details.')
+        ])
+
+
 if __name__ == "__main__":
     unittest.main()