Repository: Azure/WALinuxAgent
Pull request #2895 (2023-08-10 22:50:01)

Report useful message when extension processing is disabled
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description
The change in this PR updates the agent to fail extensions fast with a useful message when extension processing is disabled.

Run for extensions_disabled e2e test scenario: https://dev.azure.com/cplatruntime/WALinuxAgent/_build/results?buildId=7141&view=results

CRP logs show the extension provisioning is failed before the extension timeout period (in this case 15 minutes), with a useful message telling the customer how they can enable extensions:
<span>Execute in [<a href="https://dataexplorer.azure.com/clusters/azcore.centralus/databases/Crp?query=H4sIAAAAAAAAA2VPXWvCMBR9368IfbGFpsR0ggx8kFlkMIdjsj1KbC82W0zCzY2VsR+/lMEQfLv3cD5bEwMB5hP13aKvvtLnqkHbzg2hskCTouoUqYMKkE8SY6+M8ei6hC+9fnWhOYOlvXV2DXT3w4YeENgWodUBdvoEb6ROnh2ABgDL8mQGlOBcCllzMedTsZPyoRZFVcm++HdACC5iC2t00b+oE7BeBZYZHRT/WD5rGy/LY0rmo4+YTwWXsr6fCV7XMw4iuzaKhh5dB2yxYNn7prkQ2KCd3aI76/HQ9tggOhxFadsntHSzoGTOAypK9LFNyUA2q/gHPNmNNqkZtM52oWQ9kU8iimGMLa8qJNkYtAJS2oRfxAcxHHwBAAA=">Web</a>] [<a href="https://azcore.centralus.kusto.windows.net/Crp?query=H4sIAAAAAAAAA2VPXWvCMBR9368IfbGFpsR0ggx8kFlkMIdjsj1KbC82W0zCzY2VsR+/lMEQfLv3cD5bEwMB5hP13aKvvtLnqkHbzg2hskCTouoUqYMKkE8SY6+M8ei6hC+9fnWhOYOlvXV2DXT3w4YeENgWodUBdvoEb6ROnh2ABgDL8mQGlOBcCllzMedTsZPyoRZFVcm++HdACC5iC2t00b+oE7BeBZYZHRT/WD5rGy/LY0rmo4+YTwWXsr6fCV7XMw4iuzaKhh5dB2yxYNn7prkQ2KCd3aI76/HQ9tggOhxFadsntHSzoGTOAypK9LFNyUA2q/gHPNmNNqkZtM52oWQ9kU8iimGMLa8qJNkYtAJS2oRfxAcxHHwBAAA=&web=0">Desktop</a>]</span> [<a href="https://dataexplorer.azure.com/clusters/azcore.centralus/databases/Crp">cluster('azcore.centralus.kusto.windows.net').database('Crp')</a>]<div style="color: #000000;background-color: #fffffe;font-family: 'Droid Sans Mono', 'monospace', monospace;font-weight: normal;font-size: 14px;line-height: 19px;white-space: pre;"><div><span style="color: #000000;">cluster('azcrp.kusto.windows.net').database('crp_allprod').ApiQosEvent_nonGet</span></div><div><span style="color: #000000;">| where PreciseTimeStamp between (datetime(2023-08-10T22:30)..2h)</span></div><div><span style="color: #000000;">| where resourceGroupName has "lisa-WALinuxAgent-20230810-223450-335-e0"</span></div><div><span style="color: #000000;">| where resultCode == "VMExtensionProvisioningError"</span></div><div><span style="color: #000000;">| project PreciseTimeStamp, operationName, e2EDurationInMilliseconds, httpStatusCode, resultCode, errorDetails</span></div><br></div><div><br/><br/><header>Table0</header>

PreciseTimeStamp | operationName | e2EDurationInMilliseconds | httpStatusCode | resultCode | errorDetails
-- | -- | -- | -- | -- | --
2023-08-10T22:41:50.0933214Z | VMExtensions.VMExtensionOperation.PUT | 298,610 | 201 | VMExtensionProvisioningError | VM has reported a failure when processing extension 'CustomScript' (publisher 'Microsoft.Azure.Extensions' and type 'CustomScript'). Error message: "Extension will not be processed since extension processing is disabled. To enable extension processing, set Extensions.Enabled=y in '/etc/waagent.conf'". More information on troubleshooting is available at https://aka.ms/VMExtensionCSELinuxTroubleshoot.

</div>

Agent logs show placeholder status file created for the extension with error status:
```
2023-08-10T22:41:49.751214Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState started [incarnation_2 channel: WireServer source: Fabric activity: 258f78d2-25db-4623-814c-324acfc54030 correlation ada2bb69-601f-44ca-9da7-8d10e34ad266 created: 2023-08-10T22:36:51.555367Z]
2023-08-10T22:41:49.752157Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Creating a placeholder status file /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.10/status/0.status with status: error
2023-08-10T22:41:49.753612Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState completed [incarnation_2 2 ms]

2023-08-10T22:41:49.778851Z INFO ExtHandler ExtHandler Extension status: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
2023-08-10T22:41:49.779491Z INFO ExtHandler ExtHandler All extensions in the goal state have reached a terminal state: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
```

Issue # <!-- if any -->
<!--
Please add an informative description that covers that changes made by the pull request. 
This checklist is used to make sure that common issues in a pull request are addressed.
This will expedite the process of getting your pull request merged and avoid extra work on your part to fix issues discovered during the review process.
-->

---

### PR information
- [ ] The title of the PR is clear and informative.
- [ ] There are a small number of commits, each of which has an informative message. This means that previously merged commits do not appear in the history of the PR. For information on cleaning up the commits in your pull request, [see this page](https://github.com/Azure/azure-powershell/blob/master/documentation/development-docs/cleaning-up-commits.md).
- [ ] If applicable, the PR references the bug/issue that it fixes in the description.
- [ ] New Unit tests were added for the changes made

### Quality of Code and Contribution Guidelines
- [ ] I have read the [contribution guidelines](https://github.com/Azure/WALinuxAgent/blob/master/.github/CONTRIBUTING.md).

codecov[bot]: ## [Codecov](https://app.codecov.io/gh/Azure/WALinuxAgent/pull/2895?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) Report
> Merging [#2895](https://app.codecov.io/gh/Azure/WALinuxAgent/pull/2895?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (bd3682b) into [develop](https://app.codecov.io/gh/Azure/WALinuxAgent/commit/09ffc8f1f035520cd7920646a1dc830d758e502b?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (09ffc8f) will **increase** coverage by `0.01%`.
> Report is 1 commits behind head on develop.
> The diff coverage is `100.00%`.

```diff
@@             Coverage Diff             @@
##           develop    #2895      +/-   ##
===========================================
+ Coverage    71.96%   71.97%   +0.01%     
===========================================
  Files          106      106              
  Lines        16027    16033       +6     
  Branches      2300     2300              
===========================================
+ Hits         11534    11540       +6     
  Misses        3959     3959              
  Partials       534      534              
```


| [Files Changed](https://app.codecov.io/gh/Azure/WALinuxAgent/pull/2895?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/ga/exthandlers.py](https://app.codecov.io/gh/Azure/WALinuxAgent/pull/2895?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2V4dGhhbmRsZXJzLnB5) | `86.12% <100.00%> (+0.06%)` | :arrow_up: |



Patch:
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index 0aa4ed93..465c3cab 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -33,6 +33,7 @@ from functools import partial
 
 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 @@ class ExtHandlersHandler(object):
             # 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 @@ class ExtHandlersHandler(object):
                 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 @@ class ExtHandlersHandler(object):
         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 @@ class ExtHandlersHandler(object):
         # 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.


Test patch:
diff --git a/tests/ga/test_extension.py b/tests/ga/test_extension.py
index 201868fc..ff7f1700 100644
--- a/tests/ga/test_extension.py
+++ b/tests/ga/test_extension.py
@@ -1649,7 +1649,19 @@ class TestExtension_Deprecated(TestExtensionBase):
         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
diff --git a/tests_e2e/tests/extensions_disabled/extensions_disabled.py b/tests_e2e/tests/extensions_disabled/extensions_disabled.py
index 66cafcfc..27c62427 100755
--- a/tests_e2e/tests/extensions_disabled/extensions_disabled.py
+++ b/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 @@ from tests_e2e.tests.lib.virtual_machine_extension_client import VirtualMachineE
 
 
 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 @@ class ExtensionsDisabled(AgentTest):
             .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__":