From a66190258fe11f519df3282a51c5698c7bf37e33 Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 15 2025 18:44:22 +0000 Subject: [PATCH 1/6] addition checks/logging in ensuredir --- diff --git a/koji/__init__.py b/koji/__init__.py index c9a657e..0f85de7 100644 --- a/koji/__init__.py +++ b/koji/__init__.py @@ -566,15 +566,32 @@ def ensuredir(directory): if head: ensuredir(head) # note: if head is blank, then we've reached the top of a relative path + logger = logging.getLogger('koji') try: os.mkdir(directory) except OSError: - # do not thrown when dir already exists (could happen in a race) - if not os.path.isdir(directory): - # something else must have gone wrong + # do not throw when dir already exists (could happen in a race) + st = _lstat(directory) + if st is None: + logger.error('Failed to create directory: %s', directory) raise + elif not stat.S_ISDIR(st.st_mode): + logger.error('Exists, but not a directory: %s (mode=0%o)', directory, st.st_mode) + raise + else: + logger.warning('Directory already exists: %s', directory) + # no error return directory + +def _lstat(path): + # os.lstat, but returns None if file does not exist + try: + return os.lstat(fn) + except FileNotFoundError: + return None + + # END kojikamid dup # From 1220cea66d43204812d7617c261fe072ceac3b34 Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 15 2025 18:45:22 +0000 Subject: [PATCH 2/6] ... --- diff --git a/koji/__init__.py b/koji/__init__.py index 0f85de7..e22e075 100644 --- a/koji/__init__.py +++ b/koji/__init__.py @@ -587,7 +587,7 @@ def ensuredir(directory): def _lstat(path): # os.lstat, but returns None if file does not exist try: - return os.lstat(fn) + return os.lstat(path) except FileNotFoundError: return None From 306fbddd2337cf8735dd3a6c7632380a1b77e198 Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 15 2025 18:51:42 +0000 Subject: [PATCH 3/6] adjust unit test mocks --- diff --git a/koji/__init__.py b/koji/__init__.py index e22e075..fd21237 100644 --- a/koji/__init__.py +++ b/koji/__init__.py @@ -38,6 +38,7 @@ import pwd import random import re import socket +import stat import struct import sys import tempfile diff --git a/tests/test_lib/test_file_ops.py b/tests/test_lib/test_file_ops.py index 23de1b3..d1bb66e 100644 --- a/tests/test_lib/test_file_ops.py +++ b/tests/test_lib/test_file_ops.py @@ -12,10 +12,11 @@ from koji import ensuredir class TestEnsureDir(unittest.TestCase): + @mock.patch('os.lstat') @mock.patch('os.mkdir') @mock.patch('os.path.exists') - @mock.patch('os.path.isdir') - def test_ensuredir_errors(self, mock_isdir, mock_exists, mock_mkdir): + @mock.patch('stat.S_ISDIR') + def test_ensuredir_errors(self, mock_isdir, mock_exists, mock_mkdir, mock_lstat): mock_exists.return_value = False with self.assertRaises(OSError) as cm: ensuredir('/') From 0c077e7b80ed4a3326c87107e1889bada75d64e5 Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 18 2025 18:35:50 +0000 Subject: [PATCH 4/6] more debug checks --- diff --git a/koji/__init__.py b/koji/__init__.py index fd21237..252d2dc 100644 --- a/koji/__init__.py +++ b/koji/__init__.py @@ -575,7 +575,24 @@ def ensuredir(directory): st = _lstat(directory) if st is None: logger.error('Failed to create directory: %s', directory) - raise + # more debug checks + if head: + siblings = _listdir(head) + if not siblings: + logger.error('Unable to read parent dir: %s', head) + elif tail in siblings: + logger.error('Missing dir %s appears in parent listdir', directory) + # does listdir work any better than lstat? + contents = _listdir(directory) + if contents is not None: + logger.error('Missing dir can be listed: %s', directory) + # do we get the same error on retry? + try: + os.mkdir(directory) + except OSError: + logger.error('Second mkdir failed for %s', directory) + raise + logger.warning('Second mkdir succeeded for %s', directory) elif not stat.S_ISDIR(st.st_mode): logger.error('Exists, but not a directory: %s (mode=0%o)', directory, st.st_mode) raise @@ -593,6 +610,14 @@ def _lstat(path): return None +def _listdir(path): + # os.listdir, but returns None if dir does not exist + try: + return os.listdir(path) + except FileNotFoundError: + return None + + # END kojikamid dup # From d821e1f092c86f52480f96533e87de58d6a6a8cd Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 18 2025 19:14:33 +0000 Subject: [PATCH 5/6] unit tests to validate the debug code --- diff --git a/tests/test_lib/test_file_ops.py b/tests/test_lib/test_file_ops.py index d1bb66e..534847f 100644 --- a/tests/test_lib/test_file_ops.py +++ b/tests/test_lib/test_file_ops.py @@ -56,3 +56,69 @@ class TestEnsureDir(unittest.TestCase): self.assertEqual(mock_isdir.call_count, 1) mock_mkdir.assert_has_calls([mock.call('/path/foo'), mock.call('/path/foo/bar')]) + + +class TestEnsureDirRace(unittest.TestCase): + + def setUp(self): + self.lstat = mock.patch('os.lstat').start() + self.mkdir = mock.patch('os.mkdir').start() + self.exists = mock.patch('os.path.exists').start() + self.isdir = mock.patch('stat.S_ISDIR').start() + self._listdir = mock.patch('koji._listdir').start() + + def tearDown(self): + mock.patch.stopall() + + def test_ensuredir_errors2(self): + self.exists.return_value = False + self.isdir.return_value = False + self.lstat.side_effect = OSError(errno.ENOENT, 'error msg') + self.mkdir.side_effect = OSError(errno.EEXIST, 'error msg') + self._listdir.side_effect = None + with self.assertRaises(OSError) as cm: + ensuredir('path') + self.assertEqual(cm.exception.args[0], errno.EEXIST) + + def test_ensuredir_error_listdir_works(self): + self.exists.return_value = False + self.isdir.return_value = False + self.lstat.side_effect = OSError(errno.ENOENT, 'error msg') + self.mkdir.side_effect = OSError(errno.EEXIST, 'error msg') + self._listdir.side_effect = [[]] + with self.assertRaises(OSError) as cm: + ensuredir('path') + self.assertEqual(cm.exception.args[0], errno.EEXIST) + + def test_ensuredir_error_not_in_parent(self): + self.exists.return_value = False + self.isdir.return_value = False + self.lstat.side_effect = OSError(errno.ENOENT, 'error msg') + self.mkdir.side_effect = [None, OSError(errno.EEXIST, 'error msg'), OSError(errno.EEXIST, 'error msg')] + # mkdir for parent succeeds, but fails for child (and retry) + self._listdir.side_effect = [[], []] + with self.assertRaises(OSError) as cm: + ensuredir('parent/path') + self.assertEqual(cm.exception.args[0], errno.EEXIST) + + def test_ensuredir_error_in_parent(self): + self.exists.return_value = False + self.isdir.return_value = False + self.lstat.side_effect = OSError(errno.ENOENT, 'error msg') + self.mkdir.side_effect = [None, OSError(errno.EEXIST, 'error msg'), OSError(errno.EEXIST, 'error msg')] + # mkdir for parent succeeds, but fails for child (and retry) + self._listdir.side_effect = [['path'], []] + with self.assertRaises(OSError) as cm: + ensuredir('parent/path') + self.assertEqual(cm.exception.args[0], errno.EEXIST) + + def test_ensuredir_retry_works(self): + self.exists.return_value = False + self.isdir.return_value = False + self.lstat.side_effect = OSError(errno.ENOENT, 'error msg') + self.mkdir.side_effect = [OSError(errno.EEXIST, 'error msg'), None] + self._listdir.side_effect = [None] + ensuredir('path') + + +# the end From 64bcf618fd1174ed3fa2f64d7abbb8685fc527f3 Mon Sep 17 00:00:00 2001 From: Mike McLean Date: Jul 18 2025 19:37:55 +0000 Subject: [PATCH 6/6] also log some times --- diff --git a/koji/__init__.py b/koji/__init__.py index 252d2dc..5bfd80f 100644 --- a/koji/__init__.py +++ b/koji/__init__.py @@ -554,6 +554,7 @@ def ensuredir(directory): :raises OSError: If argument already exists and is not a directory, or error occurs from underlying `os.mkdir`. """ + start_ts = time.time() directory = os.path.normpath(directory) if os.path.exists(directory): if not os.path.isdir(directory): @@ -568,10 +569,15 @@ def ensuredir(directory): ensuredir(head) # note: if head is blank, then we've reached the top of a relative path logger = logging.getLogger('koji') + pre_mkdir_ts = time.time() try: os.mkdir(directory) except OSError: # do not throw when dir already exists (could happen in a race) + error_ts = time.time() + total_ms = (error_ts - start_ts) * 1000 + mkdir_ms = (error_ts - pre_mkdir_ts) * 1000 + logger.warning('mkdir failed after %.3f ms, %.3f since start', mkdir_ms, total_ms) st = _lstat(directory) if st is None: logger.error('Failed to create directory: %s', directory)