Repository: Azure/WALinuxAgent
Pull request #2639 (2022-08-01 22:54:46)

Cleanup history directory when creating new subdirectories (#2633)
* Cleanup history directory when creating new subdirectories

* Review feedback

Co-authored-by: narrieta <narrieta>
(cherry picked from commit ac56d0e1395db01e23c5e4a3aeefcc702752dd84)



codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) Report
> Merging [#2639](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (193a46a) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/4db3b44f0271f2ed825b001c2bdf4725fdcd1f72?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (4db3b44) will **decrease** coverage by `0.05%`.
> The diff coverage is `68.42%`.

```diff
@@             Coverage Diff             @@
##           develop    #2639      +/-   ##
===========================================
- Coverage    71.96%   71.91%   -0.06%     
===========================================
  Files          103      103              
  Lines        15632    15654      +22     
  Branches      2488     2494       +6     
===========================================
+ Hits         11250    11258       +8     
- Misses        3868     3880      +12     
- Partials       514      516       +2     
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/protocol/wire.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9wcm90b2NvbC93aXJlLnB5) | `78.57% <60.00%> (-0.26%)` | :arrow_down: |
| [azurelinuxagent/common/utils/archive.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi91dGlscy9hcmNoaXZlLnB5) | `81.71% <65.38%> (-6.53%)` | :arrow_down: |
| [azurelinuxagent/common/protocol/goal\_state.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9wcm90b2NvbC9nb2FsX3N0YXRlLnB5) | `95.81% <80.00%> (ø)` | |
| [azurelinuxagent/ga/update.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL3VwZGF0ZS5weQ==) | `89.34% <100.00%> (-0.01%)` | :arrow_down: |
| [azurelinuxagent/common/logger.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2639/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9sb2dnZXIucHk=) | `90.96% <0.00%> (+1.12%)` | :arrow_up: |

Help us with your feedback. Take ten seconds to tell us [how you rate us](https://about.codecov.io/nps?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).


Patch:
diff --git a/azurelinuxagent/common/protocol/goal_state.py b/azurelinuxagent/common/protocol/goal_state.py
index 8b508f61..4d354e56 100644
--- a/azurelinuxagent/common/protocol/goal_state.py
+++ b/azurelinuxagent/common/protocol/goal_state.py
@@ -352,12 +352,12 @@ class GoalState(object):
             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 @@ class SharedConfig(object):
 
 
 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 @@ class Certificates(object):
         # 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())
diff --git a/azurelinuxagent/common/protocol/wire.py b/azurelinuxagent/common/protocol/wire.py
index a57355e0..b8b05c98 100644
--- a/azurelinuxagent/common/protocol/wire.py
+++ b/azurelinuxagent/common/protocol/wire.py
@@ -767,7 +767,7 @@ class WireClient(object):
         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 @@ class WireClient(object):
 
         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
 
diff --git a/azurelinuxagent/common/utils/archive.py b/azurelinuxagent/common/utils/archive.py
index 0be1544c..b624d174 100644
--- a/azurelinuxagent/common/utils/archive.py
+++ b/azurelinuxagent/common/utils/archive.py
@@ -162,17 +162,6 @@ class StateArchiver(object):
                 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 @@ class GoalStateHistory(object):
         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 @@ class GoalStateHistory(object):
                 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():
         """
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index e373e639..c9887543 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -639,9 +639,9 @@ class UpdateHandler(object):
             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:
@@ -649,10 +649,9 @@ class UpdateHandler(object):
                 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))


Test patch:
diff --git a/tests/utils/test_archive.py b/tests/utils/test_archive.py
index 5eee67c7..ce97d65f 100644
--- a/tests/utils/test_archive.py
+++ b/tests/utils/test_archive.py
@@ -6,8 +6,9 @@ import zipfile
 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 @@ class TestArchive(AgentTestCase):
         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 @@ class TestArchive(AgentTestCase):
 
     @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 @@ class TestArchive(AgentTestCase):
                 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 @@ class TestArchive(AgentTestCase):
 
         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 @@ class TestArchive(AgentTestCase):
 
         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 @@ class TestArchive(AgentTestCase):
             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):