Ext_sequencing scenario should check agent log for extension enable order (#3049)

* Ext_sequencing scenario should check agent log for extension enable order

* Format timestamp for ignore errors before timestamp

* If test is skipped, scenario start will be datetime min

* Remove unnecessary log

* Make none check explicit

tests_e2e/tests/ext_sequencing/ext_sequencing.py

@@ -22,6 +22,7 @@
 # validates they are enabled in order of dependencies.
 #
 import copy
+import random
 import re
 import uuid
 from datetime import datetime
@@ -95,10 +96,8 @@ class ExtSequencing(AgentVmssTest):
         for ext in extensions:
             # Only check extensions which succeeded provisioning
             if "succeeded" in ext.statuses_summary[0].code:
-                enabled_time = ssh_client.run_command(f"ext_sequencing-get_ext_enable_time.py --ext '{extension_full_names[ext.name]}'", use_sudo=True)
-                formatted_time = datetime.strptime(enabled_time.strip(), u'%Y-%m-%dT%H:%M:%SZ')
-                if formatted_time < test_case_start:
-                    fail("Extension {0} was not enabled".format(extension_full_names[ext.name]))
+                enabled_time = ssh_client.run_command(f"ext_sequencing-get_ext_enable_time.py --ext '{extension_full_names[ext.name]}' --after_time '{test_case_start}'", use_sudo=True)
+                formatted_time = datetime.strptime(enabled_time.strip(), u'%Y-%m-%dT%H:%M:%S.%fZ')
                 enabled_times.append(
                     {
                         "name": ext.name,
@@ -184,7 +183,7 @@ class ExtSequencing(AgentVmssTest):
         }
 
         for case in self._test_cases:
-            test_case_start = datetime.now()
+            test_case_start = random.choice(list(ssh_clients.values())).run_command("date '+%Y-%m-%d %T'").rstrip()
             if self._scenario_start == datetime.min:
                 self._scenario_start = test_case_start
 
@@ -201,6 +200,7 @@ class ExtSequencing(AgentVmssTest):
             # test out
             log.info("")
             log.info("Test case: {0}".format(case.__name__.replace('_', ' ')))
+            log.info("Test case start time: {0}".format(test_case_start))
             ext_template = copy.deepcopy(base_extension_template)
             ext_template['resources'][0]['properties']['virtualMachineProfile']['extensionProfile'][
                 'extensions'] = extensions
@@ -255,7 +255,9 @@ class ExtSequencing(AgentVmssTest):
 
     def get_ignore_errors_before_timestamp(self) -> datetime:
         # Ignore errors in the agent log before the first test case starts
-        return self._scenario_start
+        if self._scenario_start == datetime.min:
+            return self._scenario_start
+        return datetime.strptime(self._scenario_start, u'%Y-%m-%d %H:%M:%S')
 
     def get_ignore_error_rules(self) -> List[Dict[str, Any]]:
         ignore_rules = [

tests_e2e/tests/scripts/ext_sequencing-get_ext_enable_time.py

@@ -20,68 +20,42 @@
 #
 
 import argparse
-import json
-import os
+import re
 import sys
+from datetime import datetime
 
-from pathlib import Path
+from tests_e2e.tests.lib.agent_log import AgentLog
 
 
 def main():
     """
-    Returns the timestamp of when the provided extension was enabled
+    Searches the agent log after the provided timestamp to determine when the agent enabled the provided extension.
     """
     parser = argparse.ArgumentParser()
     parser.add_argument("--ext", dest='ext', required=True)
+    parser.add_argument("--after_time", dest='after_time', required=True)
     args, _ = parser.parse_known_args()
 
-    # Extension enabled time is in extension extension status file
-    ext_dirs = [item for item in os.listdir(Path('/var/lib/waagent')) if item.startswith(args.ext)]
-    if not ext_dirs:
-        print("Extension {0} directory does not exist".format(args.ext), file=sys.stderr)
-        sys.exit(1)
-    ext_status_path = Path('/var/lib/waagent/' + ext_dirs[0] + '/status')
-    ext_status_files = os.listdir(ext_status_path)
-    ext_status_files.sort()
-    if not ext_status_files:
-        # Extension did not report a status
-        print("Extension {0} did not report a status".format(args.ext), file=sys.stderr)
-        sys.exit(1)
-    latest_ext_status_path = os.path.join(ext_status_path, ext_status_files[-1])
-    ext_status_file = open(latest_ext_status_path, 'r')
-    ext_status = json.loads(ext_status_file.read())
+    # Only search the agent log after the provided timestamp: args.after_time
+    after_time = datetime.strptime(args.after_time, u'%Y-%m-%d %H:%M:%S')
+    # Agent logs for extension enable: 2024-02-09T09:29:08.943529Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Enable extension: [bin/custom-script-shim enable]
+    enable_log_regex = r"\[{0}-[.\d]+\] Enable extension: .*".format(args.ext)
 
-    # Example status file
-    # [
-    #     {
-    #         "status": {
-    #             "status": "success",
-    #             "formattedMessage": {
-    #                 "lang": "en-US",
-    #                 "message": "Enable succeeded"
-    #             },
-    #             "operation": "Enable",
-    #             "code": "0",
-    #             "name": "Microsoft.Azure.Monitor.AzureMonitorLinuxAgent"
-    #         },
-    #         "version": "1.0",
-    #         "timestampUTC": "2023-12-12T23:14:45Z"
-    #     }
-    # ]
-    msg = ""
-    if len(ext_status) == 0 or not ext_status[0]['status']:
-        msg = "Extension {0} did not report a status".format(args.ext)
-    elif not ext_status[0]['status']['operation'] or ext_status[0]['status']['operation'] != 'Enable':
-        msg = "Extension {0} did not report a status for enable operation".format(args.ext)
-    elif ext_status[0]['status']['status'] != 'success':
-        msg = "Extension {0} did not report success for the enable operation".format(args.ext)
-    elif not ext_status[0]['timestampUTC']:
-        msg = "Extension {0} did not report the time the enable operation succeeded".format(args.ext)
-    else:
-        print(ext_status[0]['timestampUTC'])
-        sys.exit(0)
+    agent_log = AgentLog()
+    try:
+        for agent_record in agent_log.read():
+            if agent_record.timestamp >= after_time:
+                # The agent_record prefix for enable logs is the extension name, for example: [Microsoft.Azure.Extensions.CustomScript-2.1.10]
+                if agent_record.prefix is not None:
+                    ext_enabled = re.match(enable_log_regex, " ".join([agent_record.prefix, agent_record.message]))
 
-    print(msg, file=sys.stderr)
+                    if ext_enabled is not None:
+                        print(agent_record.when)
+                        sys.exit(0)
+    except IOError as e:
+        print("Error when parsing agent log: {0}".format(str(e)))
+
+    print("Extension {0} was not enabled after {1}".format(args.ext, args.after_time), file=sys.stderr)
     sys.exit(1)