Repository: Azure/WALinuxAgent (python)

Issue:
[BUG] Waagent history files consuming all inodes
I'm running a number of Azure VMs with Centos linux servers and noticed this issue permeating across a number of them. It seems the inodes have been consumed entirely, although memory usage is relatively low.

```
$ df -H
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda1        31G   13G   17G  44% /
tmpfs           7.3G     0  7.3G   0% /dev/shm
/dev/sdb1       212G   63M  201G   1% /mnt/resource

$ df -Hi
Filesystem     Inodes IUsed IFree IUse% Mounted on
/dev/sda1        2.0M  2.0M     0  100% /
tmpfs            1.8M     1  1.8M    1% /dev/shm
/dev/sdb1         14M    12   14M    1% /mnt/resource
```

It seems there were some 1.5M files generated under /var/lib/waagent/history/ that were consuming much of the inodes. 
```
$ sudo find /var/lib/waagent/history/ -type f | wc -l
1537972
```

I noticed some errors in the waagent.log file noted below. 

```
2022-06-01T08:43:44.515760Z WARNING ExtHandler ExtHandler [PERIODIC] Attempts to retrieve VM size information from IMDS are failing: [HttpError] IMDS error in /metadata/instance/compute: [HTTP Failed] [404: Not Found] { "error": "Not found" }
Traceback (most recent call last):
  File "bin/WALinuxAgent-2.8.0.6-py2.7.egg/azurelinuxagent/ga/update.py", line 455, in _get_vm_size
    imds_info = imds_client.get_compute()
  File "bin/WALinuxAgent-2.8.0.6-py2.7.egg/azurelinuxagent/common/protocol/imds.py", line 350, in get_compute
    raise HttpError(result.response)
HttpError: [HttpError] IMDS error in /metadata/instance/compute: [HTTP Failed] [404: Not Found] { "error": "Not found" }
```

Then at some point later we start seeing these errors, which suggests the inodes were consumed and no longer able to write data:

```
2022-06-23T00:45:45.650352Z INFO ExtHandler ExtHandler Forcing an update of the goal state.
2022-06-23T00:45:45.653545Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 1]
2022-06-23T00:45:45.656026Z INFO ExtHandler 
2022-06-23T00:45:45.656109Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 1]
2022-06-23T00:45:45.661255Z INFO ExtHandler ExtHandler Status Blob type 'None' is not valid, assuming BlockBlob
2022-06-23T00:45:45.668726Z INFO ExtHandler Fetch goal state completed
2022-06-23T00:45:48.286427Z WARNING MonitorHandler ExtHandler [PERIODIC] [IMDS_CONNECTION_ERROR] Unable to connect to IMDS endpoint 169.254.169.254
2022-06-23T00:45:51.682798Z INFO ExtHandler ExtHandler Forcing an update of the goal state.
2022-06-23T00:45:51.686254Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 1]
2022-06-23T00:45:51.689158Z INFO ExtHandler 
2022-06-23T00:45:51.689248Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 1]
2022-06-23T00:45:51.694320Z INFO ExtHandler ExtHandler Status Blob type 'None' is not valid, assuming BlockBlob
2022-06-23T00:45:51.701319Z INFO ExtHandler Fetch goal state completed
2022-06-23T00:45:51.791196Z WARNING ExtHandler ExtHandler Failed to save waagent_status.json to the goal state history: [Errno 28] No space left on device: '/var/lib/waagent/history/2022-06-23T00-45-45__1/waagent_status.json' [no additional errors saving the goal state will be reported]
2022-06-23T00:45:57.804137Z INFO ExtHandler ExtHandler Forcing an update of the goal state.
2022-06-23T00:45:57.808701Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 1]
2022-06-23T00:45:57.856988Z WARNING ExtHandler ExtHandler Failed to save GoalState.xml to the goal state history: [Errno 28] No space left on device: '/var/lib/waagent/history/2022-06-23T00-45-57__1' [no additional errors saving the goal state will be reported]
2022-06-23T00:45:57.857222Z INFO ExtHandler 
2022-06-23T00:45:57.857299Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 1]
2022-06-23T00:45:57.862779Z INFO ExtHandler ExtHandler Status Blob type 'None' is not valid, assuming BlockBlob
2022-06-23T00:45:57.949160Z INFO ExtHandler Fetch goal state completed
2022-06-23T00:45:57.986464Z WARNING ExtHandler ExtHandler Failed to save waagent_status.json to the goal state history: [Errno 28] No space left on device: '/var/lib/waagent/history/2022-06-23T00-45-51__1/waagent_status.json' [no additional errors saving the goal state will be reported]
2022-06-23T00:46:03.999563Z INFO ExtHandler ExtHandler Forcing an update of the goal state.
2022-06-23T00:46:04.003019Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 1]
2022-06-23T00:46:04.044419Z WARNING ExtHandler ExtHandler Failed to save GoalState.xml to the goal state history: [Errno 28] No space left on device: '/var/lib/waagent/history/2022-06-23T00-46-03__1' [no additional errors saving the goal state will be reported]
2022-06-23T00:46:04.044669Z INFO ExtHandler 
2022-06-23T00:46:04.044770Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 1]
2022-06-23T00:46:04.049623Z INFO ExtHandler ExtHandler Status Blob type 'None' is not valid, assuming BlockBlob
2022-06-23T00:46:04.130762Z INFO ExtHandler Fetch goal state completed
2022-06-23T00:46:10.179938Z INFO ExtHandler ExtHandler Forcing an update of the goal state.
2022-06-23T00:46:10.183476Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 1]
2022-06-23T00:46:10.234232Z WARNING ExtHandler ExtHandler Failed to save GoalState.xml to the goal state history: [Errno 28] No space left on device: '/var/lib/waagent/history/2022-06-23T00-46-10__1' [no additional errors saving the goal state will be reported]
2022-06-23T00:46:10.234734Z INFO ExtHandler 
2022-06-23T00:46:10.234822Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 1]
2022-06-23T00:46:10.240618Z INFO ExtHandler ExtHandler Status Blob type 'None' is not valid, assuming BlockBlob
2022-06-23T00:46:10.343409Z INFO ExtHandler Fetch goal state completed
```

Questions:
1. Is it safe to clear out the history directories to regain control of my servers?
2. What is causing the files to consume all the inodes and how can we limit this?

Here is my waagent version:
```
$ waagent --version
WALinuxAgent-2.2.45 running on centos 6.10
Python: 2.6.6
Goal state agent: 2.8.0.6
```

Pull request:
Cleanup history directory when creating new subdirectories
Fixes #2619 

When reporting status, if the status blob is None, upload_status_blob forces fetching a new goal state:
```
    def upload_status_blob(self):
        extensions_goal_state = self.get_goal_state().extensions_goal_state

        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, silent=True)
```

As part of fetching the goal state, a new item is created under the history directory and several lines are added to the agent log. This will continue happening until there is a new goal state that provides the status blob. The history folder is cleaned up only when there is a new goal state so, since reporting status is done every 6 seconds, this condition can rapidly produce a very large log file or consume a very large number of inodes, as reported in #2619.

To fix this, now we cleanup the history directory each time a new item is created, and we turn off logging while re-fetching the goal state.

While testing the fix, I notice there were a few places where we were not honoring the Logger.silent flag. This PR fixes that as well.

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 583f3894..66b0de5d 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -635,9 +635,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:
@@ -645,10 +645,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):