Telemetry not supported incident mitigation (#114)

Mitigation + additional logging for telemetry not supported incident.

Author: benank

src/core/src/core_logic/ConfigurePatchingProcessor.py

@@ -139,7 +139,7 @@ def __raise_if_agent_incompatible(self):
             self.composite_logger.log("Skipping agent compatibility check for Arc cloud type when operation is not manual")
             return
         if not self.telemetry_writer.is_agent_compatible():
-            error_msg = Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG
+            error_msg = "{0} [{1}]".format(Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG, self.telemetry_writer.get_telemetry_diagnostics())
             self.composite_logger.log_error(error_msg)
             raise Exception(error_msg)
 

src/core/src/core_logic/PatchAssessor.py

@@ -84,7 +84,7 @@ def raise_if_agent_incompatible(self):
             self.composite_logger.log("Skipping agent compatibility check for Arc cloud type when operation is not manual")
             return
         if not self.telemetry_writer.is_agent_compatible():
-            error_msg = Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG
+            error_msg = "{0} [{1}]".format(Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG, self.telemetry_writer.get_telemetry_diagnostics())
             self.composite_logger.log_error(error_msg)
             raise Exception(error_msg)
 

src/core/src/core_logic/PatchInstaller.py

@@ -103,7 +103,7 @@ def raise_if_agent_incompatible(self):
             self.composite_logger.log("Skipping agent compatibility check for Arc cloud type when operation is not manual")
             return
         if not self.telemetry_writer.is_agent_compatible():
-            error_msg = Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG
+            error_msg = "{0} [{1}]".format(Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG, self.telemetry_writer.get_telemetry_diagnostics())
             self.composite_logger.log_error(error_msg)
             raise Exception(error_msg)
 

src/core/src/service_interfaces/TelemetryWriter.py

@@ -37,8 +37,9 @@ def __init__(self, env_layer, composite_logger, events_folder_path):
         self.__telemetry_event_counter = 1  # will be added at the end of each event sent to telemetry to assist in tracing and identifying event/message loss in telemetry
         self.start_time_for_event_count_throttle_check = datetime.datetime.utcnow()
         self.event_count = 1
+        self.agent_env_var_code = 0  # code to give details on what went wrong when getting env var
 
-        if self.__get_agent_supports_telemetry_from_env_var() and self.__get_events_folder_path_exists(events_folder_path):
+        if self.__get_events_folder_path_exists(events_folder_path):
             self.events_folder_path = events_folder_path
             self.__is_agent_compatible = True
 
@@ -127,15 +128,18 @@ def __get_agent_supports_telemetry_from_env_var(self):
         """ Returns True if the env var AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES has a key of
             ExtensionTelemetryPipeline in the list. Value of the env var looks like this:
             '[{  "Key": "ExtensionTelemetryPipeline", "Value": "1.0"}]' """
+        self.agent_env_var_code = 0
         features_keyvalue_list_str = os.getenv(Constants.AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES_ENV_VAR)
         if features_keyvalue_list_str is None:
             self.composite_logger.log_error('Failed to get guest agent supported features from env var. [Var={0}]'.format(Constants.AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES_ENV_VAR))
+            self.agent_env_var_code = 1
             return False
 
         features_keyvalue_list = json.loads(features_keyvalue_list_str)
         telemetry_supported_key_exists = any(kv_pair for kv_pair in features_keyvalue_list if kv_pair['Key'] == Constants.TELEMETRY_EXTENSION_PIPELINE_SUPPORTED_KEY)
         if telemetry_supported_key_exists is False:
             self.composite_logger.log_error('Guest agent does not support telemetry. [Error=Key not found: {0}]'.format(Constants.TELEMETRY_EXTENSION_PIPELINE_SUPPORTED_KEY))
+            self.agent_env_var_code = 2
 
         return telemetry_supported_key_exists
 
@@ -189,6 +193,28 @@ def __extract_agent_version_from_string(self, pattern, string):
 
         return version_search.group()
 
+    def get_telemetry_diagnostics(self):
+        """ Returns information about the guest agent telemetry for debugging purposes.
+            Information message abbreviations:
+                AV: Agent Version (Guest Agent)
+                AGSV: Agent Goal State Version (Guest Agent)
+                EFE: Events Folder Exists (on disk)
+                EV: Env Var exists
+                EVC: Env Var Code (more detailed information on what went wrong when getting the env var)
+                    See __get_agent_supports_telemetry_from_env_var for more information
+        """
+        agent_version = self.get_agent_version()
+        agent_goalstate_version = self.get_goal_state_agent_version()
+        events_folder_exists = self.__get_events_folder_path_exists(self.events_folder_path)
+        telemetry_env_var_supported = self.__get_agent_supports_telemetry_from_env_var()
+        return "AV:{0}, AGSV:{1}, EFE:{2}, EV:{3}, EVC:{4}".format(
+                str(agent_version) if agent_version is not None else "-1",
+                str(agent_goalstate_version) if agent_goalstate_version is not None else "-1",
+                "1" if events_folder_exists is True else "0",
+                "1" if telemetry_env_var_supported is True else "0",
+                str(self.agent_env_var_code)
+            )
+
     def __log_agent_information(self):
         """ Logs WALinuxAgent version information. """
         agent_version = self.get_agent_version()

src/extension/src/ActionHandler.py

@@ -112,30 +112,44 @@ def tear_down(self):
             self.file_logger = None
 
     def setup_telemetry(self):
-        """ Init telemetry if agent is compatible (env var check) AND events_folder is specified.
+        """ Init telemetry if agent is compatible (events_folder is specified).
             Otherwise, error since guest agent does not support telemetry. """
         events_folder = self.ext_env_handler.events_folder
-        if events_folder is not None and self.telemetry_writer.is_agent_compatible():
+        if events_folder is not None:
             # Guest agent fully supports telemetry
-            ''' NOTE: unlike core, this code will run even if events_folder does not exist, 
-                since telemetry_writer.is_agent_compatible() only checks the env var. 
-                This ensures that the events_folder exists once core runs. '''
+            self.__log_telemetry_info(telemetry_supported=True)
+
             if not os.path.exists(events_folder):
                 os.mkdir(events_folder)
-                self.logger.log("Events folder path found in HandlerEnvironment but does not exist on disk. Creating now. [Path={0}]".format(str(events_folder)))
-            
-            self.logger.log(Constants.TELEMETRY_AT_AGENT_COMPATIBLE_MSG)
+                self.logger.log("Events folder path found in HandlerEnvironment but does not exist on disk. Creating now. [Path={0}][AgentVersion={1}]".format(
+                    str(events_folder), str(self.telemetry_writer.get_agent_version())))
+
             self.telemetry_writer.events_folder_path = events_folder
             # As this is a common function used by all handler actions, setting operation_id such that it will be the same timestamp for all handler actions, which can be used for identifying all events for an operation.
             # NOTE: Enable handler action will set operation_id to activity_id from config settings. And the same will be used in Core.
             self.telemetry_writer.set_operation_id(self.operation_id_substitute_for_all_actions_in_telemetry)
         else:
-            # Guest agent does not support telemetry (incompatible OR events_folder not specified)
-            err_msg = Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG
-            if self.telemetry_writer.is_agent_compatible():
-                # Agent is compatible but events folder was not given, so log additional agent version info
-                err_msg += " [AgentVer: {0} GoalStateVer: {1}]".format(self.telemetry_writer.get_agent_version(), self.telemetry_writer.get_goal_state_agent_version())
-            self.logger.log_error(err_msg)
+            self.__log_telemetry_info(telemetry_supported=False)
+
+    def __log_telemetry_info(self, telemetry_supported):
+        """ Logs detailed information about telemetry and logs an error if telemetry is not supported. """
+        events_folder = self.ext_env_handler.events_folder
+        events_folder_str = str(events_folder) if events_folder is not None else ""
+        events_folder_exists = os.path.exists(events_folder) if events_folder is not None else False
+        env_var_supports_telemetry = self.telemetry_writer.is_agent_compatible()
+        telemetry_info = "[EventsFolder=\'{0}\'][EventsFolderExists={1}][EnvVar={2}]".format(
+            events_folder_str, str(events_folder_exists), env_var_supports_telemetry)
+
+        if env_var_supports_telemetry is True:
+            telemetry_info += "[AgentVer={0}][GoalStateVer={1}]".format(self.telemetry_writer.get_agent_version(), self.telemetry_writer.get_goal_state_agent_version())
+        else:
+            telemetry_info += "[AgentVer=Unknown][GoalStateVer=Unknown]"
+
+        if telemetry_supported is True:
+            self.logger.log("{0} {1}".format(Constants.TELEMETRY_AT_AGENT_COMPATIBLE_MSG, telemetry_info))
+        else:
+            error_msg = "{0} {1}".format(Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG, telemetry_info)
+            self.logger.log_error(error_msg)
 
     def install(self):
         try:

src/extension/src/TelemetryWriter.py

@@ -28,8 +28,9 @@
 class TelemetryWriter(object):
     """Class for writing telemetry data to events"""
 
-    def __init__(self, logger):
+    def __init__(self, logger, env_layer):
         self.logger = logger
+        self.env_layer = env_layer
         self.events_folder_path = None
         self.__operation_id = ""
         self.__agent_is_compatible = self.__get_agent_supports_telemetry_from_env_var()
@@ -82,7 +83,7 @@ def __events_folder_exists(self):
     def write_event(self, message, event_level=Constants.TelemetryEventLevel.Informational, task_name=Constants.TELEMETRY_TASK_NAME):
         """ Creates and writes event to event file after validating none of the telemetry size restrictions are breached """
         try:
-            if not self.__events_folder_exists() or not self.__agent_is_compatible or not Constants.TELEMETRY_ENABLED_AT_EXTENSION:
+            if not self.__events_folder_exists() or not Constants.TELEMETRY_ENABLED_AT_EXTENSION:
                 return
 
             self.__delete_older_events()

src/extension/src/__main__.py

@@ -37,8 +37,9 @@
 def main(argv):
     stdout_file_mirror = None
     file_logger = None
+    env_layer = EnvLayer()
     logger = Logger()
-    telemetry_writer = TelemetryWriter(logger)
+    telemetry_writer = TelemetryWriter(logger, env_layer)
     logger.telemetry_writer = telemetry_writer  # Need to set telemetry_writer within logger to enable sending all logs to telemetry
     try:
         # initializing action handler
@@ -48,7 +49,6 @@ def main(argv):
         runtime_context_handler = RuntimeContextHandler(logger)
         json_file_handler = JsonFileHandler(logger)
         ext_env_handler = ExtEnvHandler(json_file_handler)
-        env_layer = EnvLayer()
         env_health_manager = EnvHealthManager(env_layer)
         if ext_env_handler.handler_environment_json is not None and ext_env_handler.config_folder is not None:
             config_folder = ext_env_handler.config_folder

src/extension/tests/Test_ActionHandler.py

@@ -252,7 +252,7 @@ def test_update_command_fail(self):
         # Remove the directory after the test
         shutil.rmtree(test_dir)
 
-    def test_telemetry_not_available(self):
+    def test_telemetry_available_env_var_not_exists(self):
         # agent env var is not set so telemetry is not supported
         backup_os_getenv = os.getenv
         backup_telemetry_writer = self.runtime.telemetry_writer
@@ -262,14 +262,14 @@ def mock_os_getenv(name, value=None):
 
         # Re-init TelemetryWriter since the env var for compatibility is only checked on init
         os.getenv = mock_os_getenv
-        self.runtime.telemetry_writer = TelemetryWriter(self.runtime.logger)
+        self.runtime.telemetry_writer = TelemetryWriter(self.runtime.logger, self.runtime.env_layer)
         self.action_handler.telemetry_writer = self.runtime.telemetry_writer
 
         self.assertTrue(self.action_handler.uninstall() == Constants.ExitCode.Okay)
 
         file_read = open(self.runtime.logger.file_logger.log_file_path, "r")
         self.assertTrue(file_read is not None)
-        self.assertTrue(Constants.TELEMETRY_AT_AGENT_NOT_COMPATIBLE_ERROR_MSG in file_read.read())
+        self.assertTrue(Constants.TELEMETRY_AT_AGENT_COMPATIBLE_MSG in file_read.read())
         file_read.close()
 
         with self.assertRaises(SystemExit) as sys_exit:

src/extension/tests/Test_TelemetryWriter.py

@@ -5,6 +5,7 @@
 import time
 import unittest
 from extension.src.Constants import Constants
+from extension.src.EnvLayer import EnvLayer
 from extension.src.TelemetryWriter import TelemetryWriter
 from extension.src.local_loggers.Logger import Logger
 from extension.tests.helpers.VirtualTerminal import VirtualTerminal
@@ -15,7 +16,8 @@ class TestTelemetryWriter(unittest.TestCase):
     def setUp(self):
         VirtualTerminal().print_lowlight("\n----------------- setup test runner -----------------")
         self.logger = Logger()
-        self.telemetry_writer = TelemetryWriter(self.logger)
+        self.env_layer = EnvLayer()
+        self.telemetry_writer = TelemetryWriter(self.logger, self.env_layer)
         self.telemetry_writer.events_folder_path = tempfile.mkdtemp()
 
     def tearDown(self):

src/extension/tests/helpers/RuntimeComposer.py

@@ -15,11 +15,11 @@ def __init__(self):
         self.backup_os_getenv = os.getenv
         os.getenv = self.getenv_telemetry_enabled
         self.logger = Logger()
-        self.telemetry_writer = TelemetryWriter(self.logger)
         self.utility = Utility(self.logger)
         self.json_file_handler = JsonFileHandler(self.logger)
         self.env_layer = EnvLayer()
         self.env_health_manager = EnvHealthManager(self.env_layer)
+        self.telemetry_writer = TelemetryWriter(self.logger, self.env_layer)
         time.sleep = self.mock_sleep
         self.env_layer.is_tty_required = self.mock_is_tty_required
         self.env_health_manager.check_sudo_status = self.mock_check_sudo_status