buildinstall: Print debug info if unmount fails

When even after retries the unmounting still fails, this patch runs `ls
-lA`, `fuser -vm` and `lsof +D` on the directory to give some idea of
what's blocking it.

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

pungi/phases/buildinstall.py

@@ -27,7 +27,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, failable, makedirs, run_unmount_cmd
+from pungi.util import get_file_size, get_mtime, failable, makedirs, fusermount
 from pungi.wrappers.lorax import LoraxWrapper
 from pungi.wrappers.kojiwrapper import KojiWrapper
 from pungi.wrappers import iso
@@ -273,7 +273,7 @@ def tweak_buildinstall(compose, src, dst, arch, variant, label, volid, kickstart
                 cmd = ["cp", "-v", "--remove-destination", config_path, config_in_image]
                 run(cmd)
 
-        run_unmount_cmd(["fusermount", "-u", mount_tmp_dir])
+        fusermount(mount_tmp_dir)
         shutil.rmtree(mount_tmp_dir)
 
     # HACK: make buildinstall files world readable

pungi/util.py

@@ -595,11 +595,19 @@ def temp_dir(log=None, *args, **kwargs):
                 log.warning('Error removing %s: %s', dir, exc.strerror)
 
 
-def run_unmount_cmd(cmd, max_retries=10):
+def fusermount(path, **kwargs):
+    """Run fusermount -u on a given path."""
+    run_unmount_cmd(['fusermount', '-u', path], path=path, **kwargs)
+
+
+def run_unmount_cmd(cmd, max_retries=10, path=None, logger=None):
     """Attempt to run the command to unmount an image.
 
     If the command fails and stderr complains about device being busy, try
     again. We will do up to ``max_retries`` attemps with increasing pauses.
+
+    If both path and logger are specified, more debugging information will be
+    printed in case of failure.
     """
     for i in xrange(max_retries):
         proc = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
@@ -611,4 +619,19 @@ def run_unmount_cmd(cmd, max_retries=10):
             raise RuntimeError('Unhandled error when running %r: %r' % (cmd, err))
         time.sleep(i)
     # Still busy, there's something wrong.
+    if path and logger:
+        commands = [
+            ['ls', '-lA', path],
+            ['fuser', '-vm', path],
+            ['lsof', '+D', path],
+        ]
+        for c in commands:
+            try:
+                proc = subprocess.Popen(c, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+                out, _ = proc.communicate()
+                logger.debug('`%s` exited with %s and following output:\n%s',
+                             ' '.join(c), proc.returncode, out)
+            except OSError:
+                logger.debug('`%s` command not available for debugging',
+                             ' '.join(c))
     raise RuntimeError('Failed to run %r: Device or resource busy.' % cmd)

tests/test_util.py

@@ -431,9 +431,9 @@ class TestTempFiles(unittest.TestCase):
 
 class TestUnmountCmd(unittest.TestCase):
 
-    def _fakeProc(self, ret, err):
+    def _fakeProc(self, ret, err='', out=''):
         proc = mock.Mock(returncode=ret)
-        proc.communicate.return_value = ('', err)
+        proc.communicate.return_value = (out, err)
         return proc
 
     @mock.patch('subprocess.Popen')
@@ -483,6 +483,41 @@ class TestUnmountCmd(unittest.TestCase):
                          [mock.call(0), mock.call(1), mock.call(2)])
         self.assertEqual(str(ctx.exception), "Failed to run 'unmount': Device or resource busy.")
 
+    @mock.patch('time.sleep')
+    @mock.patch('subprocess.Popen')
+    def test_fusermount_fail_then_retry_and_fail_with_debug(self, mockPopen, mock_sleep):
+        logger = mock.Mock()
+        mockPopen.side_effect = [self._fakeProc(1, 'Device or resource busy'),
+                                 self._fakeProc(1, 'Device or resource busy'),
+                                 self._fakeProc(1, 'Device or resource busy'),
+                                 self._fakeProc(0, out='list of files'),
+                                 self._fakeProc(0, out='It is very busy'),
+                                 self._fakeProc(1, out='lsof output')]
+        with self.assertRaises(RuntimeError) as ctx:
+            util.fusermount('/path', max_retries=3, logger=logger)
+        cmd = ['fusermount', '-u', '/path']
+        expected = [mock.call(cmd, stderr=subprocess.PIPE, stdout=subprocess.PIPE),
+                    mock.call(cmd, stderr=subprocess.PIPE, stdout=subprocess.PIPE),
+                    mock.call(cmd, stderr=subprocess.PIPE, stdout=subprocess.PIPE),
+                    mock.call(['ls', '-lA', '/path'],
+                              stderr=subprocess.STDOUT, stdout=subprocess.PIPE),
+                    mock.call(['fuser', '-vm', '/path'],
+                              stderr=subprocess.STDOUT, stdout=subprocess.PIPE),
+                    mock.call(['lsof', '+D', '/path'],
+                              stderr=subprocess.STDOUT, stdout=subprocess.PIPE)]
+        self.assertEqual(mockPopen.call_args_list, expected)
+        self.assertEqual(mock_sleep.call_args_list,
+                         [mock.call(0), mock.call(1), mock.call(2)])
+        self.assertEqual(str(ctx.exception),
+                         "Failed to run ['fusermount', '-u', '/path']: Device or resource busy.")
+        self.assertEqual(logger.mock_calls,
+                         [mock.call.debug('`%s` exited with %s and following output:\n%s',
+                                          'ls -lA /path', 0, 'list of files'),
+                          mock.call.debug('`%s` exited with %s and following output:\n%s',
+                                          'fuser -vm /path', 0, 'It is very busy'),
+                          mock.call.debug('`%s` exited with %s and following output:\n%s',
+                                          'lsof +D /path', 1, 'lsof output')])
+
 
 if __name__ == "__main__":
     unittest.main()