diff --git a/tests_e2e/tests/ext_sequencing/ext_sequencing.py b/tests_e2e/tests/ext_sequencing/ext_sequencing.py index 3af9e64fe6..042ae8a99f 100644 --- a/tests_e2e/tests/ext_sequencing/ext_sequencing.py +++ b/tests_e2e/tests/ext_sequencing/ext_sequencing.py @@ -95,11 +95,14 @@ def _get_sorted_extension_names(extensions: List[VirtualMachineScaleSetVMExtensi 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_type '{extension_full_names[ext.name]}' --start_time '{str(test_case_start)}'", use_sudo=True) + 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_times.append( { "name": ext.name, - "enabled_time": datetime.strptime(enabled_time.strip(), u'%Y-%m-%d %H:%M:%S') + "enabled_time": formatted_time } ) diff --git a/tests_e2e/tests/lib/virtual_machine_client.py b/tests_e2e/tests/lib/virtual_machine_client.py index bd4ab9ae67..5d6e471b9c 100644 --- a/tests_e2e/tests/lib/virtual_machine_client.py +++ b/tests_e2e/tests/lib/virtual_machine_client.py @@ -186,7 +186,7 @@ def restart( return log.info("The VM has not rebooted yet. Restart time: %s. Boot time: %s", before_restart, boot_time) except CommandError as e: - if (e.exit_code == 255 and "Connection refused" in str(e)) or "Unprivileged users are not permitted to log in yet" in str(e): + if (e.exit_code == 255 and ("Connection refused" in str(e) or "Connection timed out" in str(e))) or "Unprivileged users are not permitted to log in yet" in str(e): log.info("VM %s is not yet accepting SSH connections", self) else: raise diff --git a/tests_e2e/tests/scripts/ext_sequencing-get_ext_enable_time.py b/tests_e2e/tests/scripts/ext_sequencing-get_ext_enable_time.py index b9b2c66cb5..f65da676be 100755 --- a/tests_e2e/tests/scripts/ext_sequencing-get_ext_enable_time.py +++ b/tests_e2e/tests/scripts/ext_sequencing-get_ext_enable_time.py @@ -20,10 +20,10 @@ # import argparse -import re +import json +import os import sys -from datetime import datetime from pathlib import Path @@ -32,55 +32,57 @@ def main(): Returns the timestamp of when the provided extension was enabled """ parser = argparse.ArgumentParser() - parser.add_argument("--ext_type", dest='ext_type', required=True) - parser.add_argument("--start_time", dest='start_time', required=True) + parser.add_argument("--ext", dest='ext', required=True) args, _ = parser.parse_known_args() - # Extension enabled time is in extension CommandExecution.log - command_exec_log_path = Path('/var/log/azure/' + args.ext_type + '/CommandExecution.log') - command_exec_log = open(command_exec_log_path, 'r') - enabled_match = None - for line in command_exec_log.readlines(): - line = line.rstrip() - if args.ext_type == "Microsoft.Azure.Monitor.AzureMonitorLinuxAgent": - # AMA logs enable succeeded and its timestamp to the command execution log: - # 2023-11-01T23:22:53.124603Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.28.11] Command: ./shim.sh -enable - # [stdout] - # 2023/09/26 04:07:33 [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.28.5] Enable,success,0,Enable succeeded - enable_pattern = r'.*(?P\d{4}\/\d{2}\/\d{2} \d{2}:\d{2}:\d{2}) \[Microsoft\.Azure\.Monitor\.AzureMonitorLinuxAgent\-.*] .*Enable succeeded.*' - match = re.match(enable_pattern, line) - if match: - enabled_match = match - else: - # For RC and CSE, we can determine when enable succeeded from the stdout of the enable command execution from - # the command execution log: - # 2023-09-26T04:07:39.042948Z INFO ExtHandler [Microsoft.CPlat.Core.RunCommandLinux-1.0.5] Command: bin/run-command-shim enable - # [stdout] - # ... - # time=2023-09-26T04:07:37Z version=v1.0.4/git@b3be41d-dirty operation=enable seq=0 event=enabledevent=enabled - enable_pattern = r'time=(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}Z).*event=enabled' - match = re.match(enable_pattern, line) - if match: - enabled_match = match - - if not enabled_match: - # Try to get enabled time from extension command execution logs - print("Agent log does not show extension was enabled", file=sys.stderr) + # 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) - - if args.ext_type == "Microsoft.Azure.Monitor.AzureMonitorLinuxAgent": - enable_time = datetime.strptime(enabled_match.group('timestamp'), u'%Y/%m/%d %H:%M:%S') - else: - enable_time = datetime.strptime(enabled_match.group('timestamp'), u'%Y-%m-%dT%H:%M:%SZ') - - start_time = datetime.strptime(args.start_time, u'%Y-%m-%d %H:%M:%S.%f') - if enable_time < start_time: - print("Agent log does not show extension was enabled after this test case started. Last enabled time was {0}. This test case started at {1}".format(enable_time, start_time), file=sys.stderr) + 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()) + + # 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(enable_time) + print(ext_status[0]['timestampUTC']) + sys.exit(0) - sys.exit(0) + print(msg, file=sys.stderr) + sys.exit(1) if __name__ == "__main__":