Repository: Azure/WALinuxAgent
Pull request #1895 (2020-05-26 23:52:03)

Add logging for version mismatch
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description
This PR is for reporting an event incase the <Plugin> version and <PluginRuntimeSettings> version dont match. 
This PR also include a new class called AgentGlobals which should be used for all globals being used in the agent.

This is a repair item being tracked by - https://msazure.visualstudio.com/One/_workitems/edit/5813935

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).
- [ ] Except for special cases involving multiple contributors, the PR is started from a fork of the main repository, not a branch.
- [ ] If applicable, the PR references the bug/issue that it fixes in the description.
- [ ] New Unit tests were added for the changes made and Travis.CI is passing.

### 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://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=h1) Report
> Merging [#1895](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=desc) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/e361a69e77a3c36c89e192d4a8709ebe2fed0c5f&el=desc) will **increase** coverage by `0.03%`.
> The diff coverage is `92.30%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895/graphs/tree.svg?width=650&height=150&src=pr&token=ae90E2KYCw)](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=tree)

```diff
@@             Coverage Diff             @@
##           develop    #1895      +/-   ##
===========================================
+ Coverage    69.24%   69.27%   +0.03%     
===========================================
  Files           83       84       +1     
  Lines        11483    11502      +19     
  Branches      1597     1601       +4     
===========================================
+ Hits          7951     7968      +17     
- Misses        3193     3194       +1     
- Partials       339      340       +1     
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/protocol/goal\_state.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9wcm90b2NvbC9nb2FsX3N0YXRlLnB5) | `93.79% <87.50%> (-0.50%)` | :arrow_down: |
| [azurelinuxagent/common/AgentGlobals.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9BZ2VudEdsb2JhbHMucHk=) | `100.00% <100.00%> (ø)` | |
| [azurelinuxagent/common/event.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9ldmVudC5weQ==) | `86.34% <100.00%> (+0.03%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=footer). Last update [e361a69...6720015](https://codecov.io/gh/Azure/WALinuxAgent/pull/1895?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

larohra: DCR run - https://tuxgold.corp.microsoft.com/job/AzLinux/job/DungeonCrawler/job/DungeonCrawler.larohra2/473/artifact/results/

Patch:
diff --git a/azurelinuxagent/common/AgentGlobals.py b/azurelinuxagent/common/AgentGlobals.py
new file mode 100644
index 00000000..287dc486
--- /dev/null
+++ b/azurelinuxagent/common/AgentGlobals.py
@@ -0,0 +1,37 @@
+# Microsoft Azure Linux Agent
+#
+# Copyright 2020 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.
+#
+# Requires Python 2.6+ and Openssl 1.0+
+
+
+class AgentGlobals(object):
+    """
+    This class is used for setting AgentGlobals which can be used all throughout the Agent.
+    """
+
+    #
+    # Some modules (e.g. telemetry) require an up-to-date container ID. We update this variable each time we
+    # fetch the goal state.
+    #
+    _container_id = "00000000-0000-0000-0000-000000000000"
+
+    @staticmethod
+    def get_container_id():
+        return AgentGlobals._container_id
+
+    @staticmethod
+    def update_container_id(container_id):
+        AgentGlobals._container_id = container_id
\ No newline at end of file
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index f7060b9a..9b4fc01d 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -28,6 +28,7 @@ from datetime import datetime
 
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
+from azurelinuxagent.common.AgentGlobals import AgentGlobals
 from azurelinuxagent.common.exception import EventError, OSUtilError
 from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.datacontract import get_properties, set_properties
@@ -37,7 +38,6 @@ from azurelinuxagent.common.utils import fileutil, textutil
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, getattrib
 from azurelinuxagent.common.version import CURRENT_VERSION, CURRENT_AGENT, DISTRO_NAME, DISTRO_VERSION, DISTRO_CODE_NAME, AGENT_EXECUTION_MODE
 from azurelinuxagent.common.telemetryevent import TelemetryEventList
-from azurelinuxagent.common.protocol.goal_state import GoalState
 from azurelinuxagent.common.protocol.imds import get_imds_client
 
 EVENTS_DIRECTORY = "events"
@@ -98,6 +98,7 @@ class WALAEventOperation:
     Log = "Log"
     OSInfo = "OSInfo"
     Partition = "Partition"
+    PluginSettingsVersionMismatch = "PluginSettingsVersionMismatch"
     ProcessGoalState = "ProcessGoalState"
     Provision = "Provision"
     ProvisionGuestAgent = "ProvisionGuestAgent"
@@ -531,7 +532,7 @@ class EventLogger(object):
         Note that the event timestamp is saved in the OpcodeName field.
         """
         common_params = [TelemetryEventParam('GAVersion', CURRENT_AGENT),
-                         TelemetryEventParam('ContainerId', GoalState.ContainerID),
+                         TelemetryEventParam('ContainerId', AgentGlobals.get_container_id()),
                          TelemetryEventParam('OpcodeName', event_timestamp.strftime(u'%Y-%m-%dT%H:%M:%S.%fZ')),
                          TelemetryEventParam('EventTid', threading.current_thread().ident),
                          TelemetryEventParam('EventPid', os.getpid()),
diff --git a/azurelinuxagent/common/protocol/goal_state.py b/azurelinuxagent/common/protocol/goal_state.py
index 8787c09b..56243600 100644
--- a/azurelinuxagent/common/protocol/goal_state.py
+++ b/azurelinuxagent/common/protocol/goal_state.py
@@ -22,11 +22,14 @@ import re
 
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
-from azurelinuxagent.common.datacontract import set_properties, DataContract, DataContractList
+from azurelinuxagent.common.AgentGlobals import AgentGlobals
+from azurelinuxagent.common.datacontract import set_properties
+from azurelinuxagent.common.event import add_event, WALAEventOperation
+from azurelinuxagent.common.protocol.restapi import *
 from azurelinuxagent.common.utils import fileutil
 from azurelinuxagent.common.utils.cryptutil import CryptUtil
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, findtext, getattrib, gettext
-from azurelinuxagent.common.protocol.restapi import *
+from azurelinuxagent.common.version import AGENT_NAME
 
 GOAL_STATE_URI = "http://{0}/machine/?comp=goalstate"
 CERTS_FILE_NAME = "Certificates.xml"
@@ -37,11 +40,6 @@ TRANSPORT_PRV_FILE_NAME = "TransportPrivate.pem"
 
 
 class GoalState(object):
-    #
-    # Some modules (e.g. telemetry) require an up-to-date container ID. We update this variable each time we
-    # fetch the goal state.
-    #
-    ContainerID = "00000000-0000-0000-0000-000000000000"
 
     def __init__(self, wire_client, full_goal_state=False, base_incarnation=None):
         """
@@ -72,7 +70,7 @@ class GoalState(object):
         lbprobe_ports = find(xml_doc, "LBProbePorts")
         self.load_balancer_probe_port = findtext(lbprobe_ports, "Port")
 
-        GoalState.ContainerID = self.container_id
+        AgentGlobals.update_container_id(self.container_id)
 
         fetch_full_goal_state = False
         if full_goal_state:
@@ -341,13 +339,25 @@ class ExtensionsConfig(object):
 
         name = ext_handler.name
         version = ext_handler.properties.version
-        settings = [x for x in plugin_settings \
-                    if getattrib(x, "name") == name and \
-                    getattrib(x, "version") == version]
 
-        if settings is None or len(settings) == 0:
+        ext_handler_plugin_settings = [x for x in plugin_settings if getattrib(x, "name") == name]
+        if ext_handler_plugin_settings is None or len(ext_handler_plugin_settings) == 0:
             return
 
+        settings = [x for x in ext_handler_plugin_settings if getattrib(x, "version") == version]
+        if len(settings) != len(ext_handler_plugin_settings):
+            msg = "ExtHandler PluginSettings Version Mismatch! Expected PluginSettings version: {0} for Handler: " \
+                  "{1} but found versions: ({2})".format(version, name, ', '.join(
+                set([getattrib(x, "version") for x in ext_handler_plugin_settings])))
+            add_event(AGENT_NAME, op=WALAEventOperation.PluginSettingsVersionMismatch, message=msg, log_event=False,
+                      is_success=False)
+            if len(settings) == 0:
+                # If there is no corresponding settings for the specific extension handler, we will not process it at all,
+                # this is an unexpected error as we always expect both versions to be in sync.
+                logger.error(msg)
+                return
+            logger.warn(msg)
+
         runtime_settings = None
         runtime_settings_node = find(settings[0], "RuntimeSettings")
         seqNo = getattrib(runtime_settings_node, "seqNo")


Test patch:
diff --git a/tests/common/test_event.py b/tests/common/test_event.py
index acc22ae7..83971da2 100644
--- a/tests/common/test_event.py
+++ b/tests/common/test_event.py
@@ -26,10 +26,10 @@ import xml.dom
 from datetime import datetime, timedelta
 import azurelinuxagent.common.utils.textutil as textutil
 from azurelinuxagent.common import event, logger
+from azurelinuxagent.common.AgentGlobals import AgentGlobals
 from azurelinuxagent.common.event import add_event, add_periodic, add_log_event, elapsed_milliseconds, report_metric, \
     WALAEventOperation, parse_xml_event, parse_json_event, AGENT_EVENT_FILE_EXTENSION, EVENTS_DIRECTORY
 from azurelinuxagent.common.future import ustr
-from azurelinuxagent.common.protocol.goal_state import GoalState
 from tests.protocol import mockwiredata
 from tests.protocol.mocks import mock_wire_protocol, HttpRequestPredicates, MockHttpResponse
 from azurelinuxagent.common.version import CURRENT_AGENT, CURRENT_VERSION, AGENT_EXECUTION_MODE
@@ -51,7 +51,7 @@ class TestEvent(HttpRequestPredicates, AgentTestCase):
             # common parameters computed at event creation; the timestamp (stored as the opcode name) is not included here and
             # is checked separately from these parameters
             'GAVersion': CURRENT_AGENT,
-            'ContainerId': GoalState.ContainerID,
+            'ContainerId': AgentGlobals.get_container_id(),
             'EventTid': threading.current_thread().ident,
             'EventPid': os.getpid(),
             'TaskName': threading.current_thread().getName(),
diff --git a/tests/data/wire/ext_conf_plugin_settings_version_mismatch.xml b/tests/data/wire/ext_conf_plugin_settings_version_mismatch.xml
new file mode 100644
index 00000000..5b111004
--- /dev/null
+++ b/tests/data/wire/ext_conf_plugin_settings_version_mismatch.xml
@@ -0,0 +1,29 @@
+<Extensions version="1.0.0.0" goalStateIncarnation="9"><GuestAgentExtension xmlns:i="http://www.w3.org/2001/XMLSchema-instance">
+  <GAFamilies>
+    <GAFamily>
+      <Name>Prod</Name>
+      <Uris>
+          <Uri>http://mock-goal-state/manifest_of_ga.xml</Uri>
+      </Uris>
+    </GAFamily>
+    <GAFamily>
+      <Name>Test</Name>
+      <Uris>
+          <Uri>http://mock-goal-state/manifest_of_ga.xml</Uri>
+        </Uris>
+    </GAFamily>
+  </GAFamilies>
+</GuestAgentExtension>
+<Plugins>
+  <Plugin name="OSTCExtensions.ExampleHandlerLinux" version="1.0.0" location="http://mock-goal-state/rdfepirv2hknprdstr03.blob.core.windows.net/b01058962be54ceca550a390fa5ff064/Microsoft.OSTCExtensions_ExampleHandlerLinux_asiaeast_manifest.xml" config="" state="enabled" autoUpgrade="false" failoverlocation="http://mock-goal-state/rdfepirv2hknprdstr04.blob.core.windows.net/b01058962be54ceca550a390fa5ff064/Microsoft.OSTCExtensions_ExampleHandlerLinux_asiaeast_manifest.xml" runAsStartupTask="false" isJson="true" />
+</Plugins>
+<PluginSettings>
+  <Plugin name="OSTCExtensions.ExampleHandlerLinux" version="1.0.1">
+    <RuntimeSettings seqNo="0">{"runtimeSettings":[{"handlerSettings":{"protectedSettingsCertThumbprint":"4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3","protectedSettings":"MIICWgYJK","publicSettings":{"foo":"bar"}}}]}</RuntimeSettings>
+  </Plugin>
+  <Plugin name="OSTCExtensions.ExampleHandlerLinux" version="1.0.2">
+    <RuntimeSettings seqNo="0">{"runtimeSettings":[{"handlerSettings":{"protectedSettingsCertThumbprint":"4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3","protectedSettings":"MIICWgYJK","publicSettings":{"foo":"bar"}}}]}</RuntimeSettings>
+  </Plugin>
+</PluginSettings>
+<StatusUploadBlob statusBlobType="BlockBlob">https://test.blob.core.windows.net/vhds/test-cs12.test-cs12.test-cs12.status?sr=b&amp;sp=rw&amp;se=9999-01-01&amp;sk=key1&amp;sv=2014-02-14&amp;sig=hfRh7gzUE7sUtYwke78IOlZOrTRCYvkec4hGZ9zZzXo</StatusUploadBlob></Extensions>
+
diff --git a/tests/ga/test_exthandlers.py b/tests/ga/test_exthandlers.py
index 9758c5b0..93a45089 100644
--- a/tests/ga/test_exthandlers.py
+++ b/tests/ga/test_exthandlers.py
@@ -20,18 +20,16 @@ import os
 import subprocess
 import time
 
-from azurelinuxagent.common.protocol.util import ProtocolUtil
-
 from azurelinuxagent.common.cgroupconfigurator import CGroupConfigurator
-from azurelinuxagent.common.event import WALAEventOperation, AGENT_EVENT_FILE_EXTENSION
-from azurelinuxagent.common.exception import ProtocolError, ExtensionError, ExtensionErrorCodes
+from azurelinuxagent.common.event import AGENT_EVENT_FILE_EXTENSION, WALAEventOperation
+from azurelinuxagent.common.exception import ExtensionError, ExtensionErrorCodes
 from azurelinuxagent.common.protocol.restapi import ExtensionStatus, Extension, ExtHandler, ExtHandlerProperties
+from azurelinuxagent.common.protocol.util import ProtocolUtil
 from azurelinuxagent.common.utils.extensionprocessutil import TELEMETRY_MESSAGE_MAX_LEN, format_stdout_stderr, \
     read_output
-from mock import MagicMock
-from azurelinuxagent.common.protocol.wire import WireProtocol
-from azurelinuxagent.ga.exthandlers import parse_ext_status, ExtHandlerInstance, get_exthandlers_handler, \
-    ExtCommandEnvVariable
+from azurelinuxagent.ga.exthandlers import parse_ext_status, ExtHandlerInstance, ExtCommandEnvVariable
+from tests.protocol import mockwiredata
+from tests.protocol.mocks import mock_wire_protocol
 from tests.tools import AgentTestCase, patch, mock_sleep, clear_singleton_instances
 
 
@@ -249,6 +247,22 @@ class TestExtHandlers(AgentTestCase):
                                               disk_sequence_number=3,
                                               expected_sequence_number=-1)
 
+    def test_it_should_report_error_if_plugin_settings_version_mismatch(self):
+        with mock_wire_protocol(mockwiredata.DATA_FILE_PLUGIN_SETTINGS_MISMATCH) as protocol:
+            with patch("azurelinuxagent.common.protocol.goal_state.add_event") as mock_add_event:
+                # Forcing update of GoalState to allow the ExtConfig to report an event
+                protocol.mock_wire_data.set_incarnation(2)
+                protocol.client.update_goal_state()
+                plugin_setting_mismatch_calls = [kw for _, kw in mock_add_event.call_args_list if
+                                                 kw['op'] == WALAEventOperation.PluginSettingsVersionMismatch]
+                self.assertEqual(1, len(plugin_setting_mismatch_calls),
+                                 "PluginSettingsMismatch event should be reported once")
+                self.assertIn('ExtHandler PluginSettings Version Mismatch! Expected PluginSettings version: 1.0.0 for Handler: OSTCExtensions.ExampleHandlerLinux'
+                              , plugin_setting_mismatch_calls[0]['message'],
+                    "Invalid error message with incomplete data detected for PluginSettingsVersionMismatch")
+                self.assertTrue("1.0.2" in plugin_setting_mismatch_calls[0]['message'] and "1.0.1" in plugin_setting_mismatch_calls[0]['message'],
+                              "Error message should contain the incorrect versions")
+                self.assertFalse(plugin_setting_mismatch_calls[0]['is_success'], "The event should be false")
 
 class LaunchCommandTestCase(AgentTestCase):
     """
diff --git a/tests/protocol/mockwiredata.py b/tests/protocol/mockwiredata.py
index 8fb88dd7..3cb53f02 100644
--- a/tests/protocol/mockwiredata.py
+++ b/tests/protocol/mockwiredata.py
@@ -87,6 +87,9 @@ DATA_FILE_REMOTE_ACCESS = DATA_FILE.copy()
 DATA_FILE_REMOTE_ACCESS["goal_state"] = "wire/goal_state_remote_access.xml"
 DATA_FILE_REMOTE_ACCESS["remote_access"] = "wire/remote_access_single_account.xml"
 
+DATA_FILE_PLUGIN_SETTINGS_MISMATCH = DATA_FILE.copy()
+DATA_FILE_PLUGIN_SETTINGS_MISMATCH["ext_conf"] = "wire/ext_conf_plugin_settings_version_mismatch.xml"
+
 
 class WireProtocolData(object):
     def __init__(self, data_files=DATA_FILE):