From f0dc15bdc6f5ba62d33084ee871422973bac5238 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Lubom=C3=ADr=20Sedl=C3=A1=C5=99?= Date: Tue, 14 Mar 2017 10:29:53 +0100 Subject: [PATCH] buildinstall: Print debug info if unmount fails MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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ář --- pungi/phases/buildinstall.py | 4 ++-- pungi/util.py | 25 ++++++++++++++++++++++- tests/test_util.py | 39 ++++++++++++++++++++++++++++++++++-- 3 files changed, 63 insertions(+), 5 deletions(-) diff --git a/pungi/phases/buildinstall.py b/pungi/phases/buildinstall.py index b10384de..abf83382 100644 --- a/pungi/phases/buildinstall.py +++ b/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 diff --git a/pungi/util.py b/pungi/util.py index f98893d4..665eb734 100644 --- a/pungi/util.py +++ b/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) diff --git a/tests/test_util.py b/tests/test_util.py index 108b57cc..9af308ab 100644 --- a/tests/test_util.py +++ b/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()