iso-wrapper: Handle wrong implant md5

If the checkisomd5 command exits successfully but returns a wrong value,
we should catch and log that. In theory this should be impossible, but
we have seen it in production.

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

pungi/phases/createiso.py

@@ -261,7 +261,7 @@ class CreateIsoThread(WorkerThread):
         img.disc_count = cmd["disc_count"]
         img.bootable = cmd["bootable"]
         img.subvariant = variant.uid
-        img.implant_md5 = iso.get_implanted_md5(cmd["iso_path"])
+        img.implant_md5 = iso.get_implanted_md5(cmd["iso_path"], logger=compose._logger)
         setattr(img, 'can_fail', compose.can_fail(variant, arch, 'iso'))
         setattr(img, 'deliverable', 'iso')
         try:

pungi/wrappers/iso.py

@@ -19,7 +19,6 @@ import sys
 import pipes
 from fnmatch import fnmatch
 
-import kobo.log
 from kobo.shortcuts import force_list, relative_path, run
 
 
@@ -194,11 +193,22 @@ def get_checkisomd5_cmd(iso_path, just_print=False):
     return cmd
 
 
-def get_implanted_md5(iso_path):
+def get_implanted_md5(iso_path, logger=None):
     cmd = get_checkisomd5_cmd(iso_path, just_print=True)
     retcode, output = run(cmd)
     line = output.splitlines()[0]
-    return line.rsplit(":")[-1].strip()
+    md5 = line.rsplit(":")[-1].strip()
+    if len(md5) != 32:
+        # We have seen cases where the command finished successfully, but
+        # returned garbage value. We need to handle it, otherwise there would
+        # be a crash once we try to write image metadata.
+        # This only logs information about the problem and leaves the hash
+        # empty, which is valid from productmd point of view.
+        if logger:
+            logger.critical('Implanted MD5 in %s is not valid: %r', iso_path, md5)
+            logger.critical('Ran command %r; exit code %r; output %r', cmd, retcode, output)
+        return None
+    return md5
 
 
 def get_isohybrid_cmd(iso_path, arch):

tests/test_createiso_phase.py

@@ -258,7 +258,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             [mock.call(get_runroot_cmd.return_value,
                        log_file='%s/logs/x86_64/createiso-image-name.x86_64.log' % self.topdir)])
         self.assertEqual(iso.get_implanted_md5.call_args_list,
-                         [mock.call(cmd['iso_path'])])
+                         [mock.call(cmd['iso_path'], logger=compose._logger)])
         self.assertEqual(iso.get_volume_id.call_args_list,
                          [mock.call(cmd['iso_path'])])
 
@@ -323,7 +323,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             [mock.call(get_runroot_cmd.return_value,
                        log_file='%s/logs/src/createiso-image-name.src.log' % self.topdir)])
         self.assertEqual(iso.get_implanted_md5.call_args_list,
-                         [mock.call(cmd['iso_path'])])
+                         [mock.call(cmd['iso_path'], logger=compose._logger)])
         self.assertEqual(iso.get_volume_id.call_args_list,
                          [mock.call(cmd['iso_path'])])
 
@@ -389,7 +389,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             [mock.call(get_runroot_cmd.return_value,
                        log_file='%s/logs/x86_64/createiso-image-name.x86_64.log' % self.topdir)])
         self.assertEqual(iso.get_implanted_md5.call_args_list,
-                         [mock.call(cmd['iso_path'])])
+                         [mock.call(cmd['iso_path'], logger=compose._logger)])
         self.assertEqual(iso.get_volume_id.call_args_list,
                          [mock.call(cmd['iso_path'])])
 
@@ -552,7 +552,7 @@ class CreateisoThreadTest(helpers.PungiTestCase):
             [mock.call(cmd['cmd'], show_cmd=True,
                        logfile='%s/logs/x86_64/createiso-image-name.x86_64.log' % self.topdir)])
         self.assertEqual(iso.get_implanted_md5.call_args_list,
-                         [mock.call(cmd['iso_path'])])
+                         [mock.call(cmd['iso_path'], logger=compose._logger)])
         self.assertEqual(iso.get_volume_id.call_args_list,
                          [mock.call(cmd['iso_path'])])
 

tests/test_iso_wrapper.py

@@ -0,0 +1,39 @@
+# -*- coding: utf-8 -*-
+
+import mock
+import os
+import sys
+import unittest
+
+sys.path.insert(0, os.path.join(os.path.dirname(__file__), ".."))
+
+from pungi.wrappers import iso
+
+CORRECT_OUTPUT = '''dummy.iso:   31ff3e405e26ad01c63b62f6b11d30f6
+Fragment sums: 6eb92e7bda221d7fe5f19b4d21468c9bf261d84c96d145d96c76444b9cbc
+Fragment count: 20
+Supported ISO: no
+'''
+
+INCORRECT_OUTPUT = '''This should never happen: File not found'''
+
+
+class TestIsoUtils(unittest.TestCase):
+    @mock.patch('pungi.wrappers.iso.run')
+    def test_get_implanted_md5_correct(self, mock_run):
+        mock_run.return_value = (0, CORRECT_OUTPUT)
+        logger = mock.Mock()
+        self.assertEqual(iso.get_implanted_md5('dummy.iso', logger=logger),
+                         '31ff3e405e26ad01c63b62f6b11d30f6')
+        self.assertEqual(mock_run.call_args_list,
+                         [mock.call(['/usr/bin/checkisomd5', '--md5sumonly', 'dummy.iso'])])
+        self.assertEqual(logger.mock_calls, [])
+
+    @mock.patch('pungi.wrappers.iso.run')
+    def test_get_implanted_md5_incorrect(self, mock_run):
+        mock_run.return_value = (0, INCORRECT_OUTPUT)
+        logger = mock.Mock()
+        self.assertIsNone(iso.get_implanted_md5('dummy.iso', logger=logger))
+        self.assertEqual(mock_run.call_args_list,
+                         [mock.call(['/usr/bin/checkisomd5', '--md5sumonly', 'dummy.iso'])])
+        self.assertGreater(len(logger.mock_calls), 0)