Add tests for extension workflow

tests_e2e/orchestrator/runbook.yml

@@ -51,7 +51,7 @@ variable:
   #
   # The test suites to execute
   - name: test_suites
-    value: "agent_bvt, no_outbound_connections, extensions_disabled, agent_not_provisioned, fips"
+    value: "agent_bvt, no_outbound_connections, extensions_disabled, agent_not_provisioned, fips, agent_ext_workflow"
   - name: cloud
     value: "AzureCloud"
     is_case_visible: true

tests_e2e/test_suites/agent_ext_workflow.yml

@@ -0,0 +1,11 @@
+name: "AgentExtWorkflow"
+tests:
+  - "agent_ext_workflow/extension_workflow.py"
+images:
+  - "centos_79"
+  - "suse_12"
+  - "rhel_79"
+  - "ubuntu_1604"
+  - "ubuntu_1804"
+# This test suite uses the DCR Test Extension, which is only published in South Central US
+locations: "AzureCloud:southcentralus"

tests_e2e/tests/agent_ext_workflow/README.md

@@ -0,0 +1,45 @@
+# Agent Extension Worflow Test
+
+This scenario tests if the correct extension workflow sequence is being executed from the agent.
+
+### GuestAgentDcrTestExtension
+
+This is a test extension that exists for the sole purpose of testing the extension workflow of agent. This is currently deployed to SCUS only.
+
+All the extension does is prints the settings['name'] out to stdout. It is run everytime enable is called.
+
+Another important feature of this extension is that it maintains a `operations-<VERSION_NO>.log` **for every operation that the agent executes on that extension**. We use this to confirm that the agent executed the correct sequence of operations.
+
+Sample operations-<version>.log file snippet -
+```text
+Date:2019-07-30T21:54:03Z; Operation:install; SeqNo:0
+Date:2019-07-30T21:54:05Z; Operation:enable; SeqNo:0
+Date:2019-07-30T21:54:37Z; Operation:enable; SeqNo:1
+Date:2019-07-30T21:55:20Z; Operation:disable; SeqNo:1
+Date:2019-07-30T21:55:22Z; Operation:uninstall; SeqNo:1
+```
+The setting for this extension is of the format - 
+```json
+{
+  "name": String
+}
+```
+##### Repo link 
+https://github.com/larohra/GuestAgentDcrTestExtension 
+
+##### Available Versions:
+- 1.1.5 - Version with Basic functionalities as mentioned above
+- 1.2.0 - Same functionalities as above with `"updateMode": "UpdateWithInstall"` in HandlerManifest.json to test update case
+- 1.3.0 - Same functionalities as above with `"updateMode": "UpdateWithoutInstall"` in HandlerManifest.json to test update case
+
+### Test Sequence 
+
+- Install the test extension on the VM
+- Assert the extension status by checking if our Enable string matches the status message (We receive the status message by using the Azure SDK by polling for the VM instance view and parsing the extension status message)  
+
+The Enable string of our test is of the following format (this is set in the `Settings` object when we call enable from the tests ) -
+```text
+[ExtensionName]-[Version], Count: [Enable-count]
+```
+- Match the operation sequence as per the test and make sure they are in the correct chronological order
+- Restart the agent and verify if the correct operation sequence is followed

tests_e2e/tests/lib/agent_log.py

@@ -362,6 +362,17 @@ def is_error(r: AgentLogRecord) -> bool:
 
         return errors
 
+    def agent_log_contains(self, data: str):
+        """
+        This function looks for the specified test data string in the WALinuxAgent logs and returns if found or not.
+        :param data: The string to look for in the agent logs
+        :return: True if test data string found in the agent log and False if not.
+       """
+        for record in self.read():
+            if data in record.text:
+                return True
+        return False
+
     @staticmethod
     def _is_systemd():
         # Taken from azurelinuxagent/common/osutil/systemd.py; repeated here because it is available only on agents >= 2.3

tests_e2e/tests/lib/identifiers.py

@@ -62,3 +62,4 @@ class VmExtensionIds(object):
     # New run command extension, with support for multi-config
     RunCommandHandler: VmExtensionIdentifier = VmExtensionIdentifier(publisher='Microsoft.CPlat.Core', ext_type='RunCommandHandlerLinux', version="1.0")
     VmAccess: VmExtensionIdentifier = VmExtensionIdentifier(publisher='Microsoft.OSTCExtensions', ext_type='VMAccessForLinux', version="1.0")
+    GuestAgentDcrTestExtension: VmExtensionIdentifier = VmExtensionIdentifier(publisher='Microsoft.Azure.TestExtensions.Edp', ext_type='GuestAgentDcrTest', version='1.0')

tests_e2e/tests/scripts/extension_workflow-assert_operation_sequence.py

@@ -0,0 +1,176 @@
+#!/usr/bin/env pypy3
+
+# Microsoft Azure Linux Agent
+#
+# Copyright 2018 Microsoft Corporation
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+
+
+import argparse
+import os
+import sys
+import time
+from datetime import datetime
+
+DELIMITER = ";"
+OPS_FILE_DIR = "/var/log/azure/Microsoft.Azure.TestExtensions.Edp.GuestAgentDcrTest/"
+# In general most of the distros use the above directory for extension log logging except RHEL-69,
+# they use the 2nd File pattern (i.e. /var/log/azure/{ext-publisher-type}/{version}/extensions.log)
+OPS_FILE_PATTERN = ["operations-%s.log", "%s/operations-%s.log"]
+MAX_RETRY = 5
+SLEEP_TIMER = 30
+
+
+def parse_ops_log(ops_version, input_ops, start_time):
+    # input_ops are the expected operations that we expect to see in the operations log file
+    ver = (ops_version,)
+    ops_file_name = None
+    for file_pat in OPS_FILE_PATTERN:
+        ops_file_name = os.path.join(OPS_FILE_DIR, file_pat % ver)
+        if not os.path.exists(ops_file_name):
+            ver = ver + (ops_version,)
+            ops_file_name = None
+            continue
+        break
+
+    if not ops_file_name:
+        raise IOError("Operations File %s not found" % os.path.join(OPS_FILE_DIR, OPS_FILE_PATTERN[0] % ops_version))
+
+    ops = []
+    with open(ops_file_name, 'r') as ops_log:
+        # we get the last len(input_ops) from the log file and ensure they match with the input_ops
+        # Example of a line in the log file - `Date:2019-07-30T21:54:03Z; Operation:install; SeqNo:0`
+        content = ops_log.readlines()[-len(input_ops):]
+        for op_log in content:
+            data = op_log.split(DELIMITER)
+            date = datetime.strptime(data[0].split("Date:")[1], "%Y-%m-%dT%H:%M:%SZ")
+            op = data[1].split("Operation:")[1]
+            seq_no = data[2].split("SeqNo:")[1].strip('\n')
+
+            # We only capture the operations that > start_time of the test
+            if start_time > date:
+                continue
+
+            ops.append({'date': date, 'op': op, 'seq_no': seq_no})
+    return ops
+
+
+def assert_ops_in_sequence(actual_ops, expected_ops):
+    exit_code = 0
+
+    if len(actual_ops) != len(expected_ops):
+        print("Operation sequence length doesn't match, exit code 2")
+        exit_code = 2
+
+    last_date = datetime(70, 1, 1)
+    for idx, val in enumerate(actual_ops):
+        if exit_code != 0:
+            break
+
+        if val['date'] < last_date or val['op'] != expected_ops[idx]:
+            print("Operation sequence doesn't match, exit code 2")
+            exit_code = 2
+
+        last_date = val['date']
+
+    return exit_code
+
+
+def check_update_sequence(args):
+    # old_ops_file_name = OPS_FILE_PATTERN % args.old_version
+    # new_ops_file_name = OPS_FILE_PATTERN % args.new_version
+
+    actual_ops = parse_ops_log(args.old_version, args.old_ops, args.start_time)
+    actual_ops.extend(parse_ops_log(args.new_version, args.new_ops, args.start_time))
+    actual_ops = sorted(actual_ops, key=lambda op: op['date'])
+
+    exit_code = assert_ops_in_sequence(actual_ops, args.ops)
+
+    return exit_code, actual_ops
+
+
+def check_operation_sequence(args):
+    # ops_file_name = OPS_FILE_PATTERN % args.version
+
+    actual_ops = parse_ops_log(args.version, args.ops, args.start_time)
+    exit_code = assert_ops_in_sequence(actual_ops, args.ops)
+
+    return exit_code, actual_ops
+
+
+def main():
+    # There are 2 main ways you can call this file - normal_ops_sequence or update_sequence
+    parser = argparse.ArgumentParser()
+    cmd_parsers = parser.add_subparsers(help="sub-command help", dest="command")
+
+    # We use start_time to make sure we're testing the correct test and not some other test
+    parser.add_argument("--start-time", dest='start_time', required=True)
+
+    # Normal_ops_sequence gets the version of the ext and parses the corresponding operations file to get the operation
+    # sequence that were run on the extension
+    normal_ops_sequence_parser = cmd_parsers.add_parser("normal_ops_sequence", help="Test the normal operation sequence")
+    normal_ops_sequence_parser.add_argument('--version', dest='version')
+    normal_ops_sequence_parser.add_argument('--ops', nargs='*', dest='ops', default=argparse.SUPPRESS)
+
+    # Update_sequence mode is used to check for the update scenario. We get the expected old operations, expected
+    # new operations and the final operation list and verify if the expected operations match the actual ones
+    update_sequence_parser = cmd_parsers.add_parser("update_sequence", help="Test the update operation sequence")
+    update_sequence_parser.add_argument("--old-version", dest="old_version")
+    update_sequence_parser.add_argument("--new-version", dest="new_version")
+    update_sequence_parser.add_argument("--old-ver-ops", nargs="*", dest="old_ops", default=argparse.SUPPRESS)
+    update_sequence_parser.add_argument("--new-ver-ops", nargs="*", dest="new_ops", default=argparse.SUPPRESS)
+    update_sequence_parser.add_argument("--final-ops", nargs="*", dest="ops", default=argparse.SUPPRESS)
+
+    args, unknown = parser.parse_known_args()
+
+    if unknown or len(unknown) > 0:
+        # Print any unknown arguments passed to this script and fix them with low priority
+        print("[Low Proiority][To-Fix] Found unknown args: %s" % ', '.join(unknown))
+
+    args.start_time = datetime.strptime(args.start_time, "%Y-%m-%dT%H:%M:%SZ")
+
+    exit_code = 999
+    actual_ops = []
+
+    for i in range(0, MAX_RETRY):
+        if args.command == "update_sequence":
+            exit_code, actual_ops = check_update_sequence(args)
+        elif args.command == "normal_ops_sequence":
+            exit_code, actual_ops = check_operation_sequence(args)
+        else:
+            print("No such command %s, exit code 5\n" % args.command)
+            exit_code, actual_ops = 5, []
+            break
+
+        if exit_code == 0:
+            break
+
+        print("{0} test failed with exit code: {1}; Retry attempt: {2}; Retrying in {3} secs".format(args.command,
+                                                                                                     exit_code, i,
+                                                                                                     SLEEP_TIMER))
+        time.sleep(SLEEP_TIMER)
+
+    if exit_code != 0:
+        print("Expected Operations: %s" % ", ".join(args.ops))
+        print("Actual Operations: %s" %
+              ','.join(["[%s, Date: %s]" % (op['op'], op['date'].strftime("%Y-%m-%dT%H:%M:%SZ")) for op in actual_ops]))
+
+    print("Assertion completed, exiting with code: %s" % exit_code)
+    sys.exit(exit_code)
+
+
+if __name__ == "__main__":
+    print("Asserting operations\n")
+    main()

tests_e2e/tests/scripts/extension_workflow-check_data_in_agent_log.py

@@ -0,0 +1,48 @@
+#!/usr/bin/env pypy3
+
+# Microsoft Azure Linux Agent
+#
+# Copyright 2018 Microsoft Corporation
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+
+import argparse
+import sys
+
+from pathlib import Path
+from tests_e2e.tests.lib.agent_log import AgentLog
+
+
+def main():
+    parser = argparse.ArgumentParser()
+    parser.add_argument("--data", dest='data', required=True)
+    args, _ = parser.parse_known_args()
+
+    print("Verifying data: {0} in waagent.log".format(args.data))
+    found = False
+
+    try:
+        found = AgentLog(Path('/var/log/waagent.log')).agent_log_contains(args.data)
+        if found:
+            print("Found data: {0} in agent log".format(args.data))
+        else:
+            print("Did not find data: {0} in agent log".format(args.data))
+    except Exception as e:
+        print("Error thrown when searching for test data in agent log: {0}".format(str(e)))
+
+    sys.exit(0 if found else 1)
+
+
+if __name__ == "__main__":
+    main()