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 22f10f8e57..ac127b403e 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -16,10 +16,10 @@ # import atexit -import datetime import json import os import sys +import threading import time import traceback from datetime import datetime @@ -31,7 +31,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" @@ -40,6 +40,10 @@ 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" @@ -245,30 +249,19 @@ 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): 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) 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): if (not is_success) and log_event: _log_event(name, op, message, duration, is_success=is_success) @@ -281,14 +274,12 @@ def _add_event(self, duration, evt_type, is_internal, is_success, message, 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) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -315,6 +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) data = get_properties(event) try: self.save_event(json.dumps(data)) @@ -342,12 +334,35 @@ 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) 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, 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. + # + # 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. + # OpcodeName: This is used as the actual time of event generation. + + 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", '')] + + for param in default_parameters: + event.parameters.append(TelemetryEventParam(param[0], param[1])) + __event_logger__ = EventLogger() @@ -365,7 +380,7 @@ 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, @@ -375,10 +390,10 @@ def report_event(op, is_success=True, message='', log_event=True): def report_periodic(delta, op, is_success=True, message=''): 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) def report_metric(category, counter, instance, value, log_event=False, reporter=__event_logger__): @@ -400,10 +415,8 @@ def report_metric(category, counter, instance, value, log_event=False, reporter= reporter.add_metric(category, counter, instance, value, log_event) -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__): 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) @@ -411,10 +424,8 @@ 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) def add_log_event(level, message, reporter=__event_logger__): @@ -424,20 +435,16 @@ def add_log_event(level, message, reporter=__event_logger__): reporter.add_log_event(level, message) -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__): 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) def mark_event_status(name, version, op, status): 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/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 3ea3a4ea4c..cbdbf8d279 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 @@ -162,6 +163,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): @@ -171,7 +173,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: @@ -319,20 +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) - # 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]: - final_parameters.append( - TelemetryEventParam("ContainerId", os.environ.get(CONTAINER_ID_ENV_VARIABLE, "UNINITIALIZED"))) + 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/common/test_event.py b/tests/common/test_event.py index 9244e87512..4c676eeed8 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 +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.utils.extensionprocessutil import read_output from azurelinuxagent.common.protocol.wire import GoalState -from azurelinuxagent.common.version import CURRENT_VERSION +from azurelinuxagent.common.utils import fileutil +from azurelinuxagent.common.utils.extensionprocessutil import read_output +from azurelinuxagent.common.version import CURRENT_VERSION, CURRENT_AGENT from azurelinuxagent.ga.monitor import MonitorHandler - -from tests.tools import * - -import azurelinuxagent.common.event as event +from tests.tools import AgentTestCase, load_data, data_dir class TestEvent(AgentTestCase): @@ -269,13 +272,29 @@ 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_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) + 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) + + @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.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.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)) + @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, evt_type='', is_internal=False, is_success=True, + log_event=True, message='test event', op=WALAEventOperation.Unknown, + version=str(CURRENT_VERSION)) def test_save_event(self): add_event('test', message='test event') @@ -296,19 +315,54 @@ 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')) + 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)) event_json = json.loads(event_str) - self.assertEqual(len(event_json["parameters"]), 9) + 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"]: 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'], threading.current_thread().ident) + elif i['name'] == 'EventPid': + self.assertEqual(i['value'], 42) + elif i['name'] == 'TaskName': + 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'])) 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 4ade000d8d..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(5, 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/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.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.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 2f824c278f..4232edaa47 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, CONTAINER_ID_ENV_VARIABLE +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, AGENT_NAME +from azurelinuxagent.ga.monitor import parse_xml_event, get_monitor_handler, MonitorHandler, \ + generate_extension_metrics_telemetry_dictionary, parse_json_event 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.protocol.mockwiredata import WireProtocolData, DATA_FILE, conf +from tests.tools import load_data, AgentTestCase, data_dir, are_cgroups_enabled, i_am_root, skip_if_predicate_false class ResponseMock(Mock): @@ -49,17 +64,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, is_success=is_success, @@ -80,6 +94,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) @@ -94,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) @@ -108,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.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" @@ -122,6 +133,13 @@ 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 = "2019-11-02 01:42:49.188030" + EventTid_value = 140240384030528 + EventPid_value = 108573 + TaskName_value = "ExtHandler" + KeywordName_value = "" vm_name_param = "VMName" tenant_name_param = "TenantName" @@ -129,6 +147,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), @@ -164,13 +188,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() @@ -183,6 +225,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 = "" + EventTid_value = 0 + EventPid_value = 0 + TaskName_value = "" + KeywordName_value = "" vm_name_param = "VMName" tenant_name_param = "TenantName" @@ -190,6 +238,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), @@ -225,8 +279,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") @@ -533,7 +605,9 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): monitor_handler.init_protocols() self.mock_init_sysinfo(monitor_handler) - self.event_logger.save_event(create_event_message(message="Message-Test")) + 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. @@ -548,9 +622,9 @@ def test_collect_and_send_events(self, mock_lib_dir, patch_send_event, *args): '' \ '' \ '' \ + '' \ '' \ - '' \ '' \ '' \ '' \ @@ -562,10 +636,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") @@ -581,7 +661,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. @@ -601,7 +681,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() @@ -669,7 +749,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: @@ -696,7 +776,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. @@ -721,7 +801,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: