Add unit test to verify call stacks on telemetry events

tests/common/test_event.py

@@ -17,26 +17,28 @@
 #
 from __future__ import print_function
 
+import json
 import os
 import re
 import shutil
 import threading
+import xml.dom
 from datetime import datetime, timedelta
-
+import azurelinuxagent.common.utils.textutil as textutil
 from azurelinuxagent.common import event, logger
 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
+from tests.protocol.mocks import mock_wire_protocol, HttpRequestPredicates, MockHttpResponse
 from azurelinuxagent.common.version import CURRENT_AGENT, CURRENT_VERSION, AGENT_EXECUTION_MODE
 from azurelinuxagent.common.osutil import get_osutil
 from tests.tools import AgentTestCase, data_dir, load_data, Mock, patch, skip_if_predicate_true
 from tests.utils.event_logger_tools import EventLoggerTools
 
 
-class TestEvent(AgentTestCase):
+class TestEvent(HttpRequestPredicates, AgentTestCase):
     def setUp(self):
         AgentTestCase.setUp(self)
 
@@ -660,6 +662,71 @@ def test_collect_events_should_add_all_the_parameters_in_the_telemetry_schema_to
     def test_collect_events_should_ignore_extra_parameters_in_extension_events(self):
         self._assert_extension_event_includes_all_parameters_in_the_telemetry_schema('custom_script_extra_parameters.tld')
 
+    def test_report_event_should_encode_call_stack_correctly(self):
+        """
+        The Message in some telemetry events that include call stacks are being truncated in Kusto. While the issue doesn't seem
+        to be in the agent itself, this test verifies that the Message of the event we send in the HTTP request matches the
+        Message we read from the event's file.
+        """
+        def get_event_message_from_event_file(event_file):
+            with open(event_file, "rb") as fd:
+                event_data = fd.read().decode("utf-8")  # event files are UTF-8 encoded
+            telemetry_event = json.loads(event_data)
+
+            for p in telemetry_event['parameters']:
+                if p['name'] == 'Message':
+                    return p['value']
+
+            raise ValueError('Could not find the Message for the telemetry event in {0}'.format(path))
+
+        def get_event_message_from_http_request_body(http_request_body):
+            # The XML for the event is sent over as a CDATA element ("Event") in the request's body
+            request_body_xml_doc = textutil.parse_doc(http_request_body)
+
+            event_node = textutil.find(request_body_xml_doc, "Event")
+            if event_node is None:
+                raise ValueError('Could not find the Event node in the XML document')
+            if len(event_node.childNodes) != 1:
+                raise ValueError('The Event node in the XML document should have exactly 1 child')
+
+            event_node_first_child = event_node.childNodes[0]
+            if event_node_first_child.nodeType != xml.dom.Node.CDATA_SECTION_NODE:
+                raise ValueError('The Event node contents should be CDATA')
+
+            event_node_cdata = event_node_first_child.nodeValue
+
+            # The CDATA will contain a sequence of "<Param Name='foo' Value='bar'/>" nodes, which
+            # correspond to the parameters of the telemetry event.  Wrap those into a "Helper" node
+            # and extract the "Message"
+            event_xml_text = '<?xml version="1.0"?><Helper>{0}</Helper>'.format(event_node_cdata)
+            event_xml_doc = textutil.parse_doc(event_xml_text)
+            helper_node = textutil.find(event_xml_doc, "Helper")
+
+            for child in helper_node.childNodes:
+                if child.getAttribute('Name') == 'Message':
+                    return child.getAttribute('Value')
+
+            raise ValueError('Could not find the Message for the telemetry event. Request body: {0}'.format(http_request_body))
+
+        def http_post_handler(url, body, **__):
+            if self.is_telemetry_request(url):
+                http_post_handler.request_body = body
+                return MockHttpResponse(status=200)
+            return None
+        http_post_handler.request_body = None
+
+        with mock_wire_protocol(mockwiredata.DATA_FILE, http_post_handler=http_post_handler) as protocol:
+            event_file_path = self._create_test_event_file("event_with_callstack.waagent.tld")
+            expected_message = get_event_message_from_event_file(event_file_path)
+
+            event_list = event.collect_events()
+
+            protocol.client.report_event(event_list)
+
+            event_message = get_event_message_from_http_request_body(http_post_handler.request_body)
+
+            self.assertEquals(event_message, expected_message, "The Message in the HTTP request does not match the Message in the event's *.tld file")
+
 
 class TestMetrics(AgentTestCase):
     @patch('azurelinuxagent.common.event.EventLogger.save_event')

tests/data/events/event_with_callstack.waagent.tld

@@ -0,0 +1 @@
+{"eventId": 1, "providerId": "69B669B9-4AF8-4C50-BDC4-6006FA76E975", "parameters": [{"name": "Name", "value": "WALinuxAgent"}, {"name": "Version", "value": "2.2.46"}, {"name": "Operation", "value": "FetchGoalState"}, {"name": "OperationSuccess", "value": false}, {"name": "Message", "value": "An error occurred while retrieving the goal state: Traceback (most recent call last):\n  File \"bin/WALinuxAgent-2.2.47/azurelinuxagent/common/protocol/wire.py\", line 715, in try_update_goal_state\n    self.update_goal_state()\n  File \"bin/WALinuxAgent-2.2.47/azurelinuxagent/common/protocol/wire.py\", line 708, in update_goal_state\n    WireClient._UpdateType.GoalStateForced if forced else WireClient._UpdateType.GoalState)\n  File \"bin/WALinuxAgent-2.2.47/azurelinuxagent/common/protocol/wire.py\", line 771, in _update_from_goal_state\n    raise ProtocolError(\"Exceeded max retry updating goal state\")\nazurelinuxagent.common.exception.ProtocolError: [ProtocolError] Exceeded max retry updating goal state\n"}, {"name": "Duration", "value": 0}, {"name": "GAVersion", "value": "WALinuxAgent-2.2.46"}, {"name": "ContainerId", "value": "ebd8bf98-8a26-4607-b82f-41333b65b587"}, {"name": "OpcodeName", "value": "2020-03-19T15:30:15.326391Z"}, {"name": "EventTid", "value": 140524239595328}, {"name": "EventPid", "value": 3264}, {"name": "TaskName", "value": "ExtHandler"}, {"name": "KeywordName", "value": ""}, {"name": "ExtensionType", "value": ""}, {"name": "IsInternal", "value": false}, {"name": "OSVersion", "value": "Linux:ubuntu-18.04-bionic:5.0.0-1032-azure"}, {"name": "ExecutionMode", "value": "IAAS"}, {"name": "RAM", "value": 7976}, {"name": "Processors", "value": 2}, {"name": "VMName", "value": "_nam-u18"}, {"name": "TenantName", "value": "1feb87ac-f8b5-427e-a5b3-563b34a3931a"}, {"name": "RoleName", "value": "_nam-u18"}, {"name": "RoleInstanceName", "value": "1feb87ac-f8b5-427e-a5b3-563b34a3931a._nam-u18"}, {"name": "Location", "value": "northcentralus"}, {"name": "SubscriptionId", "value": "2588be01-bc36-4aa0-bf22-db6efc2b58ae"}, {"name": "ResourceGroupName", "value": "narrieta-rg"}, {"name": "VMId", "value": "06a6333f-410e-4a8f-a93a-c5b6075dfdad"}, {"name": "ImageOrigin", "value": 2}], "file_type": ""}

tests/protocol/mocks.py

@@ -154,6 +154,10 @@ class HttpRequestPredicates(object):
     def is_goal_state_request(url):
         return url.lower() == 'http://{0}/machine/?comp=goalstate'.format(restutil.KNOWN_WIRESERVER_IP)
 
+    @staticmethod
+    def is_telemetry_request(url):
+        return url.lower() == 'http://{0}/machine?comp=telemetrydata'.format(restutil.KNOWN_WIRESERVER_IP)
+
     @staticmethod
     def is_in_vm_artifacts_profile_request(url):
         return re.match(r'https://.+\.blob\.core\.windows\.net/\$system/.+\.(vmSettings|settings)\?.+', url) is not None
@@ -185,3 +189,11 @@ def is_host_plugin_in_vm_artifacts_profile_request(url, request_kwargs):
         artifact_location = HttpRequestPredicates._get_host_plugin_request_artifact_location(url, request_kwargs)
         return HttpRequestPredicates.is_in_vm_artifacts_profile_request(artifact_location)
 
+
+class MockHttpResponse:
+    def __init__(self, status, body=''):
+        self.body = body
+        self.status = status
+
+    def read(self, *_):
+        return self.body