Repository: Azure/WALinuxAgent
Pull request #2508 (2022-02-14 22:42:37)

Cleanup history directory after every goal state
There was a race condition between the env thread cleaning up the history folder and the GoalState writing to it.

Cleaning up the history folder on a separate thread was done just for legacy reasons, but  there is no good motivation to keep it that way. I moved it to the main thread, cleaning up after each goal state.



codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) Report
> Merging [#2508](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (0eedbb4) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/daad9fb4486f26b8729d7333c134eb810c501f0b?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (daad9fb) will **increase** coverage by `0.01%`.
> The diff coverage is `86.66%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/graphs/tree.svg?width=650&height=150&src=pr&token=ae90E2KYCw&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)

```diff
@@             Coverage Diff             @@
##           develop    #2508      +/-   ##
===========================================
+ Coverage    71.84%   71.85%   +0.01%     
===========================================
  Files          101      101              
  Lines        15080    15093      +13     
  Branches      2392     2393       +1     
===========================================
+ Hits         10834    10845      +11     
  Misses        3763     3763              
- Partials       483      485       +2     
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/conf.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9jb25mLnB5) | `79.31% <ø> (+0.25%)` | :arrow_up: |
| [azurelinuxagent/ga/env.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2Vudi5weQ==) | `61.53% <ø> (+0.61%)` | :arrow_up: |
| [azurelinuxagent/ga/update.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL3VwZGF0ZS5weQ==) | `88.58% <77.77%> (-0.20%)` | :arrow_down: |
| [azurelinuxagent/common/utils/archive.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi91dGlscy9hcmNoaXZlLnB5) | `88.73% <100.00%> (+4.06%)` | :arrow_up: |
| [azurelinuxagent/ga/exthandlers.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2V4dGhhbmRsZXJzLnB5) | `85.82% <100.00%> (ø)` | |
| [azurelinuxagent/ga/collect\_telemetry\_events.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2NvbGxlY3RfdGVsZW1ldHJ5X2V2ZW50cy5weQ==) | `89.72% <0.00%> (-1.72%)` | :arrow_down: |
| [azurelinuxagent/common/event.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9ldmVudC5weQ==) | `85.36% <0.00%> (-0.68%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure). Last update [daad9fb...0eedbb4](https://codecov.io/gh/Azure/WALinuxAgent/pull/2508?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).


Patch:
diff --git a/README.md b/README.md
index c69f43e6..a1bfab5a 100644
--- a/README.md
+++ b/README.md
@@ -177,7 +177,6 @@ A sample configuration file is shown below:
 ```yml
 Extensions.Enabled=y
 Extensions.GoalStatePeriod=6
-Extensions.GoalStateHistoryCleanupPeriod=1800
 Provisioning.Agent=auto
 Provisioning.DeleteRootPassword=n
 Provisioning.RegenerateSshHostKeyPair=y
@@ -243,15 +242,6 @@ _Note_: setting up this parameter to more than a few minutes can make the state
 the VM be reported as unresponsive/unavailable on the Azure portal. Also, this 
 setting affects how fast the agent starts executing extensions. 
 
-#### __Extensions.GoalStateHistoryCleanupPeriod__
-
-_Type: Integer_  
-_Default: 1800 (30 minutes)_
-
-How often to clean up the history folder of the agent. The agent keeps past goal
-states on this folder, each goal state represented with a set of small files. The
-history is useful to debug issues in the agent or extensions.
- 
 #### __AutoUpdate.Enabled__
 
 _Type: Boolean_  
diff --git a/azurelinuxagent/common/conf.py b/azurelinuxagent/common/conf.py
index f733663d..daf9d0e5 100644
--- a/azurelinuxagent/common/conf.py
+++ b/azurelinuxagent/common/conf.py
@@ -168,7 +168,6 @@ __STRING_OPTIONS__ = {
 __INTEGER_OPTIONS__ = {
     "Extensions.GoalStatePeriod": 6,
     "Extensions.InitialGoalStatePeriod": 6,
-    "Extensions.GoalStateHistoryCleanupPeriod": 1800,
     "OS.EnableFirewallPeriod": 300,
     "OS.RemovePersistentNetRulesPeriod": 30,
     "OS.RootDeviceScsiTimeoutPeriod": 30,
@@ -377,10 +376,6 @@ def get_initial_goal_state_period(conf=__conf__):
     return conf.get_int("Extensions.InitialGoalStatePeriod", default_value=lambda: get_goal_state_period(conf=conf))
 
 
-def get_goal_state_history_cleanup_period(conf=__conf__):
-    return conf.get_int("Extensions.GoalStateHistoryCleanupPeriod", 1800)
-
-
 def get_allow_reset_sys_user(conf=__conf__):
     return conf.get_switch("Provisioning.AllowResetSysUser", False)
 
diff --git a/azurelinuxagent/common/utils/archive.py b/azurelinuxagent/common/utils/archive.py
index 7c081c81..b40da796 100644
--- a/azurelinuxagent/common/utils/archive.py
+++ b/azurelinuxagent/common/utils/archive.py
@@ -44,7 +44,10 @@ _CACHE_PATTERNS = [
     re.compile(r"^VmSettings.\d+\.json$"),
     re.compile(r"^(.*)\.(\d+)\.(agentsManifest)$", re.IGNORECASE),
     re.compile(r"^(.*)\.(\d+)\.(manifest\.xml)$", re.IGNORECASE),
-    re.compile(r"^(.*)\.(\d+)\.(xml)$", re.IGNORECASE)
+    re.compile(r"^(.*)\.(\d+)\.(xml)$", re.IGNORECASE),
+    re.compile(r"^SharedConfig\.xml$", re.IGNORECASE),
+    re.compile(r"^HostingEnvironmentConfig\.xml$", re.IGNORECASE),
+    re.compile(r"^RemoteAccess\.xml$", re.IGNORECASE)
 ]
 
 #
@@ -59,8 +62,8 @@ _CACHE_PATTERNS = [
 #   2018-04-06T08:21:37.142697_N
 #   2018-04-06T08:21:37.142697_N.zip
 #
-_ARCHIVE_PATTERNS_DIRECTORY = re.compile(r"^\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d+((_incarnation)?_(\d+))?$")
-_ARCHIVE_PATTERNS_ZIP = re.compile(r"^\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d+((_incarnation)?_(\d+))?\.zip$")
+_ARCHIVE_PATTERNS_DIRECTORY = re.compile(r"^\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d+((_incarnation)?_(\d+|status))?$")
+_ARCHIVE_PATTERNS_ZIP = re.compile(r"^\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d+((_incarnation)?_(\d+|status))?\.zip$")
 
 _GOAL_STATE_FILE_NAME = "GoalState.xml"
 _VM_SETTINGS_FILE_NAME = "VmSettings.json"
@@ -161,9 +164,11 @@ class StateArchiver(object):
         for state in states[_MAX_ARCHIVED_STATES:]:
             state.delete()
 
-        # legacy history files
-        for current_file in os.listdir(self._source):
-            full_path = os.path.join(self._source, current_file)
+    @staticmethod
+    def purge_legacy_goal_state_history():
+        lib_dir = conf.get_lib_dir()
+        for current_file in os.listdir(lib_dir):
+            full_path = os.path.join(lib_dir, current_file)
             for pattern in _CACHE_PATTERNS:
                 match = pattern.match(current_file)
                 if match is not None:
@@ -175,8 +180,12 @@ class StateArchiver(object):
 
     def archive(self):
         states = self._get_archive_states()
-        for state in states:
-            state.archive()
+        states.sort(reverse=True)
+
+        if len(states) > 0:
+            # Skip the most recent goal state, since it may still be in use
+            for state in states[1:]:
+                state.archive()
 
     def _get_archive_states(self):
         states = []
diff --git a/azurelinuxagent/ga/env.py b/azurelinuxagent/ga/env.py
index 771f4765..5e170593 100644
--- a/azurelinuxagent/ga/env.py
+++ b/azurelinuxagent/ga/env.py
@@ -31,7 +31,6 @@ from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.interfaces import ThreadHandlerInterface
 from azurelinuxagent.common.osutil import get_osutil
 from azurelinuxagent.common.protocol.util import get_protocol_util
-from azurelinuxagent.common.utils.archive import StateArchiver
 from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION
 from azurelinuxagent.ga.periodic_operation import PeriodicOperation
 
@@ -99,19 +98,6 @@ class MonitorDhcpClientRestart(PeriodicOperation):
         return pid
 
 
-class CleanupGoalStateHistory(PeriodicOperation):
-    def __init__(self):
-        super(CleanupGoalStateHistory, self).__init__(conf.get_goal_state_history_cleanup_period())
-        self.archiver = StateArchiver(conf.get_lib_dir())
-
-    def _operation(self):
-        """
-        Purge history and create a .zip of the history that has been preserved.
-        """
-        self.archiver.purge()
-        self.archiver.archive()
-
-
 class EnableFirewall(PeriodicOperation):
     def __init__(self, osutil, protocol):
         super(EnableFirewall, self).__init__(conf.get_enable_firewall_period())
@@ -239,7 +225,6 @@ class EnvHandler(ThreadHandlerInterface):
             periodic_operations = [
                 RemovePersistentNetworkRules(osutil),
                 MonitorDhcpClientRestart(osutil),
-                CleanupGoalStateHistory()
             ]
 
             if conf.enable_firewall():
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index 49eb4cf0..8e35bf58 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -965,7 +965,7 @@ class ExtHandlersHandler(object):
             # On new goal state, move the last status report for the previous goal state to the history folder
             last_modified = os.path.getmtime(status_file)
             timestamp = datetime.datetime.utcfromtimestamp(last_modified).isoformat()
-            GoalStateHistory(timestamp).save_status_file(status_file)
+            GoalStateHistory(timestamp, "status").save_status_file(status_file)
 
         # Now create/overwrite the status file; this file is kept for debugging purposes only
         status_blob_text = self.protocol.get_status_blob_data()
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index f389c5cf..f5785bc4 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -50,6 +50,7 @@ from azurelinuxagent.common.protocol.restapi import VMAgentUpdateStatus, VMAgent
     VERSION_0
 from azurelinuxagent.common.protocol.util import get_protocol_util
 from azurelinuxagent.common.utils import shellutil
+from azurelinuxagent.common.utils.archive import StateArchiver
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.utils.networkutil import AddFirewallRules
 from azurelinuxagent.common.utils.shellutil import CommandError
@@ -395,6 +396,8 @@ class UpdateHandler(object):
 
             logger.info("Goal State Period: {0} sec. This indicates how often the agent checks for new goal states and reports status.", self._goal_state_period)
 
+            self._cleanup_legacy_goal_state_history()
+
             while self.is_running:
                 self._check_daemon_running(debug)
                 self._check_threads_running(all_thread_handlers)
@@ -590,11 +593,31 @@ class UpdateHandler(object):
 
             if self._processing_new_incarnation():
                 remote_access_handler.run()
+
+            if self._processing_new_extensions_goal_state():
+                try:
+                    UpdateHandler._cleanup_goal_state_history()
+                except Exception as exception:
+                    logger.warn("Error cleaning up the goal state history: {0}", ustr(exception))
+
         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():
+        archiver = StateArchiver(conf.get_lib_dir())
+        archiver.purge()
+        archiver.archive()
+
+    @staticmethod
+    def _cleanup_legacy_goal_state_history():
+        try:
+            StateArchiver.purge_legacy_goal_state_history()
+        except Exception as exception:
+            logger.warn("Error removing legacy history files: {0}", ustr(exception))
+
     def __get_vmagent_update_status(self, protocol, incarnation_changed):
         """
         This function gets the VMAgent update status as per the last GoalState.
diff --git a/config/waagent.conf b/config/waagent.conf
index c7d10e2f..0dd98884 100644
--- a/config/waagent.conf
+++ b/config/waagent.conf
@@ -9,9 +9,6 @@ Extensions.Enabled=y
 # How often (in seconds) to poll for new goal states
 Extensions.GoalStatePeriod=6
 
-# How often (in seconds) to clean up the goal state history. The default value is 30 min
-Extensions.GoalStateHistoryCleanupPeriod=1800
-
 # Which provisioning agent to use. Supported values are "auto" (default), "waagent",
 # "cloud-init", or "disabled".
 Provisioning.Agent=auto


Test patch:
diff --git a/tests/test_agent.py b/tests/test_agent.py
index b35b1424..56ac1604 100644
--- a/tests/test_agent.py
+++ b/tests/test_agent.py
@@ -46,7 +46,6 @@ DetectScvmmEnv = False
 EnableOverProvisioning = True
 Extension.LogDir = /var/log/azure
 Extensions.Enabled = True
-Extensions.GoalStateHistoryCleanupPeriod = 1800
 Extensions.GoalStatePeriod = 6
 Extensions.InitialGoalStatePeriod = 6
 HttpProxy.Host = None
diff --git a/tests/utils/test_archive.py b/tests/utils/test_archive.py
index 7834a7d2..9cf31b9e 100644
--- a/tests/utils/test_archive.py
+++ b/tests/utils/test_archive.py
@@ -53,43 +53,36 @@ class TestArchive(AgentTestCase):
         incarnation_no_ext = os.path.splitext(incarnation_ext)[0]
         return timestamp_str, incarnation_no_ext
 
-    def test_archive01(self):
-        """
-        StateArchiver should archive all history directories by
-
-          1. Creating a .zip of a timestamped directory's files
-          2. Saving the .zip to /var/lib/waagent/history/
-          2. Deleting the timestamped directory
-        """
-        temp_files = [
+    def test_archive_should_zip_all_but_the_latest_goal_state_in_the_history_folder(self):
+        test_files = [
             'GoalState.xml',
             'Prod.manifest.xml',
             'Prod.agentsManifest',
             'Microsoft.Azure.Extensions.CustomScript.xml'
         ]
 
-        # this directory matches the pattern that StateArchiver.archive() searches for
-        temp_directory = os.path.join(self.history_dir, datetime.utcnow().isoformat() + "_incarnation_0")
-
-        for current_file in temp_files:
-            self._write_file(os.path.join(temp_directory, current_file))
+        # these directories match the pattern that StateArchiver.archive() searches for
+        test_directories = []
+        for i in range(0, 3):
+            timestamp = (datetime.utcnow() + timedelta(minutes=i)).isoformat()
+            directory = os.path.join(self.history_dir, "{0}_incarnation_{1}".format(timestamp, i))
+            for current_file in test_files:
+                self._write_file(os.path.join(directory, current_file))
+            test_directories.append(directory)
 
         test_subject = StateArchiver(self.tmp_dir)
         test_subject.archive()
 
-        timestamp_zips = os.listdir(self.history_dir)
-        self.assertEqual(1, len(timestamp_zips))
+        for directory in test_directories[0:2]:
+            zip_file = directory + ".zip"
+            self.assertTrue(os.path.exists(zip_file), "{0} was not archived (could not find {1})".format(directory, zip_file))
 
-        zip_fn = timestamp_zips[0]  # 2000-01-01T00:00:00.000000_incarnation_N.zip
-        timestamp_str, incarnation = self._parse_archive_name(zip_fn)
+            missing_file = self.assert_zip_contains(zip_file, test_files)
+            self.assertEqual(None, missing_file, missing_file)
 
-        self.assert_is_iso8601(timestamp_str)
-        timestamp = self.parse_isoformat(timestamp_str)
-        self.assert_datetime_close_to(timestamp, datetime.utcnow(), timedelta(seconds=30))
-        self.assertEqual("0", incarnation)
+            self.assertFalse(os.path.exists(directory), "{0} was not removed after being archived ".format(directory))
 
-        zip_full = os.path.join(self.history_dir, zip_fn)
-        self.assertEqual(self.assert_zip_contains(zip_full, temp_files), None)
+        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):
         """
@@ -136,6 +129,27 @@ class TestArchive(AgentTestCase):
                 filename = "{0}_0.zip".format(timestamp)
             self.assertTrue(filename in archived_entries, "'{0}' is not in the list of unpurged entires".format(filename))
 
+    def test_purge_legacy_goal_state_history(self):
+        with patch("azurelinuxagent.common.conf.get_lib_dir", return_value=self.tmp_dir):
+            legacy_files = [
+                'GoalState.1.xml',
+                'VmSettings.1.json',
+                'Prod.1.manifest.xml',
+                'ExtensionsConfig.1.xml',
+                'Microsoft.Azure.Extensions.CustomScript.1.xml',
+                'SharedConfig.xml',
+                'HostingEnvironmentConfig.xml',
+                'RemoteAccess.xml'
+            ]
+            legacy_files = [os.path.join(self.tmp_dir, f) for f in legacy_files]
+            for f in legacy_files:
+                self._write_file(f)
+
+            StateArchiver.purge_legacy_goal_state_history()
+
+            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.