Report useful message when extension processing is disabled

azurelinuxagent/ga/exthandlers.py

@@ -33,6 +33,7 @@
 
 from azurelinuxagent.common import conf
 from azurelinuxagent.common import logger
+from azurelinuxagent.common.osutil import get_osutil
 from azurelinuxagent.common.utils import fileutil
 from azurelinuxagent.common import version
 from azurelinuxagent.common.agent_supported_feature import get_agent_supported_features_list_for_extensions, \
@@ -299,7 +300,7 @@ def run(self):
             # we make a deep copy of the extensions, since changes are made to self.ext_handlers while processing the extensions
             self.ext_handlers = copy.deepcopy(egs.extensions)
 
-            if not self._extension_processing_allowed():
+            if self._extensions_on_hold():
                 return
 
             utc_start = datetime.datetime.utcnow()
@@ -433,17 +434,15 @@ def _cleanup_outdated_handlers(self):
                 except OSError as e:
                     logger.warn("Failed to remove extension package {0}: {1}".format(pkg, e.strerror))
 
-    def _extension_processing_allowed(self):
-        if not conf.get_extensions_enabled():
-            logger.verbose("Extension handling is disabled")
-            return False
-
+    def _extensions_on_hold(self):
         if conf.get_enable_overprovisioning():
             if self.protocol.get_goal_state().extensions_goal_state.on_hold:
-                logger.info("Extension handling is on hold")
-                return False
+                msg = "Extension handling is on hold"
+                logger.info(msg)
+                add_event(op=WALAEventOperation.ExtensionProcessing, message=msg)
+                return True
 
-        return True
+        return False
 
     @staticmethod
     def __get_dependency_level(tup):
@@ -478,10 +477,26 @@ def handle_ext_handlers(self, goal_state_id):
         max_dep_level = self.__get_dependency_level(all_extensions[-1]) if any(all_extensions) else 0
 
         depends_on_err_msg = None
+        extensions_enabled = conf.get_extensions_enabled()
         for extension, ext_handler in all_extensions:
 
             handler_i = ExtHandlerInstance(ext_handler, self.protocol, extension=extension)
 
+            # In case of extensions disabled, we skip processing extensions. But CRP is still waiting for some status
+            # back for the skipped extensions. In order to propagate the status back to CRP, we will report status back
+            # here with an error message.
+            if not extensions_enabled:
+                agent_conf_file_path = get_osutil().agent_conf_file_path
+                msg = "Extension will not be processed since extension processing is disabled. To enable extension " \
+                      "processing, set Extensions.Enabled=y in '{0}'".format(agent_conf_file_path)
+                handler_i.set_handler_status(status=ExtHandlerStatusValue.not_ready, message=msg, code=-1)
+                handler_i.create_status_file_if_not_exist(extension,
+                                                          status=ExtensionStatusValue.error,
+                                                          code=-1,
+                                                          operation=handler_i.operation,
+                                                          message=msg)
+                continue
+
             # In case of depends-on errors, we skip processing extensions if there was an error processing dependent extensions.
             # But CRP is still waiting for some status back for the skipped extensions. In order to propagate the status back to CRP,
             # we will report status back here with the relevant error message for each of the dependent extension.
@@ -991,7 +1006,9 @@ def report_ext_handler_status(self, vm_status, ext_handler, goal_state_changed):
         # For MultiConfig, we need to report status per extension even for Handler level failures.
         # If we have HandlerStatus for a MultiConfig handler and GS is requesting for it, we would report status per
         # extension even if HandlerState == NotInstalled (Sample scenario: ExtensionsGoalStateError, DecideVersionError, etc)
-        if handler_state != ExtHandlerState.NotInstalled or ext_handler.supports_multi_config:
+        # We also need to report extension status for an uninstalled handler if extensions are disabled because CRP
+        # waits for extension runtime status before failing the extension operation.
+        if handler_state != ExtHandlerState.NotInstalled or ext_handler.supports_multi_config or not conf.get_extensions_enabled():
 
             # Since we require reading the Manifest for reading the heartbeat, this would fail if HandlerManifest not found.
             # Only try to read heartbeat if HandlerState != NotInstalled.

tests/ga/test_extension.py

@@ -1649,7 +1649,19 @@ def test_extensions_disabled(self, _, *args):
         exthandlers_handler.run()
         exthandlers_handler.report_ext_handlers_status()
 
-        self._assert_no_handler_status(protocol.report_vm_status)
+        report_vm_status = protocol.report_vm_status
+        self.assertTrue(report_vm_status.called)
+        args, kw = report_vm_status.call_args  # pylint: disable=unused-variable
+        vm_status = args[0]
+        self.assertEqual(1, len(vm_status.vmAgent.extensionHandlers))
+        exthandler = vm_status.vmAgent.extensionHandlers[0]
+        self.assertEqual(-1, exthandler.code)
+        self.assertEqual('NotReady', exthandler.status)
+        self.assertEqual("Extension will not be processed since extension processing is disabled. To enable extension processing, set Extensions.Enabled=y in '/etc/waagent.conf'", exthandler.message)
+        ext_status = exthandler.extension_status
+        self.assertEqual(-1, ext_status.code)
+        self.assertEqual('error', ext_status.status)
+        self.assertEqual("Extension will not be processed since extension processing is disabled. To enable extension processing, set Extensions.Enabled=y in '/etc/waagent.conf'", ext_status.message)
 
     def test_extensions_deleted(self, *args):
         # Ensure initial enable is successful

tests_e2e/tests/extensions_disabled/extensions_disabled.py

@@ -24,9 +24,10 @@
 
 import datetime
 import pytz
+import uuid
 
 from assertpy import assert_that, fail
-from typing import Any, Dict, List
+from typing import Any
 
 from azure.mgmt.compute.models import VirtualMachineInstanceView
 
@@ -39,39 +40,77 @@
 
 
 class ExtensionsDisabled(AgentTest):
+    class TestCase:
+        def __init__(self, extension: VirtualMachineExtensionClient, settings: Any):
+            self.extension = extension
+            self.settings = settings
+
     def run(self):
         ssh_client: SshClient = self._context.create_ssh_client()
 
         # Disable extension processing on the test VM
+        log.info("")
         log.info("Disabling extension processing on the test VM [%s]", self._context.vm.name)
         output = ssh_client.run_command("update-waagent-conf Extensions.Enabled=n", use_sudo=True)
         log.info("Disable completed:\n%s", output)
-
-        # From now on, extensions will time out; set the timeout to the minimum allowed(15 minutes)
-        log.info("Setting the extension timeout to 15 minutes")
-        vm: VirtualMachineClient = VirtualMachineClient(self._context.vm)
-
-        vm.update({"extensionsTimeBudget": "PT15M"})
-
         disabled_timestamp: datetime.datetime = datetime.datetime.utcnow() - datetime.timedelta(minutes=60)
 
-        #
-        # Validate that the agent is not processing extensions by attempting to run CustomScript
-        #
-        log.info("Executing CustomScript; it should time out after 15 min or so.")
-        custom_script = VirtualMachineExtensionClient(self._context.vm, VmExtensionIds.CustomScript, resource_name="CustomScript")
-        try:
-            custom_script.enable(settings={'commandToExecute': "date"}, force_update=True, timeout=20 * 60)
-            fail("CustomScript should have timed out")
-        except Exception as error:
-            assert_that("VMExtensionProvisioningTimeout" in str(error)) \
-                .described_as(f"Expected a VMExtensionProvisioningTimeout: {error}") \
-                .is_true()
-            log.info("CustomScript timed out as expected")
+        # Prepare test cases
+        unique = str(uuid.uuid4())
+        test_file = f"waagent-test.{unique}"
+        test_cases = [
+            ExtensionsDisabled.TestCase(
+                VirtualMachineExtensionClient(self._context.vm, VmExtensionIds.CustomScript,
+                                              resource_name="CustomScript"),
+                {'commandToExecute': f"echo '{unique}' > /tmp/{test_file}"}
+            ),
+            ExtensionsDisabled.TestCase(
+                VirtualMachineExtensionClient(self._context.vm, VmExtensionIds.RunCommandHandler,
+                                              resource_name="RunCommandHandler"),
+                {'source': {'script': f"echo '{unique}' > /tmp/{test_file}"}}
+            )
+        ]
+
+        for t in test_cases:
+            log.info("")
+            log.info("Test case: %s", t.extension)
+            #
+            # Validate that the agent is not processing extensions by attempting to enable extension & checking that
+            # provisioning fails fast
+            #
+            log.info(
+                "Executing {0}; the agent should report a VMExtensionProvisioningError without processing the extension"
+                .format(t.extension.__str__()))
+
+            try:
+                t.extension.enable(settings=t.settings, force_update=True, timeout=6 * 60)
+                fail("The agent should have reported an error processing the goal state")
+            except Exception as error:
+                assert_that("VMExtensionProvisioningError" in str(error)) \
+                    .described_as(f"Expected a VMExtensionProvisioningError error, but actual error was: {error}") \
+                    .is_true()
+                assert_that("Extension will not be processed since extension processing is disabled" in str(error)) \
+                    .described_as(
+                    f"Error message should communicate that extension will not be processed, but actual error "
+                    f"was: {error}").is_true()
+                log.info("Goal state processing for {0} failed as expected".format(t.extension.__str__()))
+
+            #
+            # Validate the agent did not process the extension by checking it did not execute the extension settings
+            #
+            output = ssh_client.run_command("dir /tmp", use_sudo=True)
+            assert_that(output) \
+                .described_as(
+                f"Contents of '/tmp' on test VM contains {test_file}. Contents: {output}. \n This indicates "
+                f"{t.extension.__str__()} was unexpectedly processed") \
+                .does_not_contain(f"{test_file}")
+            log.info("The agent did not process the extension settings for {0} as expected".format(t.extension.__str__()))
 
         #
         # Validate that the agent continued reporting status even if it is not processing extensions
         #
+        vm: VirtualMachineClient = VirtualMachineClient(self._context.vm)
+        log.info("")
         instance_view: VirtualMachineInstanceView = vm.get_instance_view()
         log.info("Instance view of VM Agent:\n%s", instance_view.vm_agent.serialize())
         assert_that(instance_view.vm_agent.statuses).described_as("The VM agent should have exactly 1 status").is_length(1)
@@ -82,10 +121,23 @@ def run(self):
             .is_greater_than(pytz.utc.localize(disabled_timestamp))
         log.info("The VM Agent reported status after extensions were disabled, as expected.")
 
-    def get_ignore_error_rules(self) -> List[Dict[str, Any]]:
-        return [
-            {'message': 'No handler status found for Microsoft.Azure.Extensions.CustomScript'},
-        ]
+        #
+        # Validate that the agent processes extensions after re-enabling extension processing
+        #
+        log.info("")
+        log.info("Enabling extension processing on the test VM [%s]", self._context.vm.name)
+        output = ssh_client.run_command("update-waagent-conf Extensions.Enabled=y", use_sudo=True)
+        log.info("Enable completed:\n%s", output)
+
+        for t in test_cases:
+            try:
+                log.info("")
+                log.info("Executing {0}; the agent should process the extension".format(t.extension.__str__()))
+                t.extension.enable(settings=t.settings, force_update=True, timeout=15 * 60)
+                log.info("Goal state processing for {0} succeeded as expected".format(t.extension.__str__()))
+            except Exception as error:
+                fail(f"Unexpected error while processing {t.extension.__str__()} after re-enabling extension "
+                     f"processing: {error}")
 
 
 if __name__ == "__main__":