From 4e5553f9542609589da92e753bd42476bb79b34d Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 9 Oct 2019 23:08:09 -0700 Subject: [PATCH 01/11] Changing add_event to start sending missing fields --- azurelinuxagent/common/event.py | 129 +++++++++++++++++++------------- tests/common/test_event.py | 85 +++++++++++++++++---- tests/common/test_logger.py | 2 +- 3 files changed, 148 insertions(+), 68 deletions(-) diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index d5af3275b4..02243e5d50 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -242,57 +242,55 @@ def is_period_elapsed(self, delta, h): return h not in self.periodic_events or \ (self.periodic_events[h] + delta) <= datetime.now() - def add_periodic(self, - delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, - version=CURRENT_VERSION, message="", evt_type="", - is_internal=False, log_event=True, force=False): - + def add_periodic(self, delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="", evt_type="", is_internal=False, log_event=True, + force=False, event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", keyword_name=""): h = hash(name + op + ustr(is_success) + message) if force or self.is_period_elapsed(delta, h): - self.add_event(name, - op=op, is_success=is_success, duration=duration, + self.add_event(name, op=op, is_success=is_success, duration=duration, version=version, message=message, evt_type=evt_type, - is_internal=is_internal, log_event=log_event) + is_internal=is_internal, log_event=log_event, + event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, + task_name=task_name, keyword_name=keyword_name) self.periodic_events[h] = datetime.now() - def add_event(self, - name, - op=WALAEventOperation.Unknown, - is_success=True, - duration=0, - version=CURRENT_VERSION, - message="", - evt_type="", - is_internal=False, - log_event=True): + def add_event(self, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), + message="", evt_type="", is_internal=False, log_event=True, + event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", + keyword_name=""): if (not is_success) and log_event: _log_event(name, op, message, duration, is_success=is_success) - self._add_event(duration, evt_type, is_internal, is_success, message, name, op, version, event_id=1) + self._add_event(duration, evt_type, is_internal, is_success, message, name, op, version, event_id=1, + event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, + task_name=task_name, keyword_name=keyword_name) - def _add_event(self, duration, evt_type, is_internal, is_success, message, name, op, version, event_id): + def _add_event(self, duration, evt_type, is_internal, is_success, message, name, op, version, event_id, + event_time_opcode_name=None, event_pid=0, event_tid=0, task_name=None, keyword_name=None): event = TelemetryEvent(event_id, TELEMETRY_EVENT_PROVIDER_ID) event.parameters.append(TelemetryEventParam('Name', name)) event.parameters.append(TelemetryEventParam('Version', str(version))) event.parameters.append(TelemetryEventParam('IsInternal', is_internal)) event.parameters.append(TelemetryEventParam('Operation', op)) - event.parameters.append(TelemetryEventParam('OperationSuccess', - is_success)) + event.parameters.append(TelemetryEventParam('OperationSuccess', is_success)) event.parameters.append(TelemetryEventParam('Message', message)) event.parameters.append(TelemetryEventParam('Duration', duration)) event.parameters.append(TelemetryEventParam('ExtensionType', evt_type)) - event.parameters.append(TelemetryEventParam('ContainerId', - os.environ.get(CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"))) + self._add_default_parameters_to_event(event, container_id=os.environ.get( + CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, + event_pid=event_pid, event_tid=event_tid, task_name=task_name, + keyword_name=keyword_name) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError as e: logger.periodic_error(logger.EVERY_FIFTEEN_MINUTES, "[PERIODIC] {0}".format(ustr(e))) - def add_log_event(self, level, message): + def add_log_event(self, level, message, event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", + keyword_name=""): # By the time the message has gotten to this point it is formatted as # # YYYY/MM/DD HH:mm:ss.fffffff LEVEL . @@ -312,13 +310,18 @@ def add_log_event(self, level, message): event.parameters.append(TelemetryEventParam('Context2', '')) event.parameters.append(TelemetryEventParam('Context3', '')) + self._add_default_parameters_to_event(event, container_id=os.environ.get( + CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, + event_pid=event_pid, event_tid=event_tid, task_name=task_name, + keyword_name=keyword_name) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError: pass - def add_metric(self, category, counter, instance, value, log_event=False): + def add_metric(self, category, counter, instance, value, log_event=False, event_time_opcode_name=None, event_pid=0, + event_tid=0, task_name="", keyword_name=""): """ Create and save an event which contains a telemetry event. @@ -339,12 +342,27 @@ def add_metric(self, category, counter, instance, value, log_event=False): event.parameters.append(TelemetryEventParam('Instance', instance)) event.parameters.append(TelemetryEventParam('Value', value)) + self._add_default_parameters_to_event(event, container_id=os.environ.get( + CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, + event_pid=event_pid, event_tid=event_tid, task_name=task_name, + keyword_name=keyword_name) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError as e: logger.error("{0}", e) + @staticmethod + def _add_default_parameters_to_event(event, container_id="UNINITIALIZED", event_time_opcode_name=None, event_pid=0, + event_tid=0, task_name='', keyword_name=''): + event.parameters.append(TelemetryEventParam('ContainerId', container_id)) + event.parameters.append(TelemetryEventParam('OpcodeName', event_time_opcode_name if event_time_opcode_name + else datetime.utcnow().__str__())) + event.parameters.append(TelemetryEventParam('EventTid', event_tid)) + event.parameters.append(TelemetryEventParam('EventPid', event_pid)) + event.parameters.append(TelemetryEventParam("TaskName", task_name)) + event.parameters.append(TelemetryEventParam("KeywordName", keyword_name)) + __event_logger__ = EventLogger() @@ -362,23 +380,27 @@ def elapsed_milliseconds(utc_start): def report_event(op, is_success=True, message='', log_event=True): from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION add_event(AGENT_NAME, - version=CURRENT_VERSION, + version=str(CURRENT_VERSION), is_success=is_success, message=message, op=op, log_event=log_event) -def report_periodic(delta, op, is_success=True, message=''): +def report_periodic(delta, op, is_success=True, message='', event_time_opcode_name=datetime.utcnow().__str__(), + event_pid=0, event_tid=0, task_name="", keyword_name=""): from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION add_periodic(delta, AGENT_NAME, - version=CURRENT_VERSION, - is_success=is_success, - message=message, - op=op) + version=str(CURRENT_VERSION), + is_success=is_success, + message=message, + op=op, + task_name=task_name, event_pid=event_pid, + event_time_opcode_name=event_time_opcode_name, event_tid=event_tid, keyword_name=keyword_name) -def report_metric(category, counter, instance, value, log_event=False, reporter=__event_logger__): +def report_metric(category, counter, instance, value, log_event=False, reporter=__event_logger__, + event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", keyword_name=""): """ Send a telemetry event reporting a single instance of a performance counter. :param str category: The category of the metric (cpu, memory, etc) @@ -394,13 +416,13 @@ def report_metric(category, counter, instance, value, log_event=False, reporter= message = "Metric {0}/{1} [{2}] = {3}".format(category, counter, instance, value) _log_event(AGENT_NAME, "METRIC", message, 0) return - reporter.add_metric(category, counter, instance, value, log_event) + reporter.add_metric(category, counter, instance, value, log_event, task_name=task_name, event_pid=event_pid, + event_time_opcode_name=event_time_opcode_name, event_tid=event_tid, keyword_name=keyword_name) -def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0, - version=CURRENT_VERSION, - message="", evt_type="", is_internal=False, log_event=True, - reporter=__event_logger__): +def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="", + evt_type="", is_internal=False, log_event=True, reporter=__event_logger__, event_time_opcode_name=None, + event_pid=0, event_tid=0, task_name="", keyword_name=""): if reporter.event_dir is None: logger.warn("Cannot add event -- Event reporter is not initialized.") _log_event(name, op, message, duration, is_success=is_success) @@ -408,33 +430,34 @@ def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0, if should_emit_event(name, version, op, is_success): mark_event_status(name, version, op, is_success) - reporter.add_event( - name, op=op, is_success=is_success, duration=duration, - version=str(version), message=message, evt_type=evt_type, - is_internal=is_internal, log_event=log_event) + reporter.add_event(name, op=op, is_success=is_success, duration=duration, version=str(version), message=message, + evt_type=evt_type, is_internal=is_internal, log_event=log_event, task_name=task_name, + event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, + keyword_name=keyword_name) -def add_log_event(level, message, reporter=__event_logger__): +def add_log_event(level, message, reporter=__event_logger__, event_time_opcode_name=None, + event_pid=0, event_tid=0, task_name="", keyword_name=""): if reporter.event_dir is None: return - reporter.add_log_event(level, message) + reporter.add_log_event(level, message, event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, + event_tid=event_tid, task_name=task_name, keyword_name=keyword_name) -def add_periodic( - delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, - version=CURRENT_VERSION, - message="", evt_type="", is_internal=False, log_event=True, force=False, - reporter=__event_logger__): +def add_periodic(delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="", evt_type="", is_internal=False, log_event=True, force=False, + reporter=__event_logger__, event_time_opcode_name=None, event_pid=0, + event_tid=0, task_name="", keyword_name=""): if reporter.event_dir is None: logger.warn("Cannot add periodic event -- Event reporter is not initialized.") _log_event(name, op, message, duration, is_success=is_success) return - reporter.add_periodic( - delta, name, op=op, is_success=is_success, duration=duration, - version=str(version), message=message, evt_type=evt_type, - is_internal=is_internal, log_event=log_event, force=force) + reporter.add_periodic(delta, name, op=op, is_success=is_success, duration=duration, version=str(version), + message=message, evt_type=evt_type, is_internal=is_internal, log_event=log_event, force=force, + event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, + task_name=task_name, keyword_name=keyword_name) def mark_event_status(name, version, op, status): diff --git a/tests/common/test_event.py b/tests/common/test_event.py index 9244e87512..7c6749b9b3 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -20,19 +20,18 @@ import json from datetime import datetime, timedelta +import mock + from azurelinuxagent.common.event import add_event, \ WALAEventOperation, elapsed_milliseconds from azurelinuxagent.common.exception import EventError from azurelinuxagent.common.future import ustr -from azurelinuxagent.common.utils.extensionprocessutil import read_output from azurelinuxagent.common.protocol.wire import GoalState +from azurelinuxagent.common.utils.extensionprocessutil import read_output from azurelinuxagent.common.version import CURRENT_VERSION from azurelinuxagent.ga.monitor import MonitorHandler - from tests.tools import * -import azurelinuxagent.common.event as event - class TestEvent(AgentTestCase): def test_add_event_should_read_container_id_from_process_environment(self): @@ -269,13 +268,42 @@ def test_periodic_emits_after_elapsed_delta(self, mock_event): @patch('azurelinuxagent.common.event.EventLogger.add_event') def test_periodic_forwards_args(self, mock_event): event.__event_logger__.reset_periodic() - - event.add_periodic(logger.EVERY_DAY, "FauxEvent") - mock_event.assert_called_once_with( - "FauxEvent", - duration=0, evt_type='', is_internal=False, is_success=True, - log_event=True, message='', op=WALAEventOperation.Unknown, - version=str(CURRENT_VERSION)) + event_time = datetime.utcnow().__str__() + event.add_periodic(logger.EVERY_DAY, "FauxEvent", op=WALAEventOperation.Log, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", is_internal=False, + log_event=True, force=False, event_time_opcode_name=event_time, event_pid=10, event_tid= + 11001001011, task_name="ExtHandler", keyword_name="Yo") + mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Log, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", + is_internal=False, log_event=True, event_time_opcode_name=event_time, + event_pid=10, event_tid=11001001011, task_name="ExtHandler", keyword_name= + "Yo") + + @patch("azurelinuxagent.common.event.datetime") + @patch('azurelinuxagent.common.event.EventLogger.add_event') + def test_periodic_forwards_args_default_values(self, mock_event, mock_datetime): + event.__event_logger__.reset_periodic() + event_time = datetime.strptime("2019-01-01 01:30:00", '%Y-%m-%d %H:%M:%S').__str__() + mock_datetime.utcnow = mock.Mock(return_value=event_time) + + # Doing the partial to mock the passing of default values of the + from functools import partial + patch_add_periodic = partial(event.add_periodic, event_time_opcode_name=event_time) + + with patch("azurelinuxagent.common.event.add_periodic", patch_add_periodic): + event.add_periodic(logger.EVERY_DAY, "FauxEvent", message="FauxEventMessage") + mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Unknown, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", + is_internal=False, log_event=True, event_time_opcode_name=event_time, + event_pid=0, event_tid=0, task_name="", keyword_name="") + + @patch("azurelinuxagent.common.event.EventLogger.add_event") + def test_add_event_default_variables(self, mock_add_event): + add_event('test', message='test event') + mock_add_event.assert_called_once_with('test', duration=0, event_pid=0, event_tid=0, + event_time_opcode_name=None, evt_type='', is_internal=False, + is_success=True, keyword_name='', log_event=True, message='test event', + op='Unknown', task_name='', version=str(CURRENT_VERSION)) def test_save_event(self): add_event('test', message='test event') @@ -296,19 +324,48 @@ def test_save_event_message_with_non_ascii_characters(self): duration = elapsed_milliseconds(datetime.utcnow()) log_msg = "{0}\n{1}".format("DummyCmd", "\n".join([line for line in msg.split('\n') if line != ""])) - add_event('test_extension', message=log_msg, duration=duration) + with patch("azurelinuxagent.common.event.datetime") as patch_datetime: + patch_datetime.utcnow = Mock(return_value=datetime.strptime("2019-01-01 01:30:00", '%Y-%m-%d %H:%M:%S')) + add_event('test_extension', message=log_msg, duration=duration) for tld_file in os.listdir(self.tmp_dir): event_str = MonitorHandler.collect_event(os.path.join(self.tmp_dir, tld_file)) event_json = json.loads(event_str) - self.assertEqual(len(event_json["parameters"]), 9) + self.assertEqual(len(event_json["parameters"]), 14) + # Checking the contents passed above, and also validating the default values that were passed in. for i in event_json["parameters"]: if i["name"] == "Name": self.assertEqual(i["value"], "test_extension") - if i["name"] == "Message": + elif i["name"] == "Message": self.assertEqual(i["value"], log_msg) + elif i["name"] == "Version": + self.assertEqual(i["value"], str(CURRENT_VERSION)) + elif i['name'] == 'IsInternal': + self.assertEqual(i['value'], False) + elif i['name'] == 'Operation': + self.assertEqual(i['value'], 'Unknown') + elif i['name'] == 'OperationSuccess': + self.assertEqual(i['value'], True) + elif i['name'] == 'Duration': + self.assertEqual(i['value'], 0) + elif i['name'] == 'ExtensionType': + self.assertEqual(i['value'], '') + elif i['name'] == 'ContainerId': + self.assertEqual(i['value'], 'UNINITIALIZED') + elif i['name'] == 'OpcodeName': + self.assertEqual(i['value'], '2019-01-01 01:30:00') + elif i['name'] == 'EventTid': + self.assertEqual(i['value'], 0) + elif i['name'] == 'EventPid': + self.assertEqual(i['value'], 0) + elif i['name'] == 'TaskName': + self.assertEqual(i['value'], '') + elif i['name'] == 'KeywordName': + self.assertEqual(i['value'], '') + else: + self.assertFalse(True, "Contains a field outside the defaults expected.") def test_save_event_message_with_decode_errors(self): tmp_file = os.path.join(self.tmp_dir, "tmp_file") diff --git a/tests/common/test_logger.py b/tests/common/test_logger.py index 6350525950..16eff3e80e 100644 --- a/tests/common/test_logger.py +++ b/tests/common/test_logger.py @@ -164,7 +164,7 @@ def test_telemetry_logger1(self, mock_save): self.assertEqual('FFF0196F-EE4C-4EAF-9AA5-776F622DEB4F', telemetry_json['providerId']) self.assertEqual(7, telemetry_json['eventId']) - self.assertEqual(5, len(telemetry_json['parameters'])) + self.assertEqual(11, len(telemetry_json['parameters'])) for x in telemetry_json['parameters']: if x['name'] == 'EventName': self.assertEqual(x['value'], 'Log') From 96af88d862fc6f9ee5131f28203b0a0175c15fa2 Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Thu, 10 Oct 2019 18:59:13 -0700 Subject: [PATCH 02/11] Updated the test to remove the default value passed. We pass None now. --- tests/common/test_event.py | 18 +++++------------- 1 file changed, 5 insertions(+), 13 deletions(-) diff --git a/tests/common/test_event.py b/tests/common/test_event.py index 7c6749b9b3..166a429c4f 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -283,19 +283,11 @@ def test_periodic_forwards_args(self, mock_event): @patch('azurelinuxagent.common.event.EventLogger.add_event') def test_periodic_forwards_args_default_values(self, mock_event, mock_datetime): event.__event_logger__.reset_periodic() - event_time = datetime.strptime("2019-01-01 01:30:00", '%Y-%m-%d %H:%M:%S').__str__() - mock_datetime.utcnow = mock.Mock(return_value=event_time) - - # Doing the partial to mock the passing of default values of the - from functools import partial - patch_add_periodic = partial(event.add_periodic, event_time_opcode_name=event_time) - - with patch("azurelinuxagent.common.event.add_periodic", patch_add_periodic): - event.add_periodic(logger.EVERY_DAY, "FauxEvent", message="FauxEventMessage") - mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Unknown, is_success=True, duration=0, - version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", - is_internal=False, log_event=True, event_time_opcode_name=event_time, - event_pid=0, event_tid=0, task_name="", keyword_name="") + event.add_periodic(logger.EVERY_DAY, "FauxEvent", message="FauxEventMessage") + mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Unknown, is_success=True, duration=0, + version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", + is_internal=False, log_event=True, event_time_opcode_name=None, + event_pid=0, event_tid=0, task_name="", keyword_name="") @patch("azurelinuxagent.common.event.EventLogger.add_event") def test_add_event_default_variables(self, mock_add_event): From 21d984f5980fd286f7a70c3f3cfe31b143b1a22f Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 16 Oct 2019 00:39:06 -0700 Subject: [PATCH 03/11] Simplifying add_event to revert the changes in spec. --- azurelinuxagent/common/event.py | 98 +++++++++++++-------------------- azurelinuxagent/ga/env.py | 1 + azurelinuxagent/ga/monitor.py | 1 + tests/common/test_event.py | 34 ++++++------ 4 files changed, 58 insertions(+), 76 deletions(-) diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index 46e7383d17..c32af40b4c 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -20,6 +20,7 @@ import json import os import sys +import threading import time import traceback from datetime import datetime @@ -39,6 +40,11 @@ # Store the last retrieved container id as an environment variable to be shared between threads for telemetry purposes CONTAINER_ID_ENV_VARIABLE = "AZURE_GUEST_AGENT_CONTAINER_ID" + +def get_container_id_from_env(): + return os.environ.get(CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED") + + class WALAEventOperation: ActivateResourceDisk = "ActivateResourceDisk" AgentBlacklisted = "AgentBlacklisted" @@ -246,31 +252,24 @@ def is_period_elapsed(self, delta, h): def add_periodic(self, delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="", evt_type="", is_internal=False, log_event=True, - force=False, event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", keyword_name=""): + force=False): h = hash(name + op + ustr(is_success) + message) if force or self.is_period_elapsed(delta, h): self.add_event(name, op=op, is_success=is_success, duration=duration, version=version, message=message, evt_type=evt_type, - is_internal=is_internal, log_event=log_event, - event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, - task_name=task_name, keyword_name=keyword_name) + is_internal=is_internal, log_event=log_event) self.periodic_events[h] = datetime.now() def add_event(self, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), - message="", evt_type="", is_internal=False, log_event=True, - event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", - keyword_name=""): + message="", evt_type="", is_internal=False, log_event=True): if (not is_success) and log_event: _log_event(name, op, message, duration, is_success=is_success) - self._add_event(duration, evt_type, is_internal, is_success, message, name, op, version, event_id=1, - event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, - task_name=task_name, keyword_name=keyword_name) + self._add_event(duration, evt_type, is_internal, is_success, message, name, op, version, event_id=1) - def _add_event(self, duration, evt_type, is_internal, is_success, message, name, op, version, event_id, - event_time_opcode_name=None, event_pid=0, event_tid=0, task_name=None, keyword_name=None): + def _add_event(self, duration, evt_type, is_internal, is_success, message, name, op, version, event_id): event = TelemetryEvent(event_id, TELEMETRY_EVENT_PROVIDER_ID) event.parameters.append(TelemetryEventParam('Name', name)) event.parameters.append(TelemetryEventParam('Version', str(version))) @@ -281,18 +280,14 @@ def _add_event(self, duration, evt_type, is_internal, is_success, message, name, event.parameters.append(TelemetryEventParam('Duration', duration)) event.parameters.append(TelemetryEventParam('ExtensionType', evt_type)) - self._add_default_parameters_to_event(event, container_id=os.environ.get( - CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, - event_pid=event_pid, event_tid=event_tid, task_name=task_name, - keyword_name=keyword_name) + self._add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError as e: logger.periodic_error(logger.EVERY_FIFTEEN_MINUTES, "[PERIODIC] {0}".format(ustr(e))) - def add_log_event(self, level, message, event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", - keyword_name=""): + def add_log_event(self, level, message): # By the time the message has gotten to this point it is formatted as # # YYYY/MM/DD HH:mm:ss.fffffff LEVEL . @@ -312,18 +307,14 @@ def add_log_event(self, level, message, event_time_opcode_name=None, event_pid=0 event.parameters.append(TelemetryEventParam('Context2', '')) event.parameters.append(TelemetryEventParam('Context3', '')) - self._add_default_parameters_to_event(event, container_id=os.environ.get( - CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, - event_pid=event_pid, event_tid=event_tid, task_name=task_name, - keyword_name=keyword_name) + self._add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError: pass - def add_metric(self, category, counter, instance, value, log_event=False, event_time_opcode_name=None, event_pid=0, - event_tid=0, task_name="", keyword_name=""): + def add_metric(self, category, counter, instance, value, log_event=False): """ Create and save an event which contains a telemetry event. @@ -344,10 +335,7 @@ def add_metric(self, category, counter, instance, value, log_event=False, event_ event.parameters.append(TelemetryEventParam('Instance', instance)) event.parameters.append(TelemetryEventParam('Value', value)) - self._add_default_parameters_to_event(event, container_id=os.environ.get( - CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"), event_time_opcode_name=event_time_opcode_name, - event_pid=event_pid, event_tid=event_tid, task_name=task_name, - keyword_name=keyword_name) + self._add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -355,15 +343,20 @@ def add_metric(self, category, counter, instance, value, log_event=False, event_ logger.error("{0}", e) @staticmethod - def _add_default_parameters_to_event(event, container_id="UNINITIALIZED", event_time_opcode_name=None, event_pid=0, - event_tid=0, task_name='', keyword_name=''): - event.parameters.append(TelemetryEventParam('ContainerId', container_id)) - event.parameters.append(TelemetryEventParam('OpcodeName', event_time_opcode_name if event_time_opcode_name - else datetime.utcnow().__str__())) - event.parameters.append(TelemetryEventParam('EventTid', event_tid)) - event.parameters.append(TelemetryEventParam('EventPid', event_pid)) + def _add_default_parameters_to_event(event): + task_name = threading.current_thread().getName() + + # We set thread names for the threads spawned by ExtHandler. We get the name of the thread, + # and if it is "MainThread" (the default name from Python. ref threading._MainThread), + # then we default to "ExtHandler". + task_name = task_name if task_name != "MainThread" else "ExtHandler" + + event.parameters.append(TelemetryEventParam('ContainerId', get_container_id_from_env())) + event.parameters.append(TelemetryEventParam('OpcodeName', datetime.utcnow().__str__())) + event.parameters.append(TelemetryEventParam('EventTid', threading.current_thread().ident)) + event.parameters.append(TelemetryEventParam('EventPid', os.getpid())) event.parameters.append(TelemetryEventParam("TaskName", task_name)) - event.parameters.append(TelemetryEventParam("KeywordName", keyword_name)) + event.parameters.append(TelemetryEventParam("KeywordName", '')) # Unused field for now. __event_logger__ = EventLogger() @@ -389,20 +382,16 @@ def report_event(op, is_success=True, message='', log_event=True): log_event=log_event) -def report_periodic(delta, op, is_success=True, message='', event_time_opcode_name=datetime.utcnow().__str__(), - event_pid=0, event_tid=0, task_name="", keyword_name=""): +def report_periodic(delta, op, is_success=True, message=''): from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION add_periodic(delta, AGENT_NAME, version=str(CURRENT_VERSION), is_success=is_success, message=message, - op=op, - task_name=task_name, event_pid=event_pid, - event_time_opcode_name=event_time_opcode_name, event_tid=event_tid, keyword_name=keyword_name) + op=op) -def report_metric(category, counter, instance, value, log_event=False, reporter=__event_logger__, - event_time_opcode_name=None, event_pid=0, event_tid=0, task_name="", keyword_name=""): +def report_metric(category, counter, instance, value, log_event=False, reporter=__event_logger__): """ Send a telemetry event reporting a single instance of a performance counter. :param str category: The category of the metric (cpu, memory, etc) @@ -418,13 +407,11 @@ def report_metric(category, counter, instance, value, log_event=False, reporter= message = "Metric {0}/{1} [{2}] = {3}".format(category, counter, instance, value) _log_event(AGENT_NAME, "METRIC", message, 0) return - reporter.add_metric(category, counter, instance, value, log_event, task_name=task_name, event_pid=event_pid, - event_time_opcode_name=event_time_opcode_name, event_tid=event_tid, keyword_name=keyword_name) + reporter.add_metric(category, counter, instance, value, log_event) def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="", - evt_type="", is_internal=False, log_event=True, reporter=__event_logger__, event_time_opcode_name=None, - event_pid=0, event_tid=0, task_name="", keyword_name=""): + evt_type="", is_internal=False, log_event=True, reporter=__event_logger__): if reporter.event_dir is None: logger.warn("Cannot add event -- Event reporter is not initialized.") _log_event(name, op, message, duration, is_success=is_success) @@ -433,33 +420,26 @@ def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0, if should_emit_event(name, version, op, is_success): mark_event_status(name, version, op, is_success) reporter.add_event(name, op=op, is_success=is_success, duration=duration, version=str(version), message=message, - evt_type=evt_type, is_internal=is_internal, log_event=log_event, task_name=task_name, - event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, - keyword_name=keyword_name) + evt_type=evt_type, is_internal=is_internal, log_event=log_event) -def add_log_event(level, message, reporter=__event_logger__, event_time_opcode_name=None, - event_pid=0, event_tid=0, task_name="", keyword_name=""): +def add_log_event(level, message, reporter=__event_logger__): if reporter.event_dir is None: return - reporter.add_log_event(level, message, event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, - event_tid=event_tid, task_name=task_name, keyword_name=keyword_name) + reporter.add_log_event(level, message) def add_periodic(delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="", evt_type="", is_internal=False, log_event=True, force=False, - reporter=__event_logger__, event_time_opcode_name=None, event_pid=0, - event_tid=0, task_name="", keyword_name=""): + reporter=__event_logger__): if reporter.event_dir is None: logger.warn("Cannot add periodic event -- Event reporter is not initialized.") _log_event(name, op, message, duration, is_success=is_success) return reporter.add_periodic(delta, name, op=op, is_success=is_success, duration=duration, version=str(version), - message=message, evt_type=evt_type, is_internal=is_internal, log_event=log_event, force=force, - event_time_opcode_name=event_time_opcode_name, event_pid=event_pid, event_tid=event_tid, - task_name=task_name, keyword_name=keyword_name) + message=message, evt_type=evt_type, is_internal=is_internal, log_event=log_event, force=force) def mark_event_status(name, version, op, status): diff --git a/azurelinuxagent/ga/env.py b/azurelinuxagent/ga/env.py index 42c329edb2..f2a17b505d 100644 --- a/azurelinuxagent/ga/env.py +++ b/azurelinuxagent/ga/env.py @@ -88,6 +88,7 @@ def is_alive(self): def start(self): self.server_thread = threading.Thread(target=self.monitor) self.server_thread.setDaemon(True) + self.server_thread.setName("EnvHandler") self.server_thread.start() def monitor(self): diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py index ff3bfa3555..98983eb291 100644 --- a/azurelinuxagent/ga/monitor.py +++ b/azurelinuxagent/ga/monitor.py @@ -162,6 +162,7 @@ def is_alive(self): def start(self): self.event_thread = threading.Thread(target=self.daemon) self.event_thread.setDaemon(True) + self.event_thread.setName("MonitorHandler") self.event_thread.start() def init_sysinfo(self): diff --git a/tests/common/test_event.py b/tests/common/test_event.py index 166a429c4f..d9184f3f04 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -18,6 +18,7 @@ from __future__ import print_function import json +import threading from datetime import datetime, timedelta import mock @@ -271,13 +272,10 @@ def test_periodic_forwards_args(self, mock_event): event_time = datetime.utcnow().__str__() event.add_periodic(logger.EVERY_DAY, "FauxEvent", op=WALAEventOperation.Log, is_success=True, duration=0, version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", is_internal=False, - log_event=True, force=False, event_time_opcode_name=event_time, event_pid=10, event_tid= - 11001001011, task_name="ExtHandler", keyword_name="Yo") + log_event=True, force=False) mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Log, is_success=True, duration=0, version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", - is_internal=False, log_event=True, event_time_opcode_name=event_time, - event_pid=10, event_tid=11001001011, task_name="ExtHandler", keyword_name= - "Yo") + is_internal=False, log_event=True) @patch("azurelinuxagent.common.event.datetime") @patch('azurelinuxagent.common.event.EventLogger.add_event') @@ -286,16 +284,14 @@ def test_periodic_forwards_args_default_values(self, mock_event, mock_datetime): event.add_periodic(logger.EVERY_DAY, "FauxEvent", message="FauxEventMessage") mock_event.assert_called_once_with("FauxEvent", op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="FauxEventMessage", evt_type="", - is_internal=False, log_event=True, event_time_opcode_name=None, - event_pid=0, event_tid=0, task_name="", keyword_name="") + is_internal=False, log_event=True) @patch("azurelinuxagent.common.event.EventLogger.add_event") def test_add_event_default_variables(self, mock_add_event): add_event('test', message='test event') - mock_add_event.assert_called_once_with('test', duration=0, event_pid=0, event_tid=0, - event_time_opcode_name=None, evt_type='', is_internal=False, - is_success=True, keyword_name='', log_event=True, message='test event', - op='Unknown', task_name='', version=str(CURRENT_VERSION)) + mock_add_event.assert_called_once_with('test', duration=0, evt_type='', is_internal=False, is_success=True, + log_event=True, message='test event', op='Unknown', + version=str(CURRENT_VERSION)) def test_save_event(self): add_event('test', message='test event') @@ -317,8 +313,11 @@ def test_save_event_message_with_non_ascii_characters(self): log_msg = "{0}\n{1}".format("DummyCmd", "\n".join([line for line in msg.split('\n') if line != ""])) with patch("azurelinuxagent.common.event.datetime") as patch_datetime: - patch_datetime.utcnow = Mock(return_value=datetime.strptime("2019-01-01 01:30:00", '%Y-%m-%d %H:%M:%S')) - add_event('test_extension', message=log_msg, duration=duration) + patch_datetime.utcnow = Mock(return_value=datetime.strptime("2019-01-01 01:30:00", + '%Y-%m-%d %H:%M:%S')) + with patch('os.getpid', return_value=42): + with patch("threading.Thread.getName", return_value="HelloWorldTask"): + add_event('test_extension', message=log_msg, duration=duration) for tld_file in os.listdir(self.tmp_dir): event_str = MonitorHandler.collect_event(os.path.join(self.tmp_dir, tld_file)) @@ -349,15 +348,16 @@ def test_save_event_message_with_non_ascii_characters(self): elif i['name'] == 'OpcodeName': self.assertEqual(i['value'], '2019-01-01 01:30:00') elif i['name'] == 'EventTid': - self.assertEqual(i['value'], 0) + self.assertEqual(i['value'], threading.current_thread().ident) elif i['name'] == 'EventPid': - self.assertEqual(i['value'], 0) + self.assertEqual(i['value'], 42) elif i['name'] == 'TaskName': - self.assertEqual(i['value'], '') + self.assertEqual(i['value'], 'HelloWorldTask') elif i['name'] == 'KeywordName': self.assertEqual(i['value'], '') else: - self.assertFalse(True, "Contains a field outside the defaults expected.") + self.assertFalse(True, "Contains a field outside the defaults expected. Field Name: {0}". + format(i['name'])) def test_save_event_message_with_decode_errors(self): tmp_file = os.path.join(self.tmp_dir, "tmp_file") From a81d294e5ff92357c6631c650ec007712babfb45 Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 16 Oct 2019 00:59:45 -0700 Subject: [PATCH 04/11] Moving GAVersion value set from sysinfo to default values Also, removing the import test.tools.* and breaking it apart. --- azurelinuxagent/common/event.py | 3 ++- azurelinuxagent/ga/monitor.py | 1 - tests/common/test_event.py | 13 +++++++++---- tests/common/test_logger.py | 10 +++++----- tests/ga/test_monitor.py | 1 - 5 files changed, 16 insertions(+), 12 deletions(-) diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index c32af40b4c..f0745805fa 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -32,7 +32,7 @@ from azurelinuxagent.common.datacontract import get_properties from azurelinuxagent.common.telemetryevent import TelemetryEventParam, TelemetryEvent from azurelinuxagent.common.utils import fileutil, textutil -from azurelinuxagent.common.version import CURRENT_VERSION +from azurelinuxagent.common.version import CURRENT_VERSION, CURRENT_AGENT _EVENT_MSG = "Event: name={0}, op={1}, message={2}, duration={3}" TELEMETRY_EVENT_PROVIDER_ID = "69B669B9-4AF8-4C50-BDC4-6006FA76E975" @@ -351,6 +351,7 @@ def _add_default_parameters_to_event(event): # then we default to "ExtHandler". task_name = task_name if task_name != "MainThread" else "ExtHandler" + event.parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) event.parameters.append(TelemetryEventParam('ContainerId', get_container_id_from_env())) event.parameters.append(TelemetryEventParam('OpcodeName', datetime.utcnow().__str__())) event.parameters.append(TelemetryEventParam('EventTid', threading.current_thread().ident)) diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py index 98983eb291..3d23ebe1ed 100644 --- a/azurelinuxagent/ga/monitor.py +++ b/azurelinuxagent/ga/monitor.py @@ -172,7 +172,6 @@ def init_sysinfo(self): DISTRO_CODE_NAME, platform.release()) self.sysinfo.append(TelemetryEventParam("OSVersion", osversion)) - self.sysinfo.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) self.sysinfo.append(TelemetryEventParam("ExecutionMode", AGENT_EXECUTION_MODE)) try: diff --git a/tests/common/test_event.py b/tests/common/test_event.py index d9184f3f04..a447253639 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -18,20 +18,23 @@ from __future__ import print_function import json +import os import threading from datetime import datetime, timedelta -import mock +from mock import patch, Mock +from azurelinuxagent.common import event, logger from azurelinuxagent.common.event import add_event, \ WALAEventOperation, elapsed_milliseconds from azurelinuxagent.common.exception import EventError from azurelinuxagent.common.future import ustr from azurelinuxagent.common.protocol.wire import GoalState +from azurelinuxagent.common.utils import fileutil from azurelinuxagent.common.utils.extensionprocessutil import read_output -from azurelinuxagent.common.version import CURRENT_VERSION +from azurelinuxagent.common.version import CURRENT_VERSION, CURRENT_AGENT from azurelinuxagent.ga.monitor import MonitorHandler -from tests.tools import * +from tests.tools import AgentTestCase, load_data, data_dir class TestEvent(AgentTestCase): @@ -323,7 +326,7 @@ def test_save_event_message_with_non_ascii_characters(self): event_str = MonitorHandler.collect_event(os.path.join(self.tmp_dir, tld_file)) event_json = json.loads(event_str) - self.assertEqual(len(event_json["parameters"]), 14) + self.assertEqual(len(event_json["parameters"]), 15) # Checking the contents passed above, and also validating the default values that were passed in. for i in event_json["parameters"]: @@ -355,6 +358,8 @@ def test_save_event_message_with_non_ascii_characters(self): self.assertEqual(i['value'], 'HelloWorldTask') elif i['name'] == 'KeywordName': self.assertEqual(i['value'], '') + elif i['name'] == 'GAVersion': + self.assertEqual(i['value'], str(CURRENT_AGENT)) else: self.assertFalse(True, "Contains a field outside the defaults expected. Field Name: {0}". format(i['name'])) diff --git a/tests/common/test_logger.py b/tests/common/test_logger.py index 3f97ed46b4..2f745f990b 100644 --- a/tests/common/test_logger.py +++ b/tests/common/test_logger.py @@ -18,11 +18,11 @@ import json from datetime import datetime -import azurelinuxagent.common.logger as logger -from azurelinuxagent.common.event import add_log_event -from azurelinuxagent.common.version import CURRENT_AGENT, CURRENT_VERSION +from mock import patch, MagicMock -from tests.tools import * +from azurelinuxagent.common import logger +from azurelinuxagent.common.event import add_log_event +from tests.tools import AgentTestCase _MSG_INFO = "This is our test info logging message {0} {1}" _MSG_WARN = "This is our test warn logging message {0} {1}" @@ -178,7 +178,7 @@ def test_telemetry_logger1(self, mock_save): self.assertEqual('FFF0196F-EE4C-4EAF-9AA5-776F622DEB4F', telemetry_json['providerId']) self.assertEqual(7, telemetry_json['eventId']) - self.assertEqual(11, len(telemetry_json['parameters'])) + self.assertEqual(12, len(telemetry_json['parameters'])) for x in telemetry_json['parameters']: if x['name'] == 'EventName': self.assertEqual(x['value'], 'Log') diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index d330c98e8e..1522d1ec15 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -428,7 +428,6 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, patch_get '' \ '' \ - '' \ '' \ '' \ '' \ From bb8750e4d49b0c44685efa18f4405931da55173f Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 16 Oct 2019 17:33:04 -0700 Subject: [PATCH 05/11] Refactoring the name of the method to create dummy_event. --- tests/ga/test_monitor.py | 32 ++++++++++++++++---------------- 1 file changed, 16 insertions(+), 16 deletions(-) diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index 1522d1ec15..f922d5ba19 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -49,16 +49,16 @@ def random_generator(size=6, chars=string.ascii_uppercase + string.digits + stri return ''.join(random.choice(chars) for x in range(size)) -def create_event_message(size=0, - name="DummyExtension", - op=WALAEventOperation.Unknown, - is_success=True, - duration=0, - version=CURRENT_VERSION, - is_internal=False, - evt_type="", - message="DummyMessage", - invalid_chars=False): +def create_dummy_event(size=0, + name="DummyExtension", + op=WALAEventOperation.Unknown, + is_success=True, + duration=0, + version=CURRENT_VERSION, + is_internal=False, + evt_type="", + message="DummyMessage", + invalid_chars=False): return get_event_message(name=size if size != 0 else name, op=op, @@ -411,7 +411,7 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, patch_get "DISTRO_CODE_NAME", platform.release()) - self.event_logger.save_event(create_event_message(message="Message-Test")) + self.event_logger.save_event(create_dummy_event(message="Message-Test")) monitor_handler.collect_and_send_events() # Validating the crafted message by the collect_and_sent_event call. @@ -457,7 +457,7 @@ def test_collect_and_send_events_with_small_events(self, mock_lib_dir, patch_sen for power in sizes: size = 2 ** power - self.event_logger.save_event(create_event_message(size)) + self.event_logger.save_event(create_dummy_event(size)) monitor_handler.collect_and_send_events() # The send_event call would be called each time, as we are filling up the buffer up to the brim for each call. @@ -477,7 +477,7 @@ def test_collect_and_send_events_with_large_events(self, mock_lib_dir, patch_sen for power in sizes: size = 2 ** power - self.event_logger.save_event(create_event_message(size)) + self.event_logger.save_event(create_dummy_event(size)) with patch("azurelinuxagent.common.logger.periodic_warn") as patch_periodic_warn: monitor_handler.collect_and_send_events() @@ -545,7 +545,7 @@ def test_collect_and_send_with_http_post_returning_503(self, mock_lib_dir, *args for power in sizes: size = 2 ** power * 1024 - self.event_logger.save_event(create_event_message(size)) + self.event_logger.save_event(create_dummy_event(size)) with patch("azurelinuxagent.common.logger.error") as mock_error: with patch("azurelinuxagent.common.utils.restutil.http_post") as mock_http_post: @@ -572,7 +572,7 @@ def test_collect_and_send_with_send_event_generating_exception(self, mock_lib_di for power in sizes: size = 2 ** power * 1024 - self.event_logger.save_event(create_event_message(size)) + self.event_logger.save_event(create_dummy_event(size)) monitor_handler.last_event_collection = datetime.datetime.utcnow() - timedelta(hours=1) # This test validates that if we hit an issue while sending an event, we never send it again. @@ -597,7 +597,7 @@ def test_collect_and_send_with_call_wireserver_returns_http_error(self, mock_lib for power in sizes: size = 2 ** power * 1024 - self.event_logger.save_event(create_event_message(size)) + self.event_logger.save_event(create_dummy_event(size)) monitor_handler.last_event_collection = datetime.datetime.utcnow() - timedelta(hours=1) with patch("azurelinuxagent.common.logger.error") as mock_error: From a5e1c821488bee7f8f24b9a82323bfa8db761bf9 Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Thu, 17 Oct 2019 10:39:20 -0700 Subject: [PATCH 06/11] Fixed imports for test_monitor and nit; Unknown op fixed. --- tests/common/test_event.py | 2 +- tests/ga/test_monitor.py | 27 +++++++++++++++++++++------ 2 files changed, 22 insertions(+), 7 deletions(-) diff --git a/tests/common/test_event.py b/tests/common/test_event.py index a447253639..4c676eeed8 100644 --- a/tests/common/test_event.py +++ b/tests/common/test_event.py @@ -293,7 +293,7 @@ def test_periodic_forwards_args_default_values(self, mock_event, mock_datetime): def test_add_event_default_variables(self, mock_add_event): add_event('test', message='test event') mock_add_event.assert_called_once_with('test', duration=0, evt_type='', is_internal=False, is_success=True, - log_event=True, message='test event', op='Unknown', + log_event=True, message='test event', op=WALAEventOperation.Unknown, version=str(CURRENT_VERSION)) def test_save_event(self): diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index f922d5ba19..0e7c49f157 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -14,24 +14,39 @@ # # Requires Python 2.6+ and Openssl 1.0+ # +import datetime +import json +import os +import platform import random +import shutil import string +import sys +import tempfile +import time from datetime import timedelta +from mock import Mock, MagicMock, patch from nose.plugins.attrib import attr +from azurelinuxagent.common import logger from azurelinuxagent.common.cgroup import CGroup +from azurelinuxagent.common.cgroupstelemetry import CGroupsTelemetry from azurelinuxagent.common.datacontract import get_properties -from azurelinuxagent.common.event import EventLogger -from azurelinuxagent.common.protocol.imds import ComputeInfo, IMDS_IMAGE_ORIGIN_ENDORSED +from azurelinuxagent.common.event import EventLogger, WALAEventOperation +from azurelinuxagent.common.exception import HttpError +from azurelinuxagent.common.future import ustr +from azurelinuxagent.common.protocol.imds import ComputeInfo from azurelinuxagent.common.protocol.restapi import VMInfo from azurelinuxagent.common.protocol.wire import WireProtocol -from azurelinuxagent.common.utils import restutil -from azurelinuxagent.common.version import AGENT_VERSION -from azurelinuxagent.ga.monitor import * +from azurelinuxagent.common.telemetryevent import TelemetryEventParam, TelemetryEvent +from azurelinuxagent.common.utils import restutil, fileutil +from azurelinuxagent.common.version import AGENT_VERSION, CURRENT_VERSION +from azurelinuxagent.ga.monitor import parse_xml_event, get_monitor_handler, MonitorHandler, \ + generate_extension_metrics_telemetry_dictionary from tests.common.test_cgroupstelemetry import make_new_cgroup, consume_cpu_time, consume_memory from tests.protocol.mockwiredata import WireProtocolData, DATA_FILE -from tests.tools import * +from tests.tools import load_data, AgentTestCase, data_dir, are_cgroups_enabled, i_am_root, skip_if_predicate_false class ResponseMock(Mock): From aa6607feaa1e316f98c41fb849c5917f1a2b790f Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Thu, 17 Oct 2019 15:12:15 -0700 Subject: [PATCH 07/11] Setting the thread name explicitly for Daemon/ExtHandler --- azurelinuxagent/agent.py | 5 +++++ azurelinuxagent/common/event.py | 9 +-------- 2 files changed, 6 insertions(+), 8 deletions(-) diff --git a/azurelinuxagent/agent.py b/azurelinuxagent/agent.py index 6e5c92d154..2e3b26c44b 100644 --- a/azurelinuxagent/agent.py +++ b/azurelinuxagent/agent.py @@ -27,6 +27,7 @@ import sys import re import subprocess +import threading import traceback import azurelinuxagent.common.logger as logger @@ -39,6 +40,7 @@ from azurelinuxagent.common.osutil import get_osutil from azurelinuxagent.common.utils import fileutil + class Agent(object): def __init__(self, verbose, conf_file_path=None): """ @@ -92,6 +94,7 @@ def daemon(self): Run agent daemon """ logger.set_prefix("Daemon") + threading.current_thread().setName("Daemon") child_args = None \ if self.conf_file_path is None \ else "-configuration-path:{0}".format(self.conf_file_path) @@ -132,6 +135,7 @@ def run_exthandlers(self, debug=False): Run the update and extension handler """ logger.set_prefix("ExtHandler") + threading.current_thread().setName("ExtHandler") from azurelinuxagent.ga.update import get_update_handler update_handler = get_update_handler() update_handler.run(debug) @@ -141,6 +145,7 @@ def show_configuration(self): for k in sorted(configuration.keys()): print("{0} = {1}".format(k, configuration[k])) + def main(args=[]): """ Parse command line arguments, exit with usage() on error. diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index f0745805fa..13240de463 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -344,19 +344,12 @@ def add_metric(self, category, counter, instance, value, log_event=False): @staticmethod def _add_default_parameters_to_event(event): - task_name = threading.current_thread().getName() - - # We set thread names for the threads spawned by ExtHandler. We get the name of the thread, - # and if it is "MainThread" (the default name from Python. ref threading._MainThread), - # then we default to "ExtHandler". - task_name = task_name if task_name != "MainThread" else "ExtHandler" - event.parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) event.parameters.append(TelemetryEventParam('ContainerId', get_container_id_from_env())) event.parameters.append(TelemetryEventParam('OpcodeName', datetime.utcnow().__str__())) event.parameters.append(TelemetryEventParam('EventTid', threading.current_thread().ident)) event.parameters.append(TelemetryEventParam('EventPid', os.getpid())) - event.parameters.append(TelemetryEventParam("TaskName", task_name)) + event.parameters.append(TelemetryEventParam("TaskName", threading.current_thread().getName())) event.parameters.append(TelemetryEventParam("KeywordName", '')) # Unused field for now. From bcc5536685f78df73231e647d2d1e33b9c4db7be Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Tue, 5 Nov 2019 17:19:59 -0800 Subject: [PATCH 08/11] Adding common params into all the events if not present & other changes 1. Added "in" support for TelemetryEvent for easier code check. Also added complementary tests for the same. 2. Updated the tests in test_monitor to reflect newer sysinfo fields added. 3. Added comments to describe the decisions behind the field decisions. --- azurelinuxagent/common/event.py | 13 ++++ azurelinuxagent/common/telemetryevent.py | 4 + azurelinuxagent/ga/monitor.py | 25 +++++- tests/common/test_telemetryevent.py | 49 ++++++++++++ tests/data/ext/event_from_agent.xml | 26 +++++++ .../{event.xml => event_from_extension.xml} | 5 +- tests/ga/test_monitor.py | 76 +++++++++++++++++-- 7 files changed, 184 insertions(+), 14 deletions(-) create mode 100644 tests/common/test_telemetryevent.py create mode 100644 tests/data/ext/event_from_agent.xml rename tests/data/ext/{event.xml => event_from_extension.xml} (83%) mode change 100755 => 100644 diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index 13240de463..2a10a20c14 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -344,9 +344,22 @@ def add_metric(self, category, counter, instance, value, log_event=False): @staticmethod def _add_default_parameters_to_event(event): + # We write the GAVersion here rather than add it in azurelinuxagent.ga.monitor.MonitorHandler.add_sysinfo + # as there could be a possibility of events being sent with newer version of the agent, rather than the agent + # version generating the event. + # Old behavior example: V1 writes the event on the disk and finds an update immediately, and updates. Now the + # new monitor thread would pick up the events from the disk and send it with the CURRENT_AGENT, which would have + # newer version of the agent. This causes confusion. event.parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) + + # ContainerId can change due to live migration and we want to preserve the container Id of the container writing + # the event, rather than sending the event. event.parameters.append(TelemetryEventParam('ContainerId', get_container_id_from_env())) + + # This is used as the actual time of event generation. event.parameters.append(TelemetryEventParam('OpcodeName', datetime.utcnow().__str__())) + + # Other commong parameters added to the events event.parameters.append(TelemetryEventParam('EventTid', threading.current_thread().ident)) event.parameters.append(TelemetryEventParam('EventPid', os.getpid())) event.parameters.append(TelemetryEventParam("TaskName", threading.current_thread().getName())) diff --git a/azurelinuxagent/common/telemetryevent.py b/azurelinuxagent/common/telemetryevent.py index 35d51bcbef..8c3eb71bc1 100644 --- a/azurelinuxagent/common/telemetryevent.py +++ b/azurelinuxagent/common/telemetryevent.py @@ -35,6 +35,10 @@ def __init__(self, eventId=None, providerId=None): self.providerId = providerId self.parameters = DataContractList(TelemetryEventParam) + # Checking if the particular param name is in the TelemetryEvent. + def __contains__(self, param_name): + return param_name in [param.name for param in self.parameters] + class TelemetryEventList(DataContract): def __init__(self): diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py index 916b9f760e..0bf16861ed 100644 --- a/azurelinuxagent/ga/monitor.py +++ b/azurelinuxagent/ga/monitor.py @@ -29,7 +29,8 @@ from azurelinuxagent.common.cgroupstelemetry import CGroupsTelemetry from azurelinuxagent.common.errorstate import ErrorState -from azurelinuxagent.common.event import add_event, WALAEventOperation, CONTAINER_ID_ENV_VARIABLE +from azurelinuxagent.common.event import add_event, WALAEventOperation, CONTAINER_ID_ENV_VARIABLE, \ + get_container_id_from_env from azurelinuxagent.common.exception import EventError, ProtocolError, OSUtilError, HttpError from azurelinuxagent.common.future import ustr from azurelinuxagent.common.osutil import get_osutil @@ -329,10 +330,26 @@ def add_sysinfo(self, event): # Add sys_info params populated by the agent final_parameters.extend(self.sysinfo) - # Container id is populated for agent events on the fly, but not for extension events. Add it if it's missing. - if "ContainerId" not in [param.name for param in event.parameters]: + if "ContainerId" not in event: + # ContainerId is populated for agent events on the fly, but not for extension events. Add it if it's missing. final_parameters.append( - TelemetryEventParam("ContainerId", os.environ.get(CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"))) + TelemetryEventParam("ContainerId", get_container_id_from_env())) + if "GAVersion" not in event: + # GAVersion is populated for agent events on the fly, but not for extension events. Add it if it's missing. + final_parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) + + # Default fields are only populated by Agent and not the extension. Agent will fill up any event if they don't + # have the default params. + if "OpcodeName" not in event: + final_parameters.append(TelemetryEventParam("OpcodeName", datetime.utcnow().__str__())) + if "EventTid" not in event: + final_parameters.append(TelemetryEventParam("EventTid", "")) + if "EventPid" not in event: + final_parameters.append(TelemetryEventParam("EventPid", "")) + if "TaskName" not in event: + final_parameters.append(TelemetryEventParam("TaskName", "")) + if "KeywordName" not in event: + final_parameters.append(TelemetryEventParam("KeywordName", "")) event.parameters = final_parameters diff --git a/tests/common/test_telemetryevent.py b/tests/common/test_telemetryevent.py new file mode 100644 index 0000000000..de75f3cb1d --- /dev/null +++ b/tests/common/test_telemetryevent.py @@ -0,0 +1,49 @@ +# Copyright 2019 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+ +# +from azurelinuxagent.common.telemetryevent import TelemetryEvent, TelemetryEventParam +from tests.tools import AgentTestCase + + +def get_test_event(name="DummyExtension", op="Unknown", is_success=True, duration=0, version="foo", evt_type="", is_internal=False, + message="DummyMessage", eventId=1): + event = TelemetryEvent(eventId, "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX") + event.parameters.append(TelemetryEventParam('Name', name)) + event.parameters.append(TelemetryEventParam('Version', str(version))) + event.parameters.append(TelemetryEventParam('IsInternal', is_internal)) + event.parameters.append(TelemetryEventParam('Operation', op)) + event.parameters.append(TelemetryEventParam('OperationSuccess', is_success)) + event.parameters.append(TelemetryEventParam('Message', message)) + event.parameters.append(TelemetryEventParam('Duration', duration)) + event.parameters.append(TelemetryEventParam('ExtensionType', evt_type)) + return event + + +class TestTelemetryEvent(AgentTestCase): + def test_contains_works_for_TelemetryEvent(self): + test_event = get_test_event(message="Dummy Event") + + self.assertTrue('Name' in test_event) + self.assertTrue('Version' in test_event) + self.assertTrue('IsInternal' in test_event) + self.assertTrue('Operation' in test_event) + self.assertTrue('OperationSuccess' in test_event) + self.assertTrue('Message' in test_event) + self.assertTrue('Duration' in test_event) + self.assertTrue('ExtensionType' in test_event) + + self.assertFalse('GAVersion' in test_event) + self.assertFalse('ContainerId' in test_event) \ No newline at end of file diff --git a/tests/data/ext/event_from_agent.xml b/tests/data/ext/event_from_agent.xml new file mode 100644 index 0000000000..d106d87318 --- /dev/null +++ b/tests/data/ext/event_from_agent.xml @@ -0,0 +1,26 @@ + + + + + + + + + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/tests/data/ext/event.xml b/tests/data/ext/event_from_extension.xml old mode 100755 new mode 100644 similarity index 83% rename from tests/data/ext/event.xml rename to tests/data/ext/event_from_extension.xml index dc35d9fe3d..bc1f70d6af --- a/tests/data/ext/event.xml +++ b/tests/data/ext/event_from_extension.xml @@ -3,7 +3,6 @@ - @@ -13,11 +12,9 @@ - - - + diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index a4c4884b9c..cc10b7b9d0 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -109,7 +109,7 @@ def get_event_message(duration, evt_type, is_internal, is_success, message, name class TestMonitor(AgentTestCase): def test_parse_xml_event(self, *args): - data_str = load_data('ext/event.xml') + data_str = load_data('ext/event_from_extension.xml') event = parse_xml_event(data_str) self.assertNotEqual(None, event) self.assertNotEqual(0, event.parameters) @@ -123,7 +123,7 @@ def test_parse_json_event(self, *args): self.assertTrue(all(param is not None for param in event.parameters)) def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(self, *args): - data_str = load_data('ext/event.xml') + data_str = load_data('ext/event_from_agent.xml') event = parse_xml_event(data_str) # Pretend that the test event is coming from the agent by ensuring the event already has a container id @@ -137,6 +137,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel sysinfo_role_name_value = "sysinfo_dummy_role" sysinfo_role_instance_name_value = "sysinfo_dummy_role_instance" sysinfo_execution_mode_value = "sysinfo_IAAS" + GAVersion_value = "WALinuxAgent-2.2.44" + OpcodeName_value = "10101010" + EventTid_value = 140240309798656 + EventPid_value = 108573 + TaskName_value = "MonitorHandler" + KeywordName_value = "" vm_name_param = "VMName" tenant_name_param = "TenantName" @@ -144,6 +150,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel role_instance_name_param = "RoleInstanceName" execution_mode_param = "ExecutionMode" container_id_param = "ContainerId" + GAVersion_param = "GAVersion" + OpcodeName_param = "OpcodeName" + EventTid_param = "EventTid" + EventPid_param = "EventPid" + TaskName_param = "TaskName" + KeywordName_param = "KeywordName" sysinfo = [ TelemetryEventParam(role_instance_name_param, sysinfo_role_instance_name_value), @@ -179,13 +191,31 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel elif p.name == container_id_param: self.assertEqual(container_id_value, p.value) counter += 1 + elif p.name == GAVersion_param: + self.assertEqual(GAVersion_value, p.value) + counter += 1 + elif p.name == OpcodeName_param: + self.assertEqual(OpcodeName_value, p.value) + counter += 1 + elif p.name == EventTid_param: + self.assertEqual(EventTid_value, p.value) + counter += 1 + elif p.name == EventPid_param: + self.assertEqual(EventPid_value, p.value) + counter += 1 + elif p.name == TaskName_param: + self.assertEqual(TaskName_value, p.value) + counter += 1 + elif p.name == KeywordName_param: + self.assertEqual(KeywordName_value, p.value) + counter += 1 - self.assertEqual(6, counter) + self.assertEqual(12, counter) def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events(self, *args): # The difference between agent and extension events is that extension events don't have the container id # populated on the fly like the agent events do. Ensure the container id is populated in add_sysinfo. - data_str = load_data('ext/event.xml') + data_str = load_data('ext/event_from_extension.xml') event = parse_xml_event(data_str) monitor_handler = get_monitor_handler() @@ -198,6 +228,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events sysinfo_role_name_value = "sysinfo_dummy_role" sysinfo_role_instance_name_value = "sysinfo_dummy_role_instance" sysinfo_execution_mode_value = "sysinfo_IAAS" + GAVersion_value = "WALinuxAgent-2.2.44" + OpcodeName_value = "2019-01-01 01:30:00" # Mocking time below. + EventTid_value = "" + EventPid_value = "" + TaskName_value = "" + KeywordName_value = "" vm_name_param = "VMName" tenant_name_param = "TenantName" @@ -205,6 +241,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events role_instance_name_param = "RoleInstanceName" execution_mode_param = "ExecutionMode" container_id_param = "ContainerId" + GAVersion_param = "GAVersion" + OpcodeName_param = "OpcodeName" + EventTid_param = "EventTid" + EventPid_param = "EventPid" + TaskName_param = "TaskName" + KeywordName_param = "KeywordName" sysinfo = [ TelemetryEventParam(role_instance_name_param, sysinfo_role_instance_name_value), @@ -214,12 +256,16 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events TelemetryEventParam(role_name_param, sysinfo_role_name_value) ] monitor_handler.sysinfo = sysinfo - monitor_handler.add_sysinfo(event) + with patch("azurelinuxagent.ga.monitor.datetime") as patch_datetime: + patch_datetime.utcnow = Mock(return_value=datetime.datetime.strptime("2019-01-01 01:30:00", + '%Y-%m-%d %H:%M:%S')) + monitor_handler.add_sysinfo(event) self.assertNotEqual(None, event) self.assertNotEqual(0, event.parameters) self.assertTrue(all(param is not None for param in event.parameters)) + counter = 0 counter = 0 for p in event.parameters: if p.name == vm_name_param: @@ -240,8 +286,26 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events elif p.name == container_id_param: self.assertEqual(container_id_value, p.value) counter += 1 + elif p.name == GAVersion_param: + self.assertEqual(GAVersion_value, p.value) + counter += 1 + elif p.name == OpcodeName_param: + self.assertEqual(OpcodeName_value, p.value) + counter += 1 + elif p.name == EventTid_param: + self.assertEqual(EventTid_value, p.value) + counter += 1 + elif p.name == EventPid_param: + self.assertEqual(EventPid_value, p.value) + counter += 1 + elif p.name == TaskName_param: + self.assertEqual(TaskName_value, p.value) + counter += 1 + elif p.name == KeywordName_param: + self.assertEqual(KeywordName_value, p.value) + counter += 1 - self.assertEqual(6, counter) + self.assertEqual(12, counter) os.environ.pop(CONTAINER_ID_ENV_VARIABLE) @patch("azurelinuxagent.ga.monitor.MonitorHandler.send_telemetry_heartbeat") From 78a7f42bcc8a545cdac2eb99d05551fe850926c7 Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Tue, 5 Nov 2019 18:04:36 -0800 Subject: [PATCH 09/11] Fixed the datetime issues for tests in test_monitor. --- azurelinuxagent/ga/monitor.py | 2 +- tests/ga/test_monitor.py | 16 +++++++++++++--- 2 files changed, 14 insertions(+), 4 deletions(-) diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py index 0bf16861ed..57ef211d15 100644 --- a/azurelinuxagent/ga/monitor.py +++ b/azurelinuxagent/ga/monitor.py @@ -341,7 +341,7 @@ def add_sysinfo(self, event): # Default fields are only populated by Agent and not the extension. Agent will fill up any event if they don't # have the default params. if "OpcodeName" not in event: - final_parameters.append(TelemetryEventParam("OpcodeName", datetime.utcnow().__str__())) + final_parameters.append(TelemetryEventParam("OpcodeName", datetime.datetime.utcnow().__str__())) if "EventTid" not in event: final_parameters.append(TelemetryEventParam("EventTid", "")) if "EventPid" not in event: diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index cc10b7b9d0..fc1b9f4a64 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -95,6 +95,7 @@ def get_event_message(duration, evt_type, is_internal, is_success, message, name event.parameters.append(TelemetryEventParam('Message', message)) event.parameters.append(TelemetryEventParam('Duration', duration)) event.parameters.append(TelemetryEventParam('ExtensionType', evt_type)) + event.parameters.append(TelemetryEventParam('OpcodeName', '2019-11-06 02:00:44.307835')) data = get_properties(event) return json.dumps(data) @@ -257,7 +258,7 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events ] monitor_handler.sysinfo = sysinfo with patch("azurelinuxagent.ga.monitor.datetime") as patch_datetime: - patch_datetime.utcnow = Mock(return_value=datetime.datetime.strptime("2019-01-01 01:30:00", + patch_datetime.datetime.utcnow = Mock(return_value=datetime.datetime.strptime("2019-01-01 01:30:00", '%Y-%m-%d %H:%M:%S')) monitor_handler.add_sysinfo(event) @@ -613,6 +614,8 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): self.mock_init_sysinfo(monitor_handler) self.event_logger.save_event(create_dummy_event(message="Message-Test")) + + monitor_handler.last_event_collection = None monitor_handler.collect_and_send_events() # Validating the crafted message by the collect_and_send_events call. @@ -627,6 +630,7 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): '' \ '' \ '' \ + '' \ '' \ '' \ @@ -640,10 +644,16 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): '' \ '' \ '' \ - ''\ - ']]>'\ + '' \ + '' \ + '' \ + '' \ + '' \ + '' \ + ']]>' \ ''.format(AGENT_VERSION) + self.maxDiff = None self.assertEqual(sample_message, send_event_call_args[1]) @patch("azurelinuxagent.common.protocol.wire.WireClient.send_event") From 415612a7c33f7520710a8618e42cfa2627a3889b Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 6 Nov 2019 12:31:29 -0800 Subject: [PATCH 10/11] Make adding defaults cleaner, and test actual agent event. --- azurelinuxagent/common/event.py | 28 +++++++++++------------ azurelinuxagent/ga/monitor.py | 32 ++++++++++----------------- tests/data/ext/event_from_agent.json | 1 + tests/data/ext/event_from_agent.xml | 26 ---------------------- tests/ga/test_monitor.py | 33 +++++++++++----------------- 5 files changed, 38 insertions(+), 82 deletions(-) create mode 100644 tests/data/ext/event_from_agent.json delete mode 100644 tests/data/ext/event_from_agent.xml diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index 2a10a20c14..ac127b403e 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -16,7 +16,6 @@ # import atexit -import datetime import json import os import sys @@ -280,7 +279,7 @@ def _add_event(self, duration, evt_type, is_internal, is_success, message, name, event.parameters.append(TelemetryEventParam('Duration', duration)) event.parameters.append(TelemetryEventParam('ExtensionType', evt_type)) - self._add_default_parameters_to_event(event) + self.add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -307,7 +306,7 @@ def add_log_event(self, level, message): event.parameters.append(TelemetryEventParam('Context2', '')) event.parameters.append(TelemetryEventParam('Context3', '')) - self._add_default_parameters_to_event(event) + self.add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -335,7 +334,7 @@ def add_metric(self, category, counter, instance, value, log_event=False): event.parameters.append(TelemetryEventParam('Instance', instance)) event.parameters.append(TelemetryEventParam('Value', value)) - self._add_default_parameters_to_event(event) + self.add_default_parameters_to_event(event) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -343,27 +342,26 @@ def add_metric(self, category, counter, instance, value, log_event=False): logger.error("{0}", e) @staticmethod - def _add_default_parameters_to_event(event): + def add_default_parameters_to_event(event, set_default_values=False): # We write the GAVersion here rather than add it in azurelinuxagent.ga.monitor.MonitorHandler.add_sysinfo # as there could be a possibility of events being sent with newer version of the agent, rather than the agent # version generating the event. # Old behavior example: V1 writes the event on the disk and finds an update immediately, and updates. Now the # new monitor thread would pick up the events from the disk and send it with the CURRENT_AGENT, which would have # newer version of the agent. This causes confusion. - event.parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) - + # # ContainerId can change due to live migration and we want to preserve the container Id of the container writing # the event, rather than sending the event. - event.parameters.append(TelemetryEventParam('ContainerId', get_container_id_from_env())) + # OpcodeName: This is used as the actual time of event generation. - # This is used as the actual time of event generation. - event.parameters.append(TelemetryEventParam('OpcodeName', datetime.utcnow().__str__())) + default_parameters = [("GAVersion", CURRENT_AGENT), ('ContainerId', get_container_id_from_env()), + ('OpcodeName', datetime.utcnow().__str__()), + ('EventTid', threading.current_thread().ident), + ('EventPid', os.getpid()), ("TaskName", threading.current_thread().getName()), + ("KeywordName", '')] - # Other commong parameters added to the events - event.parameters.append(TelemetryEventParam('EventTid', threading.current_thread().ident)) - event.parameters.append(TelemetryEventParam('EventPid', os.getpid())) - event.parameters.append(TelemetryEventParam("TaskName", threading.current_thread().getName())) - event.parameters.append(TelemetryEventParam("KeywordName", '')) # Unused field for now. + for param in default_parameters: + event.parameters.append(TelemetryEventParam(param[0], param[1])) __event_logger__ = EventLogger() diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py index 57ef211d15..cbdbf8d279 100644 --- a/azurelinuxagent/ga/monitor.py +++ b/azurelinuxagent/ga/monitor.py @@ -320,36 +320,26 @@ def add_sysinfo(self, event): sysinfo_names = [v.name for v in self.sysinfo] final_parameters = [] + # Refer: azurelinuxagent.common.event.EventLogger.add_default_parameters_to_event for agent specific values. + # + # Default fields are only populated by Agent and not the extension. Agent will fill up any event if they don't + # have the default params. Example: GAVersion and ContainerId are populated for agent events on the fly, + # but not for extension events. Add it if it's missing. + default_values = [("ContainerId", get_container_id_from_env()), ("GAVersion", CURRENT_AGENT), + ("OpcodeName", ""), ("EventTid", 0), ("EventPid", 0), ("TaskName", ""), ("KeywordName", "")] + for param in event.parameters: # Discard any sys_info parameters already in the event, since they will be overwritten if param.name in sysinfo_names: continue - final_parameters.append(param) # Add sys_info params populated by the agent final_parameters.extend(self.sysinfo) - if "ContainerId" not in event: - # ContainerId is populated for agent events on the fly, but not for extension events. Add it if it's missing. - final_parameters.append( - TelemetryEventParam("ContainerId", get_container_id_from_env())) - if "GAVersion" not in event: - # GAVersion is populated for agent events on the fly, but not for extension events. Add it if it's missing. - final_parameters.append(TelemetryEventParam("GAVersion", CURRENT_AGENT)) - - # Default fields are only populated by Agent and not the extension. Agent will fill up any event if they don't - # have the default params. - if "OpcodeName" not in event: - final_parameters.append(TelemetryEventParam("OpcodeName", datetime.datetime.utcnow().__str__())) - if "EventTid" not in event: - final_parameters.append(TelemetryEventParam("EventTid", "")) - if "EventPid" not in event: - final_parameters.append(TelemetryEventParam("EventPid", "")) - if "TaskName" not in event: - final_parameters.append(TelemetryEventParam("TaskName", "")) - if "KeywordName" not in event: - final_parameters.append(TelemetryEventParam("KeywordName", "")) + for default_value in default_values: + if default_value[0] not in event: + final_parameters.append(TelemetryEventParam(default_value[0], default_value[1])) event.parameters = final_parameters diff --git a/tests/data/ext/event_from_agent.json b/tests/data/ext/event_from_agent.json new file mode 100644 index 0000000000..ff38e1e739 --- /dev/null +++ b/tests/data/ext/event_from_agent.json @@ -0,0 +1 @@ +{"eventId": 1, "providerId": "69B669B9-4AF8-4C50-BDC4-6006FA76E975", "parameters": [{"name": "Name", "value": "WALinuxAgent"}, {"name": "Version", "value": "2.2.44"}, {"name": "IsInternal", "value": false}, {"name": "Operation", "value": "ProcessGoalState"}, {"name": "OperationSuccess", "value": true}, {"name": "Message", "value": "Incarnation 12"}, {"name": "Duration", "value": 16610}, {"name": "ExtensionType", "value": ""}, {"name": "GAVersion", "value": "WALinuxAgent-2.2.44"}, {"name": "ContainerId", "value": "TEST-CONTAINER-ID-ALREADY-PRESENT-GUID"}, {"name": "OpcodeName", "value": "2019-11-02 01:42:49.188030"}, {"name": "EventTid", "value": 140240384030528}, {"name": "EventPid", "value": 108573}, {"name": "TaskName", "value": "ExtHandler"}, {"name": "KeywordName", "value": ""}]} \ No newline at end of file diff --git a/tests/data/ext/event_from_agent.xml b/tests/data/ext/event_from_agent.xml deleted file mode 100644 index d106d87318..0000000000 --- a/tests/data/ext/event_from_agent.xml +++ /dev/null @@ -1,26 +0,0 @@ - - - - - - - - - - - - - - - - - - - - - - - - - \ No newline at end of file diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index fc1b9f4a64..7cbaf01dd3 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -74,7 +74,6 @@ def create_dummy_event(size=0, evt_type="", message="DummyMessage", invalid_chars=False): - return get_event_message(name=size if size != 0 else name, op=op, is_success=is_success, @@ -124,13 +123,9 @@ def test_parse_json_event(self, *args): self.assertTrue(all(param is not None for param in event.parameters)) def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(self, *args): - data_str = load_data('ext/event_from_agent.xml') - event = parse_xml_event(data_str) + data_str = load_data('ext/event_from_agent.json') + event = parse_json_event(data_str) - # Pretend that the test event is coming from the agent by ensuring the event already has a container id - # generated on the fly - container_id_value = "TEST-CONTAINER-ID-ALREADY-PRESENT-GUID" - event.parameters.append(TelemetryEventParam("ContainerId", container_id_value)) monitor_handler = get_monitor_handler() sysinfo_vm_name_value = "sysinfo_dummy_vm" @@ -138,11 +133,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel sysinfo_role_name_value = "sysinfo_dummy_role" sysinfo_role_instance_name_value = "sysinfo_dummy_role_instance" sysinfo_execution_mode_value = "sysinfo_IAAS" + container_id_value = "TEST-CONTAINER-ID-ALREADY-PRESENT-GUID" GAVersion_value = "WALinuxAgent-2.2.44" - OpcodeName_value = "10101010" - EventTid_value = 140240309798656 + OpcodeName_value = "2019-11-02 01:42:49.188030" + EventTid_value = 140240384030528 EventPid_value = 108573 - TaskName_value = "MonitorHandler" + TaskName_value = "ExtHandler" KeywordName_value = "" vm_name_param = "VMName" @@ -174,6 +170,7 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel counter = 0 for p in event.parameters: + print(p.name, p.value) if p.name == vm_name_param: self.assertEqual(sysinfo_vm_name_value, p.value) counter += 1 @@ -230,9 +227,9 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events sysinfo_role_instance_name_value = "sysinfo_dummy_role_instance" sysinfo_execution_mode_value = "sysinfo_IAAS" GAVersion_value = "WALinuxAgent-2.2.44" - OpcodeName_value = "2019-01-01 01:30:00" # Mocking time below. - EventTid_value = "" - EventPid_value = "" + OpcodeName_value = "" + EventTid_value = 0 + EventPid_value = 0 TaskName_value = "" KeywordName_value = "" @@ -257,16 +254,12 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_extension_events TelemetryEventParam(role_name_param, sysinfo_role_name_value) ] monitor_handler.sysinfo = sysinfo - with patch("azurelinuxagent.ga.monitor.datetime") as patch_datetime: - patch_datetime.datetime.utcnow = Mock(return_value=datetime.datetime.strptime("2019-01-01 01:30:00", - '%Y-%m-%d %H:%M:%S')) - monitor_handler.add_sysinfo(event) + monitor_handler.add_sysinfo(event) self.assertNotEqual(None, event) self.assertNotEqual(0, event.parameters) self.assertTrue(all(param is not None for param in event.parameters)) - counter = 0 counter = 0 for p in event.parameters: if p.name == vm_name_param: @@ -647,8 +640,8 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): '' \ '' \ '' \ - '' \ - '' \ + '' \ + '' \ '' \ ']]>' \ ''.format(AGENT_VERSION) From 4a55c62bc021017407dc5510d6d80ee11fff7f75 Mon Sep 17 00:00:00 2001 From: Varad Meru Date: Wed, 6 Nov 2019 14:52:29 -0800 Subject: [PATCH 11/11] nit; remove debug print left. --- tests/ga/test_monitor.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py index 7cbaf01dd3..4232edaa47 100644 --- a/tests/ga/test_monitor.py +++ b/tests/ga/test_monitor.py @@ -170,7 +170,6 @@ def test_add_sysinfo_should_honor_sysinfo_values_from_agent_for_agent_events(sel counter = 0 for p in event.parameters: - print(p.name, p.value) if p.name == vm_name_param: self.assertEqual(sysinfo_vm_name_value, p.value) counter += 1