#3756 Add more logging to rmtree
Merged 11 months ago by tkopecek. Opened a year ago by mikem.
mikem/koji rmtree-debug  into  master

file modified
+12 -7
@@ -457,13 +457,15 @@ 

                  if e.errno in (errno.ENOENT, errno.ESTALE):

                      # likely racing with another rmtree

                      # if the dir doesn't exist, we're done

+                     logger.warning("Directory to remove has disappeared: %s" % path)

                      return

                  raise

              try:

-                 _rmtree(dev)

-             except _RetryRmtree:

+                 _rmtree(dev, logger)

+             except _RetryRmtree as e:

                  # reset and retry

                  os.chdir(cwd)

+                 logger.warning("Retrying rmtree due to %s" % e)

                  continue

              break

      finally:
@@ -477,7 +479,7 @@ 

              raise

  

  

- def _rmtree(dev):

+ def _rmtree(dev, logger):

      """Remove all contents of CWD"""

      # This implementation avoids forming long paths and recursion. Otherwise

      # we will have errors with very deep directory trees.
@@ -488,7 +490,7 @@ 

      # As we descend into the tree, we append a new entry to dirstack

      # When we ascend back up after removal, we pop them off

      while True:

-         dirs = _stripcwd(dev)

+         dirs = _stripcwd(dev, logger)

  

          # if cwd has no subdirs, walk back up until we find some

          while not dirs and dirstack:
@@ -507,11 +509,12 @@ 

              empty_dir = dirs.pop()

              try:

                  os.rmdir(empty_dir)

-             except OSError:

+             except OSError as e:

                  # If this happens, either something else is writing to the dir,

                  # or there is a bug in our code.

                  # For now, we ignore this and proceed, but we'll still fail at

                  # the top level rmdir

+                 logger.error("Unable to remove directory %s: %s" % (empty_dir, e))

                  pass

  

          if not dirs:
@@ -529,19 +532,21 @@ 

                  # we'll ignore this and continue

                  # since subdir doesn't exist, we'll pop it off and forget about it

                  dirs.pop()

+                 logger.warning("Subdir disappeared during rmtree %s: %s" % (subdir, e))

                  continue  # with dirstack unchanged

              raise

          dirstack.append(dirs)

  

  

- def _stripcwd(dev):

+ def _stripcwd(dev, logger):

      """Unlink all files in cwd and return list of subdirs"""

      dirs = []

      try:

          fdirs = os.listdir('.')

      except OSError as e:

-         # cwd has been removed by others, just return an empty list

          if e.errno in (errno.ENOENT, errno.ESTALE):

+             # cwd could have been removed by others, just return an empty list

+             logger.warning("Unable to read directory: %s" % e)

              return dirs

          raise

      for fn in fdirs:

file modified
+22 -13
@@ -1270,10 +1270,11 @@ 

          isdir.return_value = True

          getcwd.return_value = 'cwd'

          path = '/mnt/folder'

+         logger = mock.MagicMock()

  

-         self.assertEqual(koji.util.rmtree(path), None)

+         self.assertEqual(koji.util.rmtree(path, logger), None)

          chdir.assert_called_with('cwd')

-         _rmtree.assert_called_once_with('dev')

+         _rmtree.assert_called_once_with('dev', logger)

          rmdir.assert_called_once_with(path)

  

      @patch('koji.util._rmtree')
@@ -1303,10 +1304,11 @@ 

      def test_rmtree_internal_empty(self, stripcwd, rmdir, chdir):

          dev = 'dev'

          stripcwd.return_value = []

+         logger = mock.MagicMock()

  

-         koji.util._rmtree(dev)

+         koji.util._rmtree(dev, logger)

  

-         stripcwd.assert_called_once_with(dev)

+         stripcwd.assert_called_once_with(dev, logger)

          rmdir.assert_not_called()

          chdir.assert_not_called()

  
@@ -1316,10 +1318,11 @@ 

      def test_rmtree_internal_dirs(self, stripcwd, rmdir, chdir):

          dev = 'dev'

          stripcwd.side_effect = (['a', 'b'], [], [])

+         logger = mock.MagicMock()

  

-         koji.util._rmtree(dev)

+         koji.util._rmtree(dev, logger)

  

-         stripcwd.assert_has_calls([call(dev), call(dev), call(dev)])

+         stripcwd.assert_has_calls([call(dev, logger), call(dev, logger), call(dev, logger)])

          rmdir.assert_has_calls([call('b'), call('a')])

          chdir.assert_has_calls([call('b'), call('..'), call('a'), call('..')])

  
@@ -1330,11 +1333,12 @@ 

          dev = 'dev'

          stripcwd.side_effect = (['a', 'b'], [], [])

          rmdir.side_effect = OSError()

+         logger = mock.MagicMock()

  

          # don't fail on anything

-         koji.util._rmtree(dev)

+         koji.util._rmtree(dev, logger)

  

-         stripcwd.assert_has_calls([call(dev), call(dev), call(dev)])

+         stripcwd.assert_has_calls([call(dev, logger), call(dev, logger), call(dev, logger)])

          rmdir.assert_has_calls([call('b'), call('a')])

          chdir.assert_has_calls([call('b'), call('..'), call('a'), call('..')])

  
@@ -1346,8 +1350,9 @@ 

          # simple empty directory

          dev = 'dev'

          listdir.return_value = []

+         logger = mock.MagicMock()

  

-         koji.util._stripcwd(dev)

+         koji.util._stripcwd(dev, logger)

  

          listdir.assert_called_once_with('.')

          unlink.assert_not_called()
@@ -1367,8 +1372,9 @@ 

          st.st_mode = 'mode'

          lstat.return_value = st

          isdir.side_effect = [True, False]

+         logger = mock.MagicMock()

  

-         koji.util._stripcwd(dev)

+         koji.util._stripcwd(dev, logger)

  

          listdir.assert_called_once_with('.')

          unlink.assert_called_once_with('b')
@@ -1391,8 +1397,9 @@ 

          st2.st_mode = 'mode'

          lstat.side_effect = [st1, st2]

          isdir.side_effect = [True, False]

+         logger = mock.MagicMock()

  

-         koji.util._stripcwd(dev)

+         koji.util._stripcwd(dev, logger)

  

          listdir.assert_called_once_with('.')

          unlink.assert_not_called()
@@ -1413,8 +1420,9 @@ 

          lstat.return_value = st

          isdir.side_effect = [True, False]

          unlink.side_effect = OSError()

+         logger = mock.MagicMock()

  

-         koji.util._stripcwd(dev)

+         koji.util._stripcwd(dev, logger)

  

          listdir.assert_called_once_with('.')

          unlink.assert_called_once_with('b')
@@ -1430,8 +1438,9 @@ 

          dev = 'dev'

          listdir.return_value = ['will-not-exist.txt']

          lstat.side_effect = OSError(errno.ENOENT, 'No such file or directory')

+         logger = mock.MagicMock()

  

-         koji.util._stripcwd(dev)

+         koji.util._stripcwd(dev, logger)

  

          listdir.assert_called_once_with('.')

          lstat.assert_called_once_with('will-not-exist.txt')

Fixes: https://pagure.io/koji/issue/3815

Related: https://pagure.io/koji/issue/3755

There are a number of odd situations that rmtree can encounter that are worth logging. This will likely help debug #3755

Metadata Update from @mikem:
- Pull-request tagged with: testing-ready

11 months ago

Metadata Update from @mfilip:
- Pull-request tagged with: testing-done

11 months ago

Commit 70c9b3e fixes this pull-request

Pull-Request has been merged by tkopecek

11 months ago