Populate telemetry events at creation time #1791

narrieta · 2020-02-26T20:48:16Z

Replaces #1757

Updates:

Instead of patching old agent events at startup, it patches them at collection time
To distinguish between events from old agents and current agent, saves telemetry files as *.waagent.tld instead of *.tld
Initializes common fields in the daemon (they were initialized only on the extension handler)
Merges SysInfo into EventLogger
Uses a static member (GoalState.ContainerID) instead of an environment variable to keep the latest container ID
Simplifies MonitorHandle.collect_and_send_events and improves error handling collecting events
Removes the call to update_goal_state() from the intialization of the MonitorHandle
Internal refactoring of the logic that adds common parameters to events; merged a few methods together
Many test improvements to avoid testing via private implementation details

This change is

…sion related values

codecov · 2020-02-26T20:50:48Z

Codecov Report

Merging #1791 into develop will decrease coverage by 0.08%.
The diff coverage is n/a.

@@             Coverage Diff             @@
##           develop    #1791      +/-   ##
===========================================
- Coverage    68.95%   68.87%   -0.09%     
===========================================
  Files           81       81              
  Lines        11322    11360      +38     
  Branches      1597     1601       +4     
===========================================
+ Hits          7807     7824      +17     
- Misses        3187     3204      +17     
- Partials       328      332       +4

Impacted Files	Coverage Δ
azurelinuxagent/common/telemetryevent.py	`72.41% <0.00%> (-27.59%)`	⬇️
azurelinuxagent/ga/monitor.py	`83.65% <0.00%> (-5.31%)`	⬇️
azurelinuxagent/ga/update.py	`88.24% <0.00%> (+0.01%)`	⬆️
azurelinuxagent/common/logger.py	`90.90% <0.00%> (+0.11%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ce8e736...57a9735. Read the comment docs.

azurelinuxagent/common/event.py

narrieta · 2020-02-26T21:14:09Z

azurelinuxagent/common/event.py

@@ -53,15 +57,13 @@

 MAX_NUMBER_OF_EVENTS = 1000

+EVENT_FILE_EXTENSION = '.waagent.tld'


Events produced by >= 2.2.47 will be saved as *.waagent.tld

NIT: Rename this to AGENT_EVENT_FILE_EXTENSION

yup, thanks!

azurelinuxagent/common/event.py

narrieta · 2020-02-26T21:22:12Z

azurelinuxagent/common/event.py

    @staticmethod
-    def add_default_parameters_to_event(event_parameters, set_values_for_agent=True):
+    def _trim_extension_event_parameters(event):


This comes from #1757; we need to improve the way we handle parameters to avoid all those sequential traversals of the array

azurelinuxagent/common/event.py

narrieta · 2020-02-26T21:26:20Z

azurelinuxagent/common/event.py

+    def _update_old_event_schema(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()


This comes from #1757. I discussed this @pgombar - we should not just add any missing fields since we may hide bugs elsewhere or populate with invalid values. Some missing fields must be added, though. For example, OpCode (timestamp) will be in 2.2.46, but not on previous agents.

azurelinuxagent/common/protocol/imds.py

azurelinuxagent/common/protocol/restapi.py

narrieta · 2020-02-26T21:28:34Z

azurelinuxagent/common/telemetryevent.py


    # 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]

+    def is_extension_event(self):


From #1757 - Needs improvement to avoid traversing the array

azurelinuxagent/daemon/main.py

azurelinuxagent/ga/monitor.py

tests/common/test_logger.py

tests/data/events/collect_and_send_events_invalid_data/1560752429123264-1.tld

tests/data/ext/event_from_agent.json

tests/ga/test_monitor.py

tests/tools.py

tests/common/test_event.py

azurelinuxagent/common/event.py

tests/tools.py

pgombar

Reviewed agent code, will look at tests later.

azurelinuxagent/common/event.py

pgombar · 2020-02-28T20:32:12Z

tests/ga/test_monitor.py

+                version=version,
+                message=random_generator(size) if size != 0 else message)
+        event_file = os.path.join(self.event_dir, "{0}.tld".format(int(time.time() * 1000000)))
+        with open(event_file, 'wb+') as fd:


Could we use save_event here? It handles the naming and event_dir creation if needed.

save_event should be a private of EventLogger, we should not introduce dependencies on private members

Also, see my comment below

pgombar · 2020-02-28T20:35:42Z

tests/ga/test_monitor.py

+            fd.write(event_data.encode('utf-8'))
+
+    @staticmethod
+    def _get_event_data(duration, is_success, message, name, op, version, eventId=1):


PyCharm identified that this method is nearly identical to tests.protocol.test_wire.get_event. In fact, the one in test_wire is outdated since we are also adding the IsInternal parameter which is removed with this change. Can you please merge the two methods?

I had to deal with so many test breaks that I did not cleanup all the tests and some of them (like this one) I only modified to allow them to pass. The original code was creating a weird event that did not follow the schema for an extension or an agent event, but was saving it using the "*.tld" extension so it looked to the new code as an extension event, causing many of these tests to break. Had it been done using the public interface (add_event, for example) the internal refactoring would have not caused any issues with it.

As we do improvements on the existing code we are going to have to decide at what point to stop. I had already done a fair amount of work investigating test failures and rewriting many of them and I did not go further on this one on specific. Each one of us will have to make that call. I stopped here.

When writing new code though, we should make every effort to avoid this kind of issues, though. I believe these tests are relatively recent, but to be fair we have not been paying enough attention to design as a team. Let's try to improve from now on.

pgombar · 2020-02-28T22:15:30Z

tests/common/test_event.py

+        self._create_test_event_file("custom_script_utf-16.tld")
+        self._create_test_event_file("custom_script_invalid_json.tld")
+        os.chmod(self._create_test_event_file("custom_script_no_read_access.tld"), 0o200)
+        self._create_test_event_file("custom_script_valid_json.tld")


What's the difference between custom_script_valid_json.tld and custom_script.tld?

none, i just want 2 valid events -- i'll rename to custom-script-1 & 2

pgombar · 2020-02-28T22:17:08Z

tests/common/test_event.py

+            # expected_warn_message = r'Failed to process event file.*custom_script_with_invalid_json.tld.*Error parsing event'
+            # self.assertIsNotNone(re.search(expected_warn_message, str(mock_warn.call_args[0])))


actually it is an assert i forgot to put back. will do

azurelinuxagent/common/event.py

pgombar · 2020-02-28T22:57:53Z

tests/common/test_event.py

+    def test_collect_events_should_add_all_the_parameters_in_the_telemetry_schema_to_extension_events(self):
+        self._assert_extension_event_includes_all_parameters_in_the_telemetry_schema('custom_script.tld')
+
+    def test_collect_events_should_ignore_extra_parameters_in_extension_events(self):
+        self._assert_extension_event_includes_all_parameters_in_the_telemetry_schema('custom_script_extra_parameters.tld')


We should also test extension events that are XML, not just JSON. The original need for this PR was because we were incorrectly handling XML extension events, because they already had ContainerId present, but empty, which we honored instead of overriding the value.

There is an existing (real) VMAccess XML event in \tests\data\ext\event_from_extension.xml.

The filename event_from_extension.xml should be updated too, since extension events are .tld, regardless of if they're XML or JSON.

Discussed offline - this is covered in the test case using custom_script_extra_parameters.tld

pgombar

Added review of tests

larohra

1 small comment else LGTM

larohra · 2020-02-29T02:16:24Z

azurelinuxagent/common/event.py

@@ -53,15 +57,13 @@

 MAX_NUMBER_OF_EVENTS = 1000

+EVENT_FILE_EXTENSION = '.waagent.tld'


NIT: Rename this to AGENT_EVENT_FILE_EXTENSION

larohra · 2020-02-29T02:16:51Z

azurelinuxagent/common/event.py

@@ -53,15 +58,13 @@

 MAX_NUMBER_OF_EVENTS = 1000

+EVENT_FILE_EXTENSION = '.waagent.tld'
+EVENT_FILE_REGEX = re.compile(r'(?P<agent_event>\.waagent)?\.tld$')


Same, rename this to AGENT_EVENT_FILE_REGEX for clarity

this one is different: it matches all event files (new agent, old agent and extensions)

pgombar

LGTM, thanks for all these improvements, especially the tests!

pgombar and others added 12 commits January 13, 2020 16:19

always override ContainerId and GAVersion, honor the rest if stated

7f336d7

refactor finalizing event parameters and update tests

1b55030

simplify logic for adding common fields; implement removing non-exten…

c27b2ef

…sion related values

Merge branch 'develop' into fix_extension_events

1f86ca3

refactor telemetry code, add tests

52a3f84

add lock for singleton and fix py2.6 test failure

4cb6dc2

Merge branch 'develop' into fix_extension_events

871f03a

address CR comments

a1af429

Merge branch 'develop' into fix_extension_events

371bf94

Merge from pgombar

d49a448

Merge from develop; write agent events to waagent-events

88ac048

Use .waagent.tld extension for event files

c25372a

narrieta requested review from larohra, pgombar and vrdmr as code owners February 26, 2020 20:48