Change format of history items (Azure#2560)

* Change format of history directory

* Update message; fix typo

* py2 compat

* py2 compat

Co-authored-by: narrieta <narrieta>

azurelinuxagent/common/protocol/goal_state.py

@@ -15,6 +15,7 @@
 # limitations under the License.
 #
 # Requires Python 2.6+ and Openssl 1.0+
+import datetime
 import os
 import re
 import time
@@ -31,7 +32,7 @@
 from azurelinuxagent.common.protocol.extensions_goal_state import VmSettingsParseError, GoalStateSource
 from azurelinuxagent.common.protocol.hostplugin import VmSettingsNotSupported, VmSettingsSupportStopped
 from azurelinuxagent.common.protocol.restapi import Cert, CertList, RemoteAccessUser, RemoteAccessUsersList
-from azurelinuxagent.common.utils import fileutil, timeutil
+from azurelinuxagent.common.utils import fileutil
 from azurelinuxagent.common.utils.archive import GoalStateHistory
 from azurelinuxagent.common.utils.cryptutil import CryptUtil
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, findtext, getattrib
@@ -131,7 +132,7 @@ def update(self):
         #
         # Fetch the goal state from both the HGAP and the WireServer
         #
-        timestamp = timeutil.create_timestamp()
+        timestamp = datetime.datetime.utcnow()
 
         incarnation, xml_text, xml_doc = GoalState._fetch_goal_state(self._wire_client)
         goal_state_updated = incarnation != self._incarnation
@@ -199,7 +200,7 @@ def update(self):
 
     def _restore_wire_server_goal_state(self, incarnation, xml_text, xml_doc, vm_settings_support_stopped_error):
         logger.info('The HGAP stopped supporting vmSettings; will fetched the goal state from the WireServer.')
-        self._history = GoalStateHistory(timeutil.create_timestamp(), incarnation)
+        self._history = GoalStateHistory(datetime.datetime.utcnow(), incarnation)
         self._history.save_goal_state(xml_text)
         self._extensions_goal_state = self._fetch_full_wire_server_goal_state(incarnation, xml_doc)
         if self._extensions_goal_state.created_on_timestamp < vm_settings_support_stopped_error.timestamp:
@@ -270,7 +271,7 @@ def _fetch_vm_settings(wire_client):
             except VmSettingsParseError as exception:
                 # ensure we save the vmSettings if there were parsing errors, but save them only once per ETag
                 if not GoalStateHistory.tag_exists(exception.etag):
-                    GoalStateHistory(timeutil.create_timestamp(), exception.etag).save_vm_settings(exception.vm_settings_text)
+                    GoalStateHistory(datetime.datetime.utcnow(), exception.etag).save_vm_settings(exception.vm_settings_text)
                 raise
 
         return vm_settings, vm_settings_updated

azurelinuxagent/common/utils/archive.py

@@ -9,7 +9,7 @@
 
 import azurelinuxagent.common.logger as logger
 import azurelinuxagent.common.conf as conf
-from azurelinuxagent.common.utils import fileutil
+from azurelinuxagent.common.utils import fileutil, timeutil
 
 # pylint: disable=W0105
 
@@ -58,13 +58,15 @@
 #   2018-04-06T08:21:37.142697.zip
 #   2018-04-06T08:21:37.142697_incarnation_N
 #   2018-04-06T08:21:37.142697_incarnation_N.zip
+#   2018-04-06T08:21:37.142697_N-M
+#   2018-04-06T08:21:37.142697_N-M.zip
 #
 # Current names
 #
-#   2018-04-06T08:21:37.142697_N-M
-#   2018-04-06T08:21:37.142697_N-M.zip
+#   2018-04-06T08-21-37__N-M
+#   2018-04-06T08-21-37__N-M.zip
 #
-_ARCHIVE_BASE_PATTERN = r"\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d+((_incarnation)?_(\d+|status)(-\d+)?)?"
+_ARCHIVE_BASE_PATTERN = r"\d{4}\-\d{2}\-\d{2}T\d{2}[:-]\d{2}[:-]\d{2}(\.\d+)?((_incarnation)?_+(\d+|status)(-\d+)?)?"
 _ARCHIVE_PATTERNS_DIRECTORY = re.compile(r'^{0}$'.format(_ARCHIVE_BASE_PATTERN))
 _ARCHIVE_PATTERNS_ZIP = re.compile(r'^{0}\.zip$'.format(_ARCHIVE_BASE_PATTERN))
 
@@ -163,7 +165,6 @@ def purge(self):
         newest ones. Also, clean up any legacy history files.
         """
         states = self._get_archive_states()
-        states.sort(reverse=True)
 
         for state in states[_MAX_ARCHIVED_STATES:]:
             state.delete()
@@ -184,7 +185,6 @@ def purge_legacy_goal_state_history():
 
     def archive(self):
         states = self._get_archive_states()
-        states.sort(reverse=True)
 
         if len(states) > 0:
             # Skip the most recent goal state, since it may still be in use
@@ -203,13 +203,16 @@ def _get_archive_states(self):
             if match is not None:
                 states.append(StateZip(full_path, match.group(0)))
 
+        states.sort(key=lambda state: os.path.getctime(state._path), reverse=True)
+
         return states
 
 
 class GoalStateHistory(object):
-    def __init__(self, timestamp, tag):
+    def __init__(self, time, tag):
         self._errors = False
-        self._root = os.path.join(conf.get_lib_dir(), ARCHIVE_DIRECTORY_NAME, "{0}_{1}".format(timestamp, tag) if tag is not None else timestamp)
+        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)
 
     @staticmethod
     def tag_exists(tag):

azurelinuxagent/common/utils/timeutil.py

@@ -5,14 +5,23 @@
 
 def create_timestamp(dt=None):
     """
-    Returns a string with the given datetime iso format. If no datetime is given as parameter, it
+    Returns a string with the given datetime in iso format. If no datetime is given as parameter, it
     uses datetime.utcnow().
     """
     if dt is None:
         dt = datetime.datetime.utcnow()
     return dt.isoformat()
 
 
+def create_history_timestamp(dt=None):
+    """
+    Returns a string with the given datetime formatted as a timestamp for the agent's history folder
+    """
+    if dt is None:
+        dt = datetime.datetime.utcnow()
+    return dt.strftime('%Y-%m-%dT%H-%M-%S')
+
+
 def datetime_to_ticks(dt):
     """
     Converts 'dt', a datetime, to the number of ticks (1 tick == 1/10000000 sec) since datetime.min (0001-01-01 00:00:00).

azurelinuxagent/ga/update.py

@@ -54,7 +54,7 @@
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.utils.networkutil import AddFirewallRules
 from azurelinuxagent.common.utils.shellutil import CommandError
-from azurelinuxagent.common.version import AGENT_LONG_NAME, AGENT_NAME, AGENT_DIR_PATTERN, CURRENT_AGENT, \
+from azurelinuxagent.common.version import AGENT_LONG_NAME, AGENT_NAME, AGENT_DIR_PATTERN, CURRENT_AGENT, AGENT_VERSION, \
     CURRENT_VERSION, DISTRO_NAME, DISTRO_VERSION, get_lis_version, \
     has_logrotate, PY_VERSION_MAJOR, PY_VERSION_MINOR, PY_VERSION_MICRO, get_daemon_version
 from azurelinuxagent.ga.collect_logs import get_collect_logs_handler, is_log_collection_allowed
@@ -324,10 +324,9 @@ def run(self, debug=False):
         """
 
         try:
-            logger.info("{0} Version: {1}", AGENT_LONG_NAME, CURRENT_AGENT)
+            logger.info("{0} (Goal State Agent version {1})", AGENT_LONG_NAME, AGENT_VERSION)
             logger.info("OS: {0} {1}", DISTRO_NAME, DISTRO_VERSION)
             logger.info("Python: {0}.{1}.{2}", PY_VERSION_MAJOR, PY_VERSION_MINOR, PY_VERSION_MICRO)
-            logger.info(u"Agent {0} is running as the goal state agent", CURRENT_AGENT)
 
             os_info_msg = u"Distro: {dist_name}-{dist_ver}; "\
                 u"OSUtil: {util_name}; AgentService: {service_name}; "\

tests/protocol/test_goal_state.py

@@ -373,4 +373,4 @@ def test_it_should_report_missing_certificates(self):
 
                 self.assertTrue(
                     len(events) == 1,
-                    "Missing certificate 59A10F50FFE2A0408D3F03FE336C8FD5716CF25C was note reported. Telemetry: {0}".format([kwargs['message'] for _, kwargs in add_event.call_args_list]))
+                    "Missing certificate 59A10F50FFE2A0408D3F03FE336C8FD5716CF25C was not reported. Telemetry: {0}".format([kwargs['message'] for _, kwargs in add_event.call_args_list]))

tests/utils/test_archive.py

@@ -67,7 +67,10 @@ def test_archive_should_zip_all_but_the_latest_goal_state_in_the_history_folder(
             test_directories.append(directory)
 
         test_subject = StateArchiver(self.tmp_dir)
-        test_subject.archive()
+        # 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):
+            test_subject.archive()
 
         for directory in test_directories[0:2]:
             zip_file = directory + ".zip"
@@ -110,7 +113,10 @@ def test_archive02(self):
         self.assertEqual(total, len(os.listdir(self.history_dir)))
 
         test_subject = StateArchiver(self.tmp_dir)
-        test_subject.purge()
+        # 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):
+            test_subject.purge()
 
         archived_entries = os.listdir(self.history_dir)
         self.assertEqual(_MAX_ARCHIVED_STATES, len(archived_entries))