From b69411dc4e940fe4fc1e12fb77a924b75c0148cf Mon Sep 17 00:00:00 2001 From: nam Date: Thu, 19 Mar 2020 21:10:09 -0700 Subject: [PATCH 1/4] Add unit test to verify callstacks on telemetry events --- tests/common/test_event.py | 73 ++++++++++++++++++- .../events/event_with_callstack.waagent.tld | 1 + tests/protocol/mocks.py | 12 +++ 3 files changed, 83 insertions(+), 3 deletions(-) create mode 100644 tests/data/events/event_with_callstack.waagent.tld diff --git a/tests/common/test_event.py b/tests/common/test_event.py index f438d65c2a..97c691577b 100644 --- a/tests/common/test_event.py +++ b/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(path): + with open(path, 'rb') as f: + data = f.read() + telemetry_event = json.loads(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 "" nodes, which + # correspond to the parameters of the telemetry event. Wrap those into a "Helper" node + # and extract the "Message" + event_xml_text = '{0}'.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) + class TestMetrics(AgentTestCase): @patch('azurelinuxagent.common.event.EventLogger.save_event') diff --git a/tests/data/events/event_with_callstack.waagent.tld b/tests/data/events/event_with_callstack.waagent.tld new file mode 100644 index 0000000000..b490ea8c35 --- /dev/null +++ b/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": ""} \ No newline at end of file diff --git a/tests/protocol/mocks.py b/tests/protocol/mocks.py index 690ffdbb76..7172ce5f54 100644 --- a/tests/protocol/mocks.py +++ b/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 From dac9eaf7d48cb385a0f24c309dd31dd6236e0222 Mon Sep 17 00:00:00 2001 From: nam Date: Thu, 19 Mar 2020 21:19:27 -0700 Subject: [PATCH 2/4] Read file as UTF-8 --- tests/common/test_event.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/common/test_event.py b/tests/common/test_event.py index 97c691577b..b73f755535 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -668,10 +668,10 @@ def test_report_event_should_encode_call_stack_correctly(self): 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(path): - with open(path, 'rb') as f: - data = f.read() - telemetry_event = json.loads(data) + def get_event_message_from_event_file(event_file): + with open(event_file, "rb") as fd: + event_data = fd.read().decode("utf-8") # this is the same way that event.collect_events reads event files + telemetry_event = json.loads(event_data) for p in telemetry_event['parameters']: if p['name'] == 'Message': From ad2e952f95d95490c70810e8da65e16ad2a9e23c Mon Sep 17 00:00:00 2001 From: nam Date: Thu, 19 Mar 2020 21:30:23 -0700 Subject: [PATCH 3/4] added message to assert --- tests/common/test_event.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/common/test_event.py b/tests/common/test_event.py index b73f755535..77720b4e50 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -725,7 +725,7 @@ def http_post_handler(url, body, **__): event_message = get_event_message_from_http_request_body(http_post_handler.request_body) - self.assertEquals(event_message, expected_message) + 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): From a3a2f5b5922692ce4a4268422be35c6400ae40ba Mon Sep 17 00:00:00 2001 From: nam Date: Fri, 20 Mar 2020 08:16:14 -0700 Subject: [PATCH 4/4] update comment --- tests/common/test_event.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/common/test_event.py b/tests/common/test_event.py index 77720b4e50..acc22ae780 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -670,7 +670,7 @@ def test_report_event_should_encode_call_stack_correctly(self): """ def get_event_message_from_event_file(event_file): with open(event_file, "rb") as fd: - event_data = fd.read().decode("utf-8") # this is the same way that event.collect_events reads event files + 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']: