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