def test_it_should_honor_batch_time_limits_before_sending_telemetry(self): events = [TelemetryEvent(eventId=ustr(uuid.uuid4())), TelemetryEvent(eventId=ustr(uuid.uuid4()))] wait_time = timedelta(seconds=10) orig_sleep = time.sleep with patch("time.sleep", lambda *_: orig_sleep(0.01)): with patch("azurelinuxagent.ga.send_telemetry_events.SendTelemetryEventsHandler._MIN_BATCH_WAIT_TIME", wait_time): with self._create_send_telemetry_events_handler(batching_queue_limit=5) as telemetry_handler: for test_event in events: telemetry_handler.enqueue_event(test_event) self.assertEqual(0, len(telemetry_handler.event_calls), "No events should have been logged") TestSendTelemetryEventsHandler._stop_handler(telemetry_handler, timeout=0.01) wait_time = timedelta(seconds=0.2) with patch("time.sleep", lambda *_: orig_sleep(0.05)): with patch("azurelinuxagent.ga.send_telemetry_events.SendTelemetryEventsHandler._MIN_BATCH_WAIT_TIME", wait_time): with self._create_send_telemetry_events_handler(batching_queue_limit=5) as telemetry_handler: test_start_time = datetime.now() for test_event in events: telemetry_handler.enqueue_event(test_event) while not telemetry_handler.event_calls and (test_start_time + timedelta(seconds=1)) > datetime.now(): # Wait for event calls to be made, wait a max of 1 secs orig_sleep(0.1) self.assertGreater(len(telemetry_handler.event_calls), 0, "No event calls made at all!") self._assert_test_data_in_event_body(telemetry_handler, events) for event_time, _ in telemetry_handler.event_calls: elapsed = event_time - test_start_time # Technically we should send out data after 0.2 secs, but keeping a buffer of 1sec while testing self.assertLessEqual(elapsed, timedelta(seconds=1), "Request was not sent properly")
def test_report_event(self, mock_post): events = TelemetryEventList() data = self.load_json("events/1478123456789000.tld") event = TelemetryEvent() set_properties("event", event, data) events.events.append(event) data = self.load_json("events/1478123456789001.tld") event = TelemetryEvent() set_properties("event", event, data) events.events.append(event) data = self.load_json("events/1479766858966718.tld") event = TelemetryEvent() set_properties("event", event, data) events.events.append(event) protocol = MetadataProtocol() protocol.report_event(events) events_uri = BASE_URI.format( METADATA_ENDPOINT, "status/telemetry", APIVERSION) self.assertEqual(mock_post.call_count, 1) self.assertEqual(mock_post.call_args[0][0], events_uri) self.assertEqual(mock_post.call_args[0][1], get_properties(events))
def test_it_should_send_events_properly(self): events = [TelemetryEvent(eventId=ustr(uuid.uuid4())), TelemetryEvent(eventId=ustr(uuid.uuid4()))] with self._create_send_telemetry_events_handler() as telemetry_handler: for test_event in events: telemetry_handler.enqueue_event(test_event) self._assert_test_data_in_event_body(telemetry_handler, events)
def parse_xml_event(data_str): try: xml_doc = parse_doc(data_str) event_id = getattrib(find(xml_doc, "Event"), 'id') provider_id = getattrib(find(xml_doc, "Provider"), 'id') event = TelemetryEvent(event_id, provider_id) param_nodes = findall(xml_doc, 'Param') for param_node in param_nodes: event.parameters.append(parse_xml_param(param_node)) event.file_type = "xml" return event except Exception as e: raise ValueError(ustr(e))
def test_it_should_send_as_soon_as_events_available_in_queue_with_minimal_batching_limits(self): events = [TelemetryEvent(eventId=ustr(uuid.uuid4())), TelemetryEvent(eventId=ustr(uuid.uuid4()))] with self._create_send_telemetry_events_handler() as telemetry_handler: test_start_time = datetime.now() for test_event in events: telemetry_handler.enqueue_event(test_event) self._assert_test_data_in_event_body(telemetry_handler, events) # Ensure that we send out the data as soon as we enqueue the events for event_time, _ in telemetry_handler.event_calls: elapsed = event_time - test_start_time self.assertLessEqual(elapsed, timedelta(seconds=2), "Request was not sent as soon as possible")
def test_it_should_clear_queue_before_stopping(self): events = [TelemetryEvent(eventId=ustr(uuid.uuid4())), TelemetryEvent(eventId=ustr(uuid.uuid4()))] wait_time = timedelta(seconds=10) with patch("time.sleep", lambda *_: mock_sleep(0.01)): with patch("azurelinuxagent.ga.send_telemetry_events.SendTelemetryEventsHandler._MIN_BATCH_WAIT_TIME", wait_time): with self._create_send_telemetry_events_handler(batching_queue_limit=5) as telemetry_handler: for test_event in events: telemetry_handler.enqueue_event(test_event) self.assertEqual(0, len(telemetry_handler.event_calls), "No events should have been logged") TestSendTelemetryEventsHandler._stop_handler(telemetry_handler, timeout=0.01) # After the service is asked to stop, we should send all data in the queue self._assert_test_data_in_event_body(telemetry_handler, events)
def add_metric(self, category, counter, instance, value, log_event=False): """ Create and save an event which contains a telemetry event. :param str category: The category of metric (e.g. "cpu", "memory") :param str counter: The specific metric within the category (e.g. "%idle") :param str instance: For instanced metrics, the instance identifier (filesystem name, cpu core#, etc.) :param value: Value of the metric :param bool log_event: If true, log the collected metric in the agent log """ if log_event: from azurelinuxagent.common.version import AGENT_NAME message = "Metric {0}/{1} [{2}] = {3}".format( category, counter, instance, value) _log_event(AGENT_NAME, "METRIC", message, 0) event = TelemetryEvent(4, "69B669B9-4AF8-4C50-BDC4-6006FA76E975") event.parameters.append(TelemetryEventParam('Category', category)) event.parameters.append(TelemetryEventParam('Counter', counter)) 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)
def test_thread_should_wait_for_events_to_get_in_queue_before_processing(self): events = [TelemetryEvent(eventId=ustr(uuid.uuid4())), TelemetryEvent(eventId=ustr(uuid.uuid4()))] with self._create_send_telemetry_events_handler(timeout=0.1) as telemetry_handler: # Do nothing for some time time.sleep(0.3) # Ensure that no events were transmitted by the telemetry handler during this time, i.e. telemetry thread was idle self.assertEqual(0, len(telemetry_handler.event_calls), "Unwanted calls to telemetry") # Now enqueue data and verify send_telemetry_events sends them asap for test_event in events: telemetry_handler.enqueue_event(test_event) self._assert_test_data_in_event_body(telemetry_handler, events)
def add_metric(self, category, counter, instance, value, log_event=False): """ Create and save an event which contains a telemetry event. :param str category: The category of metric (e.g. "cpu", "memory") :param str counter: The specific metric within the category (e.g. "%idle") :param str instance: For instanced metrics, the instance identifier (filesystem name, cpu core#, etc.) :param value: Value of the metric :param bool log_event: If true, log the collected metric in the agent log """ if log_event: message = "Metric {0}/{1} [{2}] = {3}".format(category, counter, instance, value) _log_event(AGENT_NAME, "METRIC", message, 0) event = TelemetryEvent(TELEMETRY_METRICS_EVENT_ID, TELEMETRY_EVENT_PROVIDER_ID) event.parameters.append(TelemetryEventParam(GuestAgentPerfCounterEventsSchema.Category, str(category))) event.parameters.append(TelemetryEventParam(GuestAgentPerfCounterEventsSchema.Counter, str(counter))) event.parameters.append(TelemetryEventParam(GuestAgentPerfCounterEventsSchema.Instance, str(instance))) event.parameters.append(TelemetryEventParam(GuestAgentPerfCounterEventsSchema.Value, float(value))) self.add_common_event_parameters(event, datetime.utcnow()) 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 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(GuestAgentExtensionEventsSchema.Name, name)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.Version, str(version))) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.IsInternal, is_internal)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.Operation, op)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.OperationSuccess, is_success)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.Message, message)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.Duration, duration)) event.parameters.append( TelemetryEventParam(GuestAgentExtensionEventsSchema.ExtensionType, evt_type)) return event
def add_event(self, name, op=WALAEventOperation.Unknown, is_success=True, duration=0, version=str(CURRENT_VERSION), message="", log_event=True): if (not is_success) and log_event: _log_event(name, op, message, duration, is_success=is_success) event = TelemetryEvent(TELEMETRY_EVENT_EVENT_ID, TELEMETRY_EVENT_PROVIDER_ID) event.parameters.append(TelemetryEventParam('Name', str(name))) event.parameters.append(TelemetryEventParam('Version', str(version))) event.parameters.append(TelemetryEventParam('Operation', str(op))) event.parameters.append( TelemetryEventParam('OperationSuccess', bool(is_success))) event.parameters.append(TelemetryEventParam('Message', str(message))) event.parameters.append(TelemetryEventParam('Duration', int(duration))) self._add_common_event_parameters(event, datetime.utcnow()) 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 = TelemetryEvent(TELEMETRY_LOG_EVENT_ID, TELEMETRY_LOG_PROVIDER_ID) event.parameters.append( TelemetryEventParam(GuestAgentGenericLogsSchema.EventName, WALAEventOperation.Log)) event.parameters.append( TelemetryEventParam(GuestAgentGenericLogsSchema.CapabilityUsed, logger.LogLevel.STRINGS[level])) event.parameters.append( TelemetryEventParam( GuestAgentGenericLogsSchema.Context1, str_to_encoded_ustr(self._clean_up_message(message)))) event.parameters.append( TelemetryEventParam( GuestAgentGenericLogsSchema.Context2, datetime.utcnow().strftime(logger.Logger.LogTimeFormatInUTC))) event.parameters.append( TelemetryEventParam(GuestAgentGenericLogsSchema.Context3, '')) self.add_common_event_parameters(event, datetime.utcnow()) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError: pass
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 <text>. # # The timestamp and the level are redundant, and should be stripped. # The logging library does not schematize this data, so I am forced # to parse the message. The format is regular, so the burden is low. parts = message.split(' ', 3) msg = parts[3] if len(parts) == 4 \ else message event = TelemetryEvent(7, "FFF0196F-EE4C-4EAF-9AA5-776F622DEB4F") event.parameters.append( TelemetryEventParam('EventName', WALAEventOperation.Log)) event.parameters.append( TelemetryEventParam('CapabilityUsed', logger.LogLevel.STRINGS[level])) event.parameters.append(TelemetryEventParam('Context1', msg)) 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)) except EventError: pass
def test_it_should_raise_on_enqueue_if_service_stopped(self): with self._create_send_telemetry_events_handler(start_thread=False) as telemetry_handler: # Ensure the thread is stopped telemetry_handler.stop() with self.assertRaises(ServiceStoppedError) as context_manager: telemetry_handler.enqueue_event(TelemetryEvent(eventId=ustr(uuid.uuid4()))) exception = context_manager.exception self.assertIn("{0} is stopped, not accepting anymore events".format(telemetry_handler.get_thread_name()), str(exception))
def _setup_and_assert_bad_request_scenarios(self, http_post_handler, expected_msgs): with self._create_send_telemetry_events_handler() as telemetry_handler: telemetry_handler.get_mock_wire_protocol().set_http_handlers(http_post_handler=http_post_handler) with patch("azurelinuxagent.common.event.add_event") as mock_add_event: telemetry_handler.enqueue_event(TelemetryEvent()) TestSendTelemetryEventsHandler._stop_handler(telemetry_handler) for msg in expected_msgs: self._assert_error_event_reported(mock_add_event, msg)
def test_it_should_honor_batch_queue_limits_before_sending_telemetry(self): batch_limit = 5 with self._create_send_telemetry_events_handler(batching_queue_limit=batch_limit) as telemetry_handler: events = [] for _ in range(batch_limit-1): test_event = TelemetryEvent(eventId=ustr(uuid.uuid4())) events.append(test_event) telemetry_handler.enqueue_event(test_event) self.assertEqual(0, len(telemetry_handler.event_calls), "No events should have been logged") for _ in range(batch_limit): test_event = TelemetryEvent(eventId=ustr(uuid.uuid4())) events.append(test_event) telemetry_handler.enqueue_event(test_event) self._assert_test_data_in_event_body(telemetry_handler, events)
def _update_legacy_agent_event(self, event, event_creation_time): # Ensure that if an agent event is missing a field from the schema defined since 2.2.47, the missing fields # will be appended, ensuring the event schema is complete before the event is reported. new_event = TelemetryEvent() new_event.parameters = [] self._add_common_event_parameters(new_event, event_creation_time) event_params = dict([(param.name, param.value) for param in event.parameters]) new_event_params = dict([(param.name, param.value) for param in new_event.parameters]) missing_params = set(new_event_params.keys()).difference( set(event_params.keys())) params_to_add = [] for param_name in missing_params: params_to_add.append( TelemetryEventParam(param_name, new_event_params[param_name])) event.parameters.extend(params_to_add)
def _get_event_data(message, name): event = TelemetryEvent(1, TestSendTelemetryEventsHandler._TEST_EVENT_PROVIDER_ID) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.Name, name)) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.Version, str(CURRENT_VERSION))) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.Operation, WALAEventOperation.Unknown)) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.OperationSuccess, True)) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.Message, message)) event.parameters.append(TelemetryEventParam(GuestAgentExtensionEventsSchema.Duration, 0)) data = get_properties(event) return json.dumps(data)
def _parse_telemetry_event(self, handler_name, extension_unparsed_event, event_file_time): """ Parse the Json event file and convert it to TelemetryEvent object with the required data. :return: Complete TelemetryEvent with all required fields filled up properly. Raises if event breaches contract. """ extension_event = self._parse_event_and_ensure_it_is_valid( extension_unparsed_event) # Create a telemetry event, add all common parameters to the event # and then overwrite all the common params with extension events params if same event = TelemetryEvent(TELEMETRY_LOG_EVENT_ID, TELEMETRY_LOG_PROVIDER_ID) event.file_type = "json" CollectTelemetryEventsHandler.add_common_params_to_telemetry_event( event, event_file_time) replace_or_add_params = { GuestAgentGenericLogsSchema.EventName: "{0}-{1}".format( handler_name, extension_event[ExtensionEventSchema.Version.lower()]), GuestAgentGenericLogsSchema.CapabilityUsed: extension_event[ExtensionEventSchema.EventLevel.lower()], GuestAgentGenericLogsSchema.TaskName: extension_event[ExtensionEventSchema.TaskName.lower()], GuestAgentGenericLogsSchema.Context1: extension_event[ExtensionEventSchema.Message.lower()], GuestAgentGenericLogsSchema.Context2: extension_event[ExtensionEventSchema.Timestamp.lower()], GuestAgentGenericLogsSchema.Context3: extension_event[ExtensionEventSchema.OperationId.lower()], GuestAgentGenericLogsSchema.EventPid: extension_event[ExtensionEventSchema.EventPid.lower()], GuestAgentGenericLogsSchema.EventTid: extension_event[ExtensionEventSchema.EventTid.lower()] } self._replace_or_add_param_in_event(event, replace_or_add_params) return event
def test_it_should_honour_the_incoming_order_of_events(self): with self._create_send_telemetry_events_handler(timeout=0.3, start_thread=False) as telemetry_handler: for index in range(5): telemetry_handler.enqueue_event(TelemetryEvent(eventId=index)) telemetry_handler.start() self.assertTrue(telemetry_handler.is_alive(), "Thread not alive") TestSendTelemetryEventsHandler._stop_handler(telemetry_handler) _, event_body = telemetry_handler.event_calls[0] event_orders = re.findall(r'<Event id=\"(\d+)\"><!\[CDATA\[]]></Event>', event_body) self.assertEqual(sorted(event_orders), event_orders, "Events not ordered correctly")
def test_send_telemetry_events_should_add_event_on_unexpected_errors(self): with self._create_send_telemetry_events_handler(timeout=0.1) as telemetry_handler: with patch("azurelinuxagent.ga.send_telemetry_events.add_event") as mock_add_event: with patch("azurelinuxagent.common.protocol.wire.WireClient.report_event") as patch_report_event: test_str = "Test exception, Guid: {0}".format(str(uuid.uuid4())) patch_report_event.side_effect = Exception(test_str) telemetry_handler.enqueue_event(TelemetryEvent()) TestSendTelemetryEventsHandler._stop_handler(telemetry_handler, timeout=0.01) self._assert_error_event_reported(mock_add_event, test_str, operation=WALAEventOperation.UnhandledError)
def _get_event_data(duration, is_success, message, name, op, version, 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('Operation', op)) event.parameters.append( TelemetryEventParam('OperationSuccess', is_success)) event.parameters.append(TelemetryEventParam('Message', message)) event.parameters.append(TelemetryEventParam('Duration', duration)) data = get_properties(event) return json.dumps(data)
def add_log_event(self, level, message): event = TelemetryEvent(TELEMETRY_LOG_EVENT_ID, TELEMETRY_LOG_PROVIDER_ID) event.parameters.append( TelemetryEventParam('EventName', WALAEventOperation.Log)) event.parameters.append( TelemetryEventParam('CapabilityUsed', logger.LogLevel.STRINGS[level])) event.parameters.append( TelemetryEventParam('Context1', self._clean_up_message(message))) event.parameters.append(TelemetryEventParam('Context2', '')) event.parameters.append(TelemetryEventParam('Context3', '')) self._add_common_event_parameters(event, datetime.utcnow()) data = get_properties(event) try: self.save_event(json.dumps(data)) except EventError: pass
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
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))) 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)) 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 parse_json_event(data_str): data = json.loads(data_str) event = TelemetryEvent() set_properties("TelemetryEvent", event, data) return event