Adding status file for non enable commands and catching early errors (#…

…144)

* Adding status file for non enable commands and catching early errors

* Changes based on earlier discussions and adding UT coverage

* Addressing PR feedback

* Modifying exit code values acc to agent team's inputs

* Addressing PR comments

* Reverting a small change leftover from earlier iterations

src/extension/src/ActionHandler.py

@@ -48,6 +48,7 @@ def __init__(self, logger, env_layer, telemetry_writer, utility, runtime_context
         self.stdout_file_mirror = None
         self.file_logger = None
         self.operation_id_substitute_for_all_actions_in_telemetry = str((datetime.datetime.utcnow()).strftime(Constants.UTC_DATETIME_FORMAT))
+        self.seq_no = self.ext_config_settings_handler.get_seq_no_from_env_var()
 
     def determine_operation(self, command):
         switcher = {
@@ -64,32 +65,49 @@ def determine_operation(self, command):
             raise e
 
     def setup(self, action, log_message):
-        self.setup_file_logger(action)
-        self.setup_telemetry()
-        self.logger.log(log_message)
-        if action == Constants.ENABLE:
-            self.write_basic_status()
+        try:
+            self.setup_file_logger(action)
+            self.validate_sudo()  # Validating sudo as early as possible and before it's use in setup_telemetry
+            self.setup_telemetry()
+            self.logger.log(log_message)
+        except Exception:
+            raise
+        finally:
+            self.write_basic_status(action)
+
+    def validate_sudo(self):
+        # Disable tty for sudo access, if required
+        self.env_health_manager.ensure_tty_not_required()
+
+        # Ensure sudo works in the environment
+        sudo_check_result = self.env_health_manager.check_sudo_status()
+        self.logger.log_debug("Sudo status check: " + str(sudo_check_result) + "\n")
 
-    def write_basic_status(self):
+    def write_basic_status(self, action):
         """ Writes a basic status file if one for the same sequence number does not exist """
         try:
             # read seq no, if not found, log error and return, as this code opportunistically tries to write status file as early as possible
-            seq_no = self.ext_config_settings_handler.get_seq_no_from_env_var()
-            if seq_no is None:
+            if self.seq_no is None:
                 self.logger.log_error("Since sequence number for current operation was not found, handler could not write an initial/basic status file")
                 return
 
             # check if a status file for this sequence exists, if yes, do nothing
-            if not os.path.exists(os.path.join(self.ext_env_handler.status_folder, str(seq_no) + Constants.STATUS_FILE_EXTENSION)):
-                config_settings = self.ext_config_settings_handler.read_file(seq_no)
+            if os.path.exists(os.path.join(self.ext_env_handler.status_folder, str(self.seq_no) + Constants.STATUS_FILE_EXTENSION)):
+                return
+
+            # if status file for this sequence does not exist and enable is executed, read and use values from config setting file, else do not set those in status file
+            operation = ""
+            if action == Constants.ENABLE:
+                config_settings = self.ext_config_settings_handler.read_file(self.seq_no)
 
                 # set activity_id in telemetry
                 if self.telemetry_writer is not None:
                     self.telemetry_writer.set_operation_id(config_settings.__getattribute__(Constants.ConfigPublicSettingsFields.activity_id))
 
                 operation = config_settings.__getattribute__(Constants.ConfigPublicSettingsFields.operation)
-                # create status file with basic status
-                self.ext_output_status_handler.write_status_file(operation, seq_no)
+
+            # create status file with basic status
+            self.ext_output_status_handler.write_status_file(operation, self.seq_no)
 
         except Exception as error:
             self.logger.log_error("Exception occurred while writing basic status. [Exception={0}]".format(repr(error)))
@@ -159,10 +177,16 @@ def install(self):
         try:
             self.setup(action=Constants.INSTALL, log_message="Extension installation started")
             install_command_handler = InstallCommandHandler(self.logger, self.ext_env_handler)
-            return install_command_handler.execute_handler_action()
+            exit_code_from_executing_install = install_command_handler.execute_handler_action()
+            if exit_code_from_executing_install == Constants.ExitCode.Okay or exit_code_from_executing_install is None:
+                self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Success.lower())
+            else:
+                self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension install", code=exit_code_from_executing_install)
+            return exit_code_from_executing_install
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension install. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension install", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
 
         finally:
@@ -191,27 +215,34 @@ def update(self):
                 # Extension Update action called when
                 # a) artifacts for the preceding version do not exist on the machine, or
                 # b) after all artifacts from the preceding versions have been deleted
-                self.logger.log_error("No earlier versions for the extension found on the machine. So, could not copy any references to the current version.")
+                error_msg = "No earlier versions for the extension found on the machine. So, could not copy any references to the current version."
+                self.logger.log_error(error_msg)
+                self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message=error_msg, code=Constants.ExitCode.HandlerFailed)
                 return Constants.ExitCode.HandlerFailed
 
             # identify the version preceding current
             self.logger.log("Fetching the extension version preceding current from all available versions...")
             paths_to_all_versions.sort(reverse=True, key=LooseVersion)
             preceding_version_path = paths_to_all_versions[1]
             if preceding_version_path is None or preceding_version_path == "" or not os.path.exists(preceding_version_path):
-                self.logger.log_error("Could not find path where preceding extension version artifacts are stored. Hence, cannot copy the required artifacts to the latest version. "
-                                      "[Preceding extension version path={0}]".format(str(preceding_version_path)))
+                error_msg = "Could not find path where preceding extension version artifacts are stored. Hence, cannot copy the required artifacts to the latest version. "\
+                            "[Preceding extension version path={0}]".format(str(preceding_version_path))
+                self.logger.log_error(error_msg)
+                self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message=error_msg, code=Constants.ExitCode.HandlerFailed)
                 return Constants.ExitCode.HandlerFailed
+
             self.logger.log("Preceding version path. [Path={0}]".format(str(preceding_version_path)))
 
             # copy all required files from preceding version to current
             self.copy_config_files(preceding_version_path, new_version_config_folder)
 
             self.logger.log("All update actions from extension handler completed.")
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Success.lower())
             return Constants.ExitCode.Okay
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension update. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension update", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
 
         finally:
@@ -260,10 +291,12 @@ def copy_config_files(self, src, dst, raise_if_not_copied=False):
     def uninstall(self):
         try:
             self.setup(action=Constants.UNINSTALL, log_message="Extension uninstalled")
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Success.lower())
             return Constants.ExitCode.Okay
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension uninstall. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension uninstall", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
 
         finally:
@@ -273,10 +306,14 @@ def enable(self):
         try:
             self.setup(action=Constants.ENABLE, log_message="Enable triggered on extension")
             enable_command_handler = EnableCommandHandler(self.logger, self.telemetry_writer, self.utility, self.env_health_manager, self.runtime_context_handler, self.ext_env_handler, self.ext_config_settings_handler, self.core_state_handler, self.ext_state_handler, self.ext_output_status_handler, self.process_handler, self.cmd_exec_start_time)
-            return enable_command_handler.execute_handler_action()
+            exit_code_returned_from_executing_enable = enable_command_handler.execute_handler_action()
+            if exit_code_returned_from_executing_enable is not None and exit_code_returned_from_executing_enable != Constants.ExitCode.Okay:
+                self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension enable", code=exit_code_returned_from_executing_enable)
+            return Constants.ExitCode.Okay if exit_code_returned_from_executing_enable is None else exit_code_returned_from_executing_enable
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension enable. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension enable", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
         finally:
             self.tear_down()
@@ -306,10 +343,12 @@ def disable(self):
             # End of temporary auto-assessment disablement
 
             self.logger.log("Extension disabled successfully")
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Success.lower())
             return Constants.ExitCode.Okay
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension disable. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension disable", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
         finally:
             self.tear_down()
@@ -319,10 +358,12 @@ def reset(self):
             self.setup(action=Constants.RESET, log_message="Reset triggered on extension, deleting CoreState and ExtState files")
             self.utility.delete_file(self.core_state_handler.dir_path, self.core_state_handler.file, raise_if_not_found=False)
             self.utility.delete_file(self.ext_state_handler.dir_path, self.ext_state_handler.file, raise_if_not_found=False)
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Success.lower())
             return Constants.ExitCode.Okay
 
         except Exception as error:
             self.logger.log_error("Error occurred during extension reset. [Error={0}]".format(repr(error)))
+            self.ext_output_status_handler.write_status_file("", self.seq_no, status=Constants.Status.Error.lower(), message="Error occurred during extension reset", code=Constants.ExitCode.HandlerFailed)
             return Constants.ExitCode.HandlerFailed
         finally:
             self.tear_down()

src/extension/src/Constants.py

@@ -201,19 +201,19 @@ class Status(EnumBackport):
 
     class ExitCode(EnumBackport):
         Okay = 0
-        HandlerFailed = -1
-        MissingConfig = -2
-        BadConfig = -3
         UnsupportedOperatingSystem = 51
         MissingDependency = 52
         ConfigurationError = 53
-        BadHandlerEnvironmentFile = 3560
-        UnableToReadStatusFile = 3561
-        CreateFileLoggerFailure = 3562
-        ReadingAndDeserializingConfigFileFailure = 3563
-        InvalidConfigSettingPropertyValue = 3564
-        CreateLoggerFailure = 3565
-        CreateStatusWriterFailure = 3566
+        BadHandlerEnvironmentFile = 81
+        UnableToReadStatusFile = 82
+        CreateFileLoggerFailure = 83
+        ReadingAndDeserializingConfigFileFailure = 84
+        InvalidConfigSettingPropertyValue = 85
+        CreateLoggerFailure = 86
+        CreateStatusWriterFailure = 87
+        HandlerFailed = 88
+        MissingConfig = 89
+        OperationNotSupported = 90
 
     class AgentEnvVarStatusCode(EnumBackport):
         AGENT_ENABLED = "AGENT_ENABLED"

src/extension/src/EnableCommandHandler.py

@@ -41,13 +41,6 @@ def __init__(self, logger, telemetry_writer, utility, env_health_manager, runtim
     def execute_handler_action(self):
         """ Responsible for taking appropriate action for enable command as per the request sent in Handler Configuration file by user """
         try:
-            # Disable tty for sudo access, if required
-            self.env_health_manager.ensure_tty_not_required()
-
-            # Ensure sudo works in the environment
-            sudo_check_result = self.env_health_manager.check_sudo_status()
-            self.logger.log_debug("Sudo status check: " + str(sudo_check_result) + "\n")
-
             # fetch seq_no
             self.seq_no = self.ext_config_settings_handler.get_seq_no(is_enable_request=True)
             if self.seq_no is None:
@@ -68,7 +61,8 @@ def execute_handler_action(self):
             # Allow only certain operations
             if operation not in [Constants.NOOPERATION, Constants.ASSESSMENT, Constants.INSTALLATION, Constants.CONFIGURE_PATCHING]:
                 self.logger.log_error("Requested operation is not supported by the extension")
-                exit(Constants.ExitCode.InvalidConfigSettingPropertyValue)
+                self.ext_output_status_handler.write_status_file(operation, self.seq_no, status=Constants.Status.Error.lower(), message="Requested operation {0} is not supported by the extension".format(str(operation)), code=Constants.ExitCode.OperationNotSupported)
+                exit(Constants.ExitCode.OperationNotSupported)
 
             prev_patch_max_end_time = self.cmd_exec_start_time + datetime.timedelta(hours=0, minutes=Constants.ENABLE_MAX_RUNTIME)
             self.ext_state_handler.create_file(self.seq_no, operation, prev_patch_max_end_time)
@@ -125,7 +119,7 @@ def launch_new_process(self, config_settings, create_status_output_file):
         if create_status_output_file:
             self.ext_output_status_handler.write_status_file(config_settings.__getattribute__(self.config_public_settings.operation), self.seq_no, status=self.status.Transitioning.lower())
         else:
-            self.ext_output_status_handler.update_file(self.seq_no, self.ext_env_handler.status_folder)
+            self.ext_output_status_handler.update_file(self.seq_no)
         # launch core code in a process and exit extension handler
         process = self.process_handler.start_daemon(self.seq_no, config_settings, self.ext_env_handler)
         self.logger.log("exiting extension handler")

src/extension/src/__main__.py

@@ -41,6 +41,7 @@ def main(argv):
     logger = 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
+    exit_code = None
     try:
         # initializing action handler
         # args will have values install, uninstall, etc, as given in MsftLinuxPatchExtShim.sh in the operation var
@@ -62,19 +63,21 @@ def main(argv):
             ext_output_status_handler = ExtOutputStatusHandler(logger, utility, json_file_handler, ext_env_handler.status_folder)
             process_handler = ProcessHandler(logger, env_layer, ext_output_status_handler)
             action_handler = ActionHandler(logger, env_layer, telemetry_writer, utility, runtime_context_handler, json_file_handler, env_health_manager, ext_env_handler, ext_config_settings_handler, core_state_handler, ext_state_handler, ext_output_status_handler, process_handler, cmd_exec_start_time)
-            action_handler.determine_operation(argv[1])
+            exit_code_from_handler_actions = action_handler.determine_operation(argv[1])
+            exit_code = Constants.ExitCode.Okay if exit_code_from_handler_actions is None else exit_code_from_handler_actions
         else:
             error_cause = "No configuration provided in HandlerEnvironment" if ext_env_handler.handler_environment_json is None else "Path to config folder not specified in HandlerEnvironment"
             error_msg = "Error processing file. [File={0}] [Error={1}]".format(Constants.HANDLER_ENVIRONMENT_FILE, error_cause)
             raise Exception(error_msg)
     except Exception as error:
         logger.log_error(repr(error))
-        return Constants.ExitCode.HandlerFailed
+        exit_code = Constants.ExitCode.HandlerFailed
     finally:
         if stdout_file_mirror is not None:
             stdout_file_mirror.stop()
         if file_logger is not None:
             file_logger.close()
+    exit(exit_code)
 
 
 if __name__ == '__main__':