Report useful message when extension processing is disabled

azurelinuxagent/ga/exthandlers.py

@@ -299,7 +299,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 +433,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 +476,25 @@ 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:
+                msg = "Extension will not be processed since extension processing is disabled. To enable extension " \
+                      "processing, set Extensions.Enabled=y in '/etc/waagent.conf'"
+                handler_i.set_handler_status(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 +1004,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.
@@ -1668,6 +1683,7 @@ def collect_ext_status(self, ext):
         # We did not encounter InvalidJsonFile/CouldNotReadStatusFile and thus the status file was correctly written
         # and has valid json.
         try:
+            msg = "data in status file is: {0}".format(data)
             parse_ext_status(ext_status, data)
             if len(data_str) > _MAX_STATUS_FILE_SIZE_IN_BYTES:
                 raise ExtensionStatusError(msg="For Extension Handler {0} for the sequence number {1}, the status "

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

@@ -33,6 +33,7 @@
 from tests_e2e.tests.lib.agent_test import AgentTest
 from tests_e2e.tests.lib.identifiers import VmExtensionIds
 from tests_e2e.tests.lib.logging import log
+from tests_e2e.tests.lib.shell import CommandError
 from tests_e2e.tests.lib.ssh_client import SshClient
 from tests_e2e.tests.lib.virtual_machine_client import VirtualMachineClient
 from tests_e2e.tests.lib.virtual_machine_extension_client import VirtualMachineExtensionClient
@@ -47,27 +48,43 @@ def run(self):
         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)
+        # Set the timeout to the minimum allowed(15 minutes) so we can check that the extension fails before timeout
         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
+        # Validate that the agent is not processing extensions by attempting to run CSE & checking that provisioning fails fast
         #
-        log.info("Executing CustomScript; it should time out after 15 min or so.")
+        log.info("Executing CustomScript; the agent should report a VMExtensionProvisioningError without processing the extension")
         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")
+            # Use mkdir in script settings so we can check if the command was executed
+            custom_script.enable(settings={'commandToExecute': "mkdir /var/lib/waagent/testdir"}, force_update=True, timeout=6 * 60)
+            fail("The agent should have reported an error processing the goal state")
         except Exception as error:
-            assert_that("VMExtensionProvisioningTimeout" in str(error)) \
-                .described_as(f"Expected a VMExtensionProvisioningTimeout: {error}") \
+            assert_that("VMExtensionProvisioningError" in str(error)) \
+                .described_as(f"Expected a VMExtensionProvisioningError error, but actual error was: {error}") \
                 .is_true()
-            log.info("CustomScript timed out as expected")
+            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 failed as expected")
+
+        #
+        # Validate the agent is not processing extensions by checking it did not execute the extension settings
+        #
+        try:
+            ssh_client.run_command("dir /var/lib/waagent/testdir", use_sudo=True)
+            fail("The extension settings should not have been executed")
+        except CommandError as error:
+            assert_that(error.stderr)\
+                .described_as("Extension should not be processed, but extension settings were executed")\
+                .contains('No such file or directory')
+            log.info("The agent did not execute the extension settings as expected")
+
 
         #
         # Validate that the agent continued reporting status even if it is not processing extensions
@@ -82,6 +99,19 @@ def run(self):
             .is_greater_than(pytz.utc.localize(disabled_timestamp))
         log.info("The VM Agent reported status after extensions were disabled, as expected.")
 
+        #
+        # Validate that the agent processes extensions after re-enabling extension processing
+        #
+        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)
+
+        try:
+            custom_script.enable(settings={'commandToExecute': "date"}, force_update=True, timeout=15 * 60)
+        except Exception as error:
+            log.info("Goal state processing unexpectedly failed after re-enabling extension processing")
+
+
     def get_ignore_error_rules(self) -> List[Dict[str, Any]]:
         return [
             {'message': 'No handler status found for Microsoft.Azure.Extensions.CustomScript'},