Cleanup history directory when creating new subdirectories (#2633)

* Cleanup history directory when creating new subdirectories

* Review feedback

Co-authored-by: narrieta <narrieta>

azurelinuxagent/common/protocol/goal_state.py

@@ -352,12 +352,12 @@ def _fetch_full_wire_server_goal_state(self, incarnation, xml_doc):
             certs_uri = findtext(xml_doc, "Certificates")
             if certs_uri is not None:
                 xml_text = self._wire_client.fetch_config(certs_uri, self._wire_client.get_header_for_cert())
-                certs = Certificates(xml_text)
+                certs = Certificates(xml_text, self.logger)
                 # Log and save the certificates summary (i.e. the thumbprint but not the certificate itself) to the goal state history
                 for c in certs.summary:
-                    logger.info("Downloaded certificate {0}".format(c))
+                    self.logger.info("Downloaded certificate {0}".format(c))
                 if len(certs.warnings) > 0:
-                    logger.warn(certs.warnings)
+                    self.logger.warn(certs.warnings)
                 self._history.save_certificates(json.dumps(certs.summary))
 
             remote_access = None
@@ -403,7 +403,7 @@ def __init__(self, xml_text):
 
 
 class Certificates(object):
-    def __init__(self, xml_text):
+    def __init__(self, xml_text, my_logger):
         self.cert_list = CertList()
         self.summary = []  # debugging info
         self.warnings = []
@@ -421,7 +421,7 @@ def __init__(self, xml_text):
         # if the certificates format is not Pkcs7BlobWithPfxContents do not parse it
         certificateFormat = findtext(xml_doc, "Format")
         if certificateFormat and certificateFormat != "Pkcs7BlobWithPfxContents":
-            logger.warn("The Format is not Pkcs7BlobWithPfxContents. Format is " + certificateFormat)
+            my_logger.warn("The Format is not Pkcs7BlobWithPfxContents. Format is " + certificateFormat)
             return
 
         cryptutil = CryptUtil(conf.get_openssl_cmd())

azurelinuxagent/common/protocol/wire.py

@@ -767,7 +767,7 @@ def update_goal_state(self, force_update=False, silent=False):
         Updates the goal state if the incarnation or etag changed or if 'force_update' is True
         """
         try:
-            if force_update:
+            if force_update and not silent:
                 logger.info("Forcing an update of the goal state.")
 
             if self._goal_state is None or force_update:
@@ -970,11 +970,13 @@ def upload_status_blob(self):
 
         if extensions_goal_state.status_upload_blob is None:
             # the status upload blob is in ExtensionsConfig so force a full goal state refresh
-            self.update_goal_state(force_update=True)
+            self.update_goal_state(force_update=True, silent=True)
             extensions_goal_state = self.get_goal_state().extensions_goal_state
 
-        if extensions_goal_state.status_upload_blob is None:
-            raise ProtocolNotFoundError("Status upload uri is missing")
+            if extensions_goal_state.status_upload_blob is None:
+                raise ProtocolNotFoundError("Status upload uri is missing")
+
+            logger.info("Refreshed the goal state to get the status upload blob. New Goal State ID: {0}", extensions_goal_state.id)
 
         blob_type = extensions_goal_state.status_upload_blob_type
 

azurelinuxagent/common/utils/archive.py

@@ -162,17 +162,6 @@ def __init__(self, lib_dir):
                 if exception.errno != errno.EEXIST:
                     logger.warn("{0} : {1}", self._source, exception.strerror)
 
-    def purge(self):
-        """
-        Delete "old" archive directories and .zip archives.  Old
-        is defined as any directories or files older than the X
-        newest ones. Also, clean up any legacy history files.
-        """
-        states = self._get_archive_states()
-
-        for state in states[_MAX_ARCHIVED_STATES:]:
-            state.delete()
-
     @staticmethod
     def purge_legacy_goal_state_history():
         lib_dir = conf.get_lib_dir()
@@ -222,6 +211,8 @@ def __init__(self, time, tag):
         timestamp = timeutil.create_history_timestamp(time)
         self._root = os.path.join(conf.get_lib_dir(), ARCHIVE_DIRECTORY_NAME, "{0}__{1}".format(timestamp, tag) if tag is not None else timestamp)
 
+        GoalStateHistory._purge()
+
     @staticmethod
     def tag_exists(tag):
         """
@@ -240,6 +231,44 @@ def save(self, data, file_name):
                 self._errors = True
                 logger.warn("Failed to save {0} to the goal state history: {1} [no additional errors saving the goal state will be reported]".format(file_name, e))
 
+    _purge_error_count = 0
+
+    @staticmethod
+    def _purge():
+        """
+        Delete "old" history directories and .zip archives. Old is defined as any directories or files older than the X newest ones.
+        """
+        try:
+            history_root = os.path.join(conf.get_lib_dir(), ARCHIVE_DIRECTORY_NAME)
+
+            if not os.path.exists(history_root):
+                return
+
+            items = []
+            for current_item in os.listdir(history_root):
+                full_path = os.path.join(history_root, current_item)
+                items.append(full_path)
+            items.sort(key=os.path.getctime, reverse=True)
+
+            for current_item in items[_MAX_ARCHIVED_STATES:]:
+                if os.path.isfile(current_item):
+                    os.remove(current_item)
+                else:
+                    shutil.rmtree(current_item)
+
+            if GoalStateHistory._purge_error_count > 0:
+                GoalStateHistory._purge_error_count = 0
+                # Log a success message when we are recovering from errors.
+                logger.info("Successfully cleaned up the goal state history directory")
+
+        except Exception as e:
+            GoalStateHistory._purge_error_count += 1
+            if GoalStateHistory._purge_error_count < 5:
+                logger.warn("Failed to clean up the goal state history directory: {0}".format(e))
+            elif GoalStateHistory._purge_error_count == 5:
+                logger.warn("Failed to clean up the goal state history directory [will stop reporting these errors]: {0}".format(e))
+
+
     @staticmethod
     def _save_placeholder():
         """

azurelinuxagent/ga/update.py

@@ -635,20 +635,19 @@ def _process_goal_state(self, exthandlers_handler, remote_access_handler):
             if self._processing_new_incarnation():
                 remote_access_handler.run()
 
-            # lastly, cleanup the goal state history (but do it only on new goal states - no need to do it on every iteration)
+            # lastly, archive the goal state history (but do it only on new goal states - no need to do it on every iteration)
             if self._processing_new_extensions_goal_state():
-                UpdateHandler._cleanup_goal_state_history()
+                UpdateHandler._archive_goal_state_history()
 
         finally:
             if self._goal_state is not None:
                 self._last_incarnation = self._goal_state.incarnation
                 self._last_extensions_gs_id = self._goal_state.extensions_goal_state.id
 
     @staticmethod
-    def _cleanup_goal_state_history():
+    def _archive_goal_state_history():
         try:
             archiver = StateArchiver(conf.get_lib_dir())
-            archiver.purge()
             archiver.archive()
         except Exception as exception:
             logger.warn("Error cleaning up the goal state history: {0}", ustr(exception))

tests/utils/test_archive.py

@@ -6,8 +6,9 @@
 from datetime import datetime, timedelta
 
 import azurelinuxagent.common.logger as logger
+from azurelinuxagent.common import conf
 from azurelinuxagent.common.utils import fileutil, timeutil
-from azurelinuxagent.common.utils.archive import StateArchiver, _MAX_ARCHIVED_STATES
+from azurelinuxagent.common.utils.archive import GoalStateHistory, StateArchiver, _MAX_ARCHIVED_STATES, ARCHIVE_DIRECTORY_NAME
 from tests.tools import AgentTestCase, patch
 
 debug = False
@@ -28,7 +29,7 @@ def setUp(self):
         self.tmp_dir = tempfile.mkdtemp(prefix=prefix)
 
     def _write_file(self, filename, contents=None):
-        full_name = os.path.join(self.tmp_dir, filename)
+        full_name = os.path.join(conf.get_lib_dir(), filename)
         fileutil.mkdir(os.path.dirname(full_name))
 
         with open(full_name, 'w') as file_handler:
@@ -38,7 +39,7 @@ def _write_file(self, filename, contents=None):
 
     @property
     def history_dir(self):
-        return os.path.join(self.tmp_dir, 'history')
+        return os.path.join(conf.get_lib_dir(), ARCHIVE_DIRECTORY_NAME)
 
     @staticmethod
     def _parse_archive_name(name):
@@ -66,7 +67,7 @@ def test_archive_should_zip_all_but_the_latest_goal_state_in_the_history_folder(
                 self._write_file(os.path.join(directory, current_file))
             test_directories.append(directory)
 
-        test_subject = StateArchiver(self.tmp_dir)
+        test_subject = StateArchiver(conf.get_lib_dir())
         # NOTE: StateArchiver sorts the state directories by creation time, but the test files are created too fast and the
         # time resolution is too coarse, so instead we mock getctime to simply return the path of the file
         with patch("azurelinuxagent.common.utils.archive.os.path.getctime", side_effect=lambda path: path):
@@ -83,9 +84,9 @@ def test_archive_should_zip_all_but_the_latest_goal_state_in_the_history_folder(
 
         self.assertTrue(os.path.exists(test_directories[2]), "{0}, the latest goal state, should not have being removed".format(test_directories[2]))
 
-    def test_archive02(self):
+    def test_goal_state_history_init_should_purge_old_items(self):
         """
-        StateArchiver should purge the MAX_ARCHIVED_STATES oldest files
+        GoalStateHistory.__init__ should _purge the MAX_ARCHIVED_STATES oldest files
         or directories.  The oldest timestamps are purged first.
 
         This test case creates a mixture of archive files and directories.
@@ -112,11 +113,10 @@ def test_archive02(self):
 
         self.assertEqual(total, len(os.listdir(self.history_dir)))
 
-        test_subject = StateArchiver(self.tmp_dir)
-        # NOTE: StateArchiver sorts the state directories by creation time, but the test files are created too fast and the
+        # NOTE: The purge method sorts the items by creation time, but the test files are created too fast and the
         # time resolution is too coarse, so instead we mock getctime to simply return the path of the file
         with patch("azurelinuxagent.common.utils.archive.os.path.getctime", side_effect=lambda path: path):
-            test_subject.purge()
+            GoalStateHistory(datetime.utcnow(), 'test')
 
         archived_entries = os.listdir(self.history_dir)
         self.assertEqual(_MAX_ARCHIVED_STATES, len(archived_entries))
@@ -153,46 +153,6 @@ def test_purge_legacy_goal_state_history(self):
             for f in legacy_files:
                 self.assertFalse(os.path.exists(f), "Legacy file {0} was not removed".format(f))
 
-    def test_archive03(self):
-        """
-        All archives should be purged, both with the legacy naming (with incarnation number) and with the new naming.
-        """
-        start = datetime.now()
-        timestamp1 = start + timedelta(seconds=5)
-        timestamp2 = start + timedelta(seconds=10)
-        timestamp3 = start + timedelta(seconds=10)
-
-        dir_old = timestamp1.isoformat()
-        dir_new = "{0}_incarnation_1".format(timestamp2.isoformat())
-
-        archive_old = "{0}.zip".format(timestamp1.isoformat())
-        archive_new = "{0}_incarnation_1.zip".format(timestamp2.isoformat())
-
-        status = "{0}.zip".format(timestamp3.isoformat())
-
-        self._write_file(os.path.join("history", dir_old, "Prod.manifest.xml"))
-        self._write_file(os.path.join("history", dir_new, "Prod.manifest.xml"))
-        self._write_file(os.path.join("history", archive_old))
-        self._write_file(os.path.join("history", archive_new))
-        self._write_file(os.path.join("history", status))
-
-        self.assertEqual(5, len(os.listdir(self.history_dir)), "Not all entries were archived!")
-
-        test_subject = StateArchiver(self.tmp_dir)
-        with patch("azurelinuxagent.common.utils.archive._MAX_ARCHIVED_STATES", 0):
-            test_subject.purge()
-
-        archived_entries = os.listdir(self.history_dir)
-        self.assertEqual(0, len(archived_entries), "Not all entries were purged!")
-
-    def test_archive04(self):
-        """
-        The archive directory is created if it does not exist.
-
-        This failure was caught when .purge() was called before .archive().
-        """
-        test_subject = StateArchiver(os.path.join(self.tmp_dir, 'does-not-exist'))
-        test_subject.purge()
 
     @staticmethod
     def parse_isoformat(timestamp_str):