From ac90666c937645d45fb52522c80e10195a31a8d6 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Thu, 15 Dec 2022 18:37:20 +0530 Subject: [PATCH 01/15] Add logs to get time taken by assessment job and install updates job. Added relevant details in logs like patch service used (apt, yum or zypper), machine ram, machine cpu, OS details, etc. --- src/core/src/core_logic/PatchAssessor.py | 11 +++++++++++ src/core/src/core_logic/PatchInstaller.py | 11 +++++++++++ src/core/src/service_interfaces/TelemetryWriter.py | 6 ++++-- 3 files changed, 26 insertions(+), 2 deletions(-) diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 1ae8e545..a9934f7c 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -21,6 +21,7 @@ import shutil import time from core.src.bootstrap.Constants import Constants +from core.src.service_interfaces.TelemetryWriter import TelemetryWriter class PatchAssessor(object): @@ -49,6 +50,8 @@ def start_assessment(self): self.composite_logger.log('\nStarting patch assessment...') self.write_assessment_state() # success / failure does not matter, only that an attempt started + startTime = self.env_layer.datetime.datetime_utcnow() + self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_TRANSITIONING) self.composite_logger.log("\nMachine Id: " + self.env_layer.platform.node()) self.composite_logger.log("Activity Id: " + self.execution_config.activity_id) @@ -87,6 +90,14 @@ def start_assessment(self): self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_ERROR) raise + endTime = self.env_layer.datetime.datetime_utcnow() + patchService = self.package_manager.__class__.__name__ + machine_details = TelemetryWriter.machine_info + + assessmentDetails = {'job': "Assessment", 'startTime': str(startTime), 'endTime': str(endTime), + 'patchService': patchService, 'machineDetails': machine_details} + + self.composite_logger.log(str(assessmentDetails)) self.composite_logger.log("\nPatch assessment completed.\n") return True diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 23681f78..da68394b 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -19,6 +19,7 @@ import os import time from core.src.bootstrap.Constants import Constants +from core.src.service_interfaces.TelemetryWriter import TelemetryWriter class PatchInstaller(object): @@ -70,6 +71,7 @@ def start_installation(self, simulate=False): self.composite_logger.log_debug("Attempting to reboot the machine prior to patch installation as there is a reboot pending...") reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) + startTime = self.env_layer.datetime.datetime_utcnow() # Install Updates installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) @@ -88,6 +90,15 @@ def start_installation(self, simulate=False): self.composite_logger.log("\nInstalled update count: " + str(installed_update_count) + " (including dependencies)") + endTime = self.env_layer.datetime.datetime_utcnow() + patchService = self.package_manager.__class__.__name__ + machine_details = TelemetryWriter.machine_info + + InstallUpdatesDetails = {'job': "Install Updates", 'startTime': str(startTime), 'endTime': str(endTime), 'installed_update_count': str(installed_update_count), 'update_run_successful': str(update_run_successful), + 'maintenance_window': str(maintenance_window.duration), 'maintenance_window_exceeded': str(maintenance_window_exceeded), 'patchService': patchService, 'machineDetails': machine_details} + + self.composite_logger.log(str(InstallUpdatesDetails)) + # Reboot as per setting and environment state reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) maintenance_window_exceeded = maintenance_window_exceeded or reboot_manager.maintenance_window_exceeded_flag diff --git a/src/core/src/service_interfaces/TelemetryWriter.py b/src/core/src/service_interfaces/TelemetryWriter.py index a7fdcd52..3aa6dcbb 100644 --- a/src/core/src/service_interfaces/TelemetryWriter.py +++ b/src/core/src/service_interfaces/TelemetryWriter.py @@ -28,6 +28,8 @@ class TelemetryWriter(object): """Class for writing telemetry data to data transports""" + machine_info = "" + def __init__(self, env_layer, composite_logger, events_folder_path, telemetry_supported): self.env_layer = env_layer self.composite_logger = composite_logger @@ -75,14 +77,14 @@ def write_package_info(self, package_name, package_ver, package_size, install_du # Composed payload def write_machine_config_info(self): # Machine info - sent only once at the start of the run - machine_info = { + TelemetryWriter.machine_info = { 'platform_name': str(self.env_layer.platform.linux_distribution()[0]), 'platform_version': str(self.env_layer.platform.linux_distribution()[1]), 'machine_cpu': self.get_machine_processor(), 'machine_arch': str(self.env_layer.platform.machine()), 'disk_type': self.get_disk_type() } - return self.write_config_info(machine_info, 'machine_config') + return self.write_config_info(TelemetryWriter.machine_info, 'machine_config') def write_execution_error(self, cmd, code, output): # Expected to log any errors from a cmd execution, including package manager execution errors From df9c818a60f479fe6cb4f5852424837b83efd5e2 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 10 Jan 2023 20:18:37 +0530 Subject: [PATCH 02/15] Addressing PR comments. Some of the changes: (a) Creating separate class Stopwatch (b) Renaming variable names to be consistent (c) Renaming write_machine_config_info() to set_machine_config_info() as we are not logging machine_info in this function. (d) Creating constant for strings which are used in logs as they are referred multiple places. (e) Pre calculating time taken by task and percentage of maintenance window used instead of calculating them in kusto query. (f) Adding number_of_tries (for assessment) and number_of_rounds (for patch installation) (g) Removing import TelemetryWriter as it is already available in PatchAssessor and PatchInstaller --- src/core/src/bootstrap/Constants.py | 27 ++++++++++ src/core/src/core_logic/MaintenanceWindow.py | 20 +++++++ src/core/src/core_logic/PatchAssessor.py | 24 +++++---- src/core/src/core_logic/PatchInstaller.py | 34 +++++++----- src/core/src/core_logic/Stopwatch.py | 54 +++++++++++++++++++ .../src/service_interfaces/TelemetryWriter.py | 8 ++- 6 files changed, 140 insertions(+), 27 deletions(-) create mode 100644 src/core/src/core_logic/Stopwatch.py diff --git a/src/core/src/bootstrap/Constants.py b/src/core/src/bootstrap/Constants.py index f5750a6d..3d7ad9c1 100644 --- a/src/core/src/bootstrap/Constants.py +++ b/src/core/src/bootstrap/Constants.py @@ -98,6 +98,33 @@ class ConfigSettings(EnumBackport): # patch versions for healthstore when there is no maintenance run id PATCH_VERSION_UNKNOWN = "UNKNOWN" + # Strings used in perf logs + class LogStrings: + TASK = "task" + TASK_STATUS = "task_status" + ASSESSMENT = "Assessment" + PATCH_INSTALLATION = "PatchInstallation" + PACKAGE_MANAGER = "package_manager" + NUMBER_OF_TRIALS = "number_of_trials" + NUMBER_OF_ROUNDS = "number_of_rounds" + FAILED = "failed" + SUCCEEDED = "succeeded" + ERROR_MSG = "error_msg" + INSTALLED_UPDATE_COUNT = "installed_update_count" + UPDATE_RUN_SUCCESSFUL = "update_run_successful" + MAINTENANCE_WINDOW = "maintenance_window" + PERC_MAINTENANCE_WINDOW_USED = "perc_maintenance_window_used" + MAINTENANCE_WINDOW_EXCEEDED = "maintenance_window_exceeded" + START_TIME = "start_time" + END_TIME = "end_time" + TIME_TAKEN = "time_taken" + MACHINE_INFO = "machine_info" + MESSAGE = "message" + + # Stopwatch exception strings + STARTED_ALREADY = "Stopwatch is already started" + STOPPED_ALREADY = "Stopwatch is already stoppped" + # Patch Modes for Configure Patching class PatchModes(EnumBackport): IMAGE_DEFAULT = "ImageDefault" diff --git a/src/core/src/core_logic/MaintenanceWindow.py b/src/core/src/core_logic/MaintenanceWindow.py index 5daee268..d83751ca 100644 --- a/src/core/src/core_logic/MaintenanceWindow.py +++ b/src/core/src/core_logic/MaintenanceWindow.py @@ -71,3 +71,23 @@ def is_package_install_time_available(self, remaining_time_in_minutes=None): else: self.composite_logger.log_warning("Time Remaining: " + str(timedelta(seconds=int(remaining_time_in_minutes * 60))) + ", Cutoff time: " + str(timedelta(minutes=cutoff_time_in_minutes)) + " [Out of time!]") return False + + def get_percentage_maintenance_window_used(self): + """Calculate percentage of maintenance window used""" + try: + current_time = self.env_layer.datetime.datetime_utcnow() + start_time = self.env_layer.datetime.utc_to_standard_datetime(self.start_time) + dur = datetime.datetime.strptime(self.duration, "%H:%M:%S") + dura = timedelta(hours=dur.hour, minutes=dur.minute, seconds=dur.second) + total_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(dura) + elapsed_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(current_time - start_time) + percent_maintenance_window_used = (elapsed_time_in_minutes / total_time_in_minutes) * 100 + except ValueError as error: + error_msg = "Error calculating percentage of maintenance window used." + self.composite_logger.log_error("\n" + error_msg) + self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.DEFAULT_ERROR) + if Constants.ERROR_ADDED_TO_STATUS not in repr(error): + error.args = (error.args, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) + raise + + return percent_maintenance_window_used \ No newline at end of file diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index a9934f7c..291ac7b5 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -21,7 +21,7 @@ import shutil import time from core.src.bootstrap.Constants import Constants -from core.src.service_interfaces.TelemetryWriter import TelemetryWriter +from Stopwatch import Stopwatch class PatchAssessor(object): @@ -35,6 +35,7 @@ def __init__(self, env_layer, execution_config, composite_logger, telemetry_writ self.status_handler = status_handler self.lifecycle_manager = lifecycle_manager self.package_manager = package_manager + self.package_manager_name = self.package_manager.__class__.__name__ self.assessment_state_file_path = os.path.join(self.execution_config.config_folder, Constants.ASSESSMENT_STATE_FILE) def start_assessment(self): @@ -50,7 +51,8 @@ def start_assessment(self): self.composite_logger.log('\nStarting patch assessment...') self.write_assessment_state() # success / failure does not matter, only that an attempt started - startTime = self.env_layer.datetime.datetime_utcnow() + stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) + stopwatch.start() self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_TRANSITIONING) self.composite_logger.log("\nMachine Id: " + self.env_layer.platform.node()) @@ -60,11 +62,13 @@ def start_assessment(self): self.composite_logger.log("\n\nGetting available patches...") self.package_manager.refresh_repo() self.status_handler.reset_assessment_data() + number_of_tries = 0 for i in range(0, Constants.MAX_ASSESSMENT_RETRY_COUNT): try: if self.lifecycle_manager is not None: self.lifecycle_manager.lifecycle_status_check() # may terminate the code abruptly, as designed + number_of_tries = number_of_tries + 1 packages, package_versions = self.package_manager.get_all_updates() self.telemetry_writer.write_event("Full assessment: " + str(packages), Constants.TelemetryEventLevel.Verbose) self.status_handler.set_package_assessment_status(packages, package_versions) @@ -84,20 +88,20 @@ def start_assessment(self): else: error_msg = 'Error retrieving available patches: ' + repr(error) self.composite_logger.log_error(error_msg) + assessment_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: Constants.LogStrings.FAILED, + Constants.LogStrings.ERROR_MSG: error_msg} + stopwatch.stop_and_write_telemetry(str(self.assessment_perf_log)) self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.DEFAULT_ERROR) if Constants.ERROR_ADDED_TO_STATUS not in repr(error): error.args = (error.args, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_ERROR) raise - endTime = self.env_layer.datetime.datetime_utcnow() - patchService = self.package_manager.__class__.__name__ - machine_details = TelemetryWriter.machine_info - - assessmentDetails = {'job': "Assessment", 'startTime': str(startTime), 'endTime': str(endTime), - 'patchService': patchService, 'machineDetails': machine_details} - - self.composite_logger.log(str(assessmentDetails)) + assessment_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: Constants.LogStrings.SUCCEEDED, + Constants.LogStrings.ERROR_MSG: ""} + stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) self.composite_logger.log("\nPatch assessment completed.\n") return True diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index da68394b..2fa29a8f 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -20,7 +20,7 @@ import time from core.src.bootstrap.Constants import Constants from core.src.service_interfaces.TelemetryWriter import TelemetryWriter - +from Stopwatch import Stopwatch class PatchInstaller(object): """" Wrapper class for a single patch installation operation """ @@ -34,6 +34,7 @@ def __init__(self, env_layer, execution_config, composite_logger, telemetry_writ self.lifecycle_manager = lifecycle_manager self.package_manager = package_manager + self.package_manager_name = self.package_manager.__class__.__name__ self.package_filter = package_filter self.maintenance_window = maintenance_window self.reboot_manager = reboot_manager @@ -52,6 +53,9 @@ def start_installation(self, simulate=False): self.composite_logger.log('\nStarting patch installation...') + stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) + stopwatch.start() + self.composite_logger.log("\nMachine Id: " + self.env_layer.platform.node()) self.composite_logger.log("Activity Id: " + self.execution_config.activity_id) self.composite_logger.log("Operation request time: " + self.execution_config.start_time + ", Maintenance Window Duration: " + self.execution_config.duration) @@ -70,11 +74,10 @@ def start_installation(self, simulate=False): else: self.composite_logger.log_debug("Attempting to reboot the machine prior to patch installation as there is a reboot pending...") reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) - - startTime = self.env_layer.datetime.datetime_utcnow() + # Install Updates installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) - + number_of_rounds = 1 # Repeat patch installation if flagged as required and time is available if not maintenance_window_exceeded and package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): self.composite_logger.log("\nInstalled update count (first round): " + str(installed_update_count)) @@ -82,22 +85,29 @@ def start_installation(self, simulate=False): package_manager.set_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False) # Resetting new_installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) installed_update_count += new_installed_update_count + number_of_rounds = number_of_rounds + 1 if package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): # We should not see this again error_msg = "Unexpected repeated package manager update occurred. Please re-run the update deployment." self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE) + perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() + patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.PATCH_INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.UPDATE_RUN_SUCCESSFUL: str(update_run_successful), Constants.LogStrings.INSTALLED_UPDATE_COUNT: str(installed_update_count), + Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), + Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), + Constants.LogStrings.TASK_STATUS: Constants.LogStrings.FAILED, Constants.LogStrings.ERROR_MSG: error_msg} + stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.composite_logger.log("\nInstalled update count: " + str(installed_update_count) + " (including dependencies)") - endTime = self.env_layer.datetime.datetime_utcnow() - patchService = self.package_manager.__class__.__name__ - machine_details = TelemetryWriter.machine_info - - InstallUpdatesDetails = {'job': "Install Updates", 'startTime': str(startTime), 'endTime': str(endTime), 'installed_update_count': str(installed_update_count), 'update_run_successful': str(update_run_successful), - 'maintenance_window': str(maintenance_window.duration), 'maintenance_window_exceeded': str(maintenance_window_exceeded), 'patchService': patchService, 'machineDetails': machine_details} - - self.composite_logger.log(str(InstallUpdatesDetails)) + perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() + patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.PATCH_INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.UPDATE_RUN_SUCCESSFUL: str(update_run_successful), Constants.LogStrings.INSTALLED_UPDATE_COUNT: str(installed_update_count), + Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), + Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), + Constants.LogStrings.TASK_STATUS: Constants.LogStrings.SUCCEEDED, Constants.LogStrings.ERROR_MSG: ""} + stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) # Reboot as per setting and environment state reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py new file mode 100644 index 00000000..1ff953bd --- /dev/null +++ b/src/core/src/core_logic/Stopwatch.py @@ -0,0 +1,54 @@ +# Copyright 2023 Microsoft Corporation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +# Requires Python 2.7+ + +from core.src.bootstrap.Constants import Constants + +class Stopwatch(object): + """Implements the stopwatch logic""" + + def __init__(self, env_layer, telemetry_writer, composite_logger): + self.env_layer = env_layer + self.telemetry_writer = telemetry_writer + self.composite_logger = composite_logger + self.start_time = None + self.end_time = None + + def __del__(self): + # call stop only if end_time is None otherwise stop() is already called. + if (self.end_time == None): + self.stop() + self.task_details = {Constants.LogStrings.START_TIME: str(self.start_time), Constants.LogStrings.END_TIME: str(self.end_time), Constants.LogStrings.TIME_TAKEN: str(self.time_taken), + Constants.LogStrings.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.LogStrings.MESSAGE: ""} + self.composite_logger.log(str(self.task_details)) + + def start(self): + if (self.start_time != None): + raise Exception(Constants.STARTED_ALREADY) + self.start_time = self.env_layer.datetime.datetime_utcnow() + + def stop(self): + if (self.end_time != None): + raise Exception(Constants.STOPPED_ALREADY) + self.end_time = self.env_layer.datetime.datetime_utcnow() + self.time_taken = self.env_layer.datetime.total_minutes_from_time_delta(self.end_time - self.start_time) + + def stop_and_write_telemetry(self, message): + if (self.end_time != None): + raise Exception(Constants.STOPPED_ALREADY) + self.stop() + self.task_details = {Constants.LogStrings.START_TIME: str(self.start_time), Constants.LogStrings.END_TIME: str(self.end_time), Constants.LogStrings.TIME_TAKEN: str(self.time_taken), + Constants.LogStrings.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.LogStrings.MESSAGE: str(message)} + self.composite_logger.log(str(self.task_details)) \ No newline at end of file diff --git a/src/core/src/service_interfaces/TelemetryWriter.py b/src/core/src/service_interfaces/TelemetryWriter.py index 3aa6dcbb..37b50c8f 100644 --- a/src/core/src/service_interfaces/TelemetryWriter.py +++ b/src/core/src/service_interfaces/TelemetryWriter.py @@ -28,7 +28,6 @@ class TelemetryWriter(object): """Class for writing telemetry data to data transports""" - machine_info = "" def __init__(self, env_layer, composite_logger, events_folder_path, telemetry_supported): self.env_layer = env_layer @@ -47,7 +46,7 @@ def __init__(self, env_layer, composite_logger, events_folder_path, telemetry_su self.__is_telemetry_supported = telemetry_supported and self.events_folder_path is not None self.write_event('Started Linux patch core operation.', Constants.TelemetryEventLevel.Informational) - self.write_machine_config_info() + self.set_machine_config_info() def write_config_info(self, config_info, config_type='unknown'): # Configuration info @@ -75,16 +74,15 @@ def write_package_info(self, package_name, package_ver, package_size, install_du self.write_event(message, Constants.TelemetryEventLevel.Informational) # Composed payload - def write_machine_config_info(self): + def set_machine_config_info(self): # Machine info - sent only once at the start of the run - TelemetryWriter.machine_info = { + self.machine_info = { 'platform_name': str(self.env_layer.platform.linux_distribution()[0]), 'platform_version': str(self.env_layer.platform.linux_distribution()[1]), 'machine_cpu': self.get_machine_processor(), 'machine_arch': str(self.env_layer.platform.machine()), 'disk_type': self.get_disk_type() } - return self.write_config_info(TelemetryWriter.machine_info, 'machine_config') def write_execution_error(self, cmd, code, output): # Expected to log any errors from a cmd execution, including package manager execution errors From a247894454e089ba34f4ed3001035e7a015e21bc Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 10 Jan 2023 20:21:14 +0530 Subject: [PATCH 03/15] Removing import TelemetryWriter from PatchInstaller.py as telemetryWriter is already available --- src/core/src/core_logic/PatchInstaller.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 2fa29a8f..d4def193 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -19,7 +19,6 @@ import os import time from core.src.bootstrap.Constants import Constants -from core.src.service_interfaces.TelemetryWriter import TelemetryWriter from Stopwatch import Stopwatch class PatchInstaller(object): From 9e4b43d13d55445e64b1f1e92c7cc719e8173a0f Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 10 Jan 2023 20:24:13 +0530 Subject: [PATCH 04/15] Removing extra spaces --- src/core/src/core_logic/PatchInstaller.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index d4def193..8b32eb88 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -73,7 +73,7 @@ def start_installation(self, simulate=False): else: self.composite_logger.log_debug("Attempting to reboot the machine prior to patch installation as there is a reboot pending...") reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) - + # Install Updates installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) number_of_rounds = 1 From 5dd3a5f434cc3f15ec62f05e03c23a7d174b5f60 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Mon, 16 Jan 2023 15:30:47 +0530 Subject: [PATCH 05/15] Addressing PR comments: (a) Created new functions write_assessment_perf_logs and write_installer_perf_logs (b) As operation string are already there in Constants.py file, removing the newly added redundant strings. (c) Moved constant strings related to stopwatch to Stopwatch.py file as they are being used only in Stopwatch.py file. (d) Renamed constant strings to be consistent with nomenclature. Run -> Operation, update -> patch --- src/core/src/bootstrap/Constants.py | 10 ++------ src/core/src/core_logic/PatchAssessor.py | 20 +++++++-------- src/core/src/core_logic/PatchInstaller.py | 30 +++++++++++------------ src/core/src/core_logic/Stopwatch.py | 10 +++++--- 4 files changed, 33 insertions(+), 37 deletions(-) diff --git a/src/core/src/bootstrap/Constants.py b/src/core/src/bootstrap/Constants.py index 3d7ad9c1..7697ee2d 100644 --- a/src/core/src/bootstrap/Constants.py +++ b/src/core/src/bootstrap/Constants.py @@ -102,16 +102,14 @@ class ConfigSettings(EnumBackport): class LogStrings: TASK = "task" TASK_STATUS = "task_status" - ASSESSMENT = "Assessment" - PATCH_INSTALLATION = "PatchInstallation" PACKAGE_MANAGER = "package_manager" NUMBER_OF_TRIALS = "number_of_trials" NUMBER_OF_ROUNDS = "number_of_rounds" FAILED = "failed" SUCCEEDED = "succeeded" ERROR_MSG = "error_msg" - INSTALLED_UPDATE_COUNT = "installed_update_count" - UPDATE_RUN_SUCCESSFUL = "update_run_successful" + INSTALLED_PATCH_COUNT = "installed_patch_count" + PATCH_OPERATION_SUCCESSFUL = "patch_operation_successful" MAINTENANCE_WINDOW = "maintenance_window" PERC_MAINTENANCE_WINDOW_USED = "perc_maintenance_window_used" MAINTENANCE_WINDOW_EXCEEDED = "maintenance_window_exceeded" @@ -121,10 +119,6 @@ class LogStrings: MACHINE_INFO = "machine_info" MESSAGE = "message" - # Stopwatch exception strings - STARTED_ALREADY = "Stopwatch is already started" - STOPPED_ALREADY = "Stopwatch is already stoppped" - # Patch Modes for Configure Patching class PatchModes(EnumBackport): IMAGE_DEFAULT = "ImageDefault" diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 291ac7b5..652fe55f 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -51,8 +51,8 @@ def start_assessment(self): self.composite_logger.log('\nStarting patch assessment...') self.write_assessment_state() # success / failure does not matter, only that an attempt started - stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) - stopwatch.start() + self.stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) + self.stopwatch.start() self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_TRANSITIONING) self.composite_logger.log("\nMachine Id: " + self.env_layer.platform.node()) @@ -88,23 +88,23 @@ def start_assessment(self): else: error_msg = 'Error retrieving available patches: ' + repr(error) self.composite_logger.log_error(error_msg) - assessment_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: Constants.LogStrings.FAILED, - Constants.LogStrings.ERROR_MSG: error_msg} - stopwatch.stop_and_write_telemetry(str(self.assessment_perf_log)) + self.write_assessment_perf_logs(number_of_tries, Constants.LogStrings.FAILED, error_msg) self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.DEFAULT_ERROR) if Constants.ERROR_ADDED_TO_STATUS not in repr(error): error.args = (error.args, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_ERROR) raise - assessment_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: Constants.LogStrings.SUCCEEDED, - Constants.LogStrings.ERROR_MSG: ""} - stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) + self.write_assessment_perf_logs(number_of_tries, Constants.LogStrings.SUCCEEDED, "") self.composite_logger.log("\nPatch assessment completed.\n") return True + def write_assessment_perf_logs(self, number_of_tries, task_status, error_msg): + assessment_perf_log = {Constants.LogStrings.TASK: Constants.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: task_status, + Constants.LogStrings.ERROR_MSG: error_msg} + self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) + def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: self.composite_logger.log("Skipping telemetry compatibility check for Arc cloud type when operation is not manual") diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 8b32eb88..0580c997 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -52,8 +52,8 @@ def start_installation(self, simulate=False): self.composite_logger.log('\nStarting patch installation...') - stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) - stopwatch.start() + self.stopwatch = Stopwatch(self.env_layer, self.telemetry_writer, self.composite_logger) + self.stopwatch.start() self.composite_logger.log("\nMachine Id: " + self.env_layer.platform.node()) self.composite_logger.log("Activity Id: " + self.execution_config.activity_id) @@ -89,24 +89,12 @@ def start_installation(self, simulate=False): if package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): # We should not see this again error_msg = "Unexpected repeated package manager update occurred. Please re-run the update deployment." self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE) - perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() - patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.PATCH_INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.UPDATE_RUN_SUCCESSFUL: str(update_run_successful), Constants.LogStrings.INSTALLED_UPDATE_COUNT: str(installed_update_count), - Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), - Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), - Constants.LogStrings.TASK_STATUS: Constants.LogStrings.FAILED, Constants.LogStrings.ERROR_MSG: error_msg} - stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.LogStrings.FAILED, error_msg) raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.composite_logger.log("\nInstalled update count: " + str(installed_update_count) + " (including dependencies)") - perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() - patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.LogStrings.PATCH_INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.UPDATE_RUN_SUCCESSFUL: str(update_run_successful), Constants.LogStrings.INSTALLED_UPDATE_COUNT: str(installed_update_count), - Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), - Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), - Constants.LogStrings.TASK_STATUS: Constants.LogStrings.SUCCEEDED, Constants.LogStrings.ERROR_MSG: ""} - stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.LogStrings.SUCCEEDED, "") # Reboot as per setting and environment state reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) @@ -118,6 +106,16 @@ def start_installation(self, simulate=False): return overall_patch_installation_successful + def write_installer_perf_logs(self, patch_operation_successful, installed_patch_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, task_status, error_msg): + perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() + + patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, + Constants.LogStrings.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), Constants.LogStrings.INSTALLED_PATCH_COUNT: str(installed_patch_count), + Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), + Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), + Constants.LogStrings.TASK_STATUS: task_status, Constants.LogStrings.ERROR_MSG: error_msg} + self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: self.composite_logger.log("Skipping telemetry compatibility check for Arc cloud type when operation is not manual") diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py index 1ff953bd..631332c0 100644 --- a/src/core/src/core_logic/Stopwatch.py +++ b/src/core/src/core_logic/Stopwatch.py @@ -26,6 +26,10 @@ def __init__(self, env_layer, telemetry_writer, composite_logger): self.start_time = None self.end_time = None + # Stopwatch exception strings + self.STARTED_ALREADY = "Stopwatch is already started" + self.STOPPED_ALREADY = "Stopwatch is already stoppped" + def __del__(self): # call stop only if end_time is None otherwise stop() is already called. if (self.end_time == None): @@ -36,18 +40,18 @@ def __del__(self): def start(self): if (self.start_time != None): - raise Exception(Constants.STARTED_ALREADY) + raise Exception(self.STARTED_ALREADY) self.start_time = self.env_layer.datetime.datetime_utcnow() def stop(self): if (self.end_time != None): - raise Exception(Constants.STOPPED_ALREADY) + raise Exception(self.STOPPED_ALREADY) self.end_time = self.env_layer.datetime.datetime_utcnow() self.time_taken = self.env_layer.datetime.total_minutes_from_time_delta(self.end_time - self.start_time) def stop_and_write_telemetry(self, message): if (self.end_time != None): - raise Exception(Constants.STOPPED_ALREADY) + raise Exception(self.STOPPED_ALREADY) self.stop() self.task_details = {Constants.LogStrings.START_TIME: str(self.start_time), Constants.LogStrings.END_TIME: str(self.end_time), Constants.LogStrings.TIME_TAKEN: str(self.time_taken), Constants.LogStrings.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.LogStrings.MESSAGE: str(message)} From ca7669bb3c76ead92305751056abb9be46fd09f3 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Wed, 25 Jan 2023 11:57:47 +0530 Subject: [PATCH 06/15] Incorporated PR comments. Some of the major changes: (a) Added UTs (b) Created enum for task status (c) Updated class name in Constants file from LogStrings to PerfLogTrackerParams to be more specific on purpose of the class (d) Created new method set_task_details in Stopwatch for setting task details --- src/core/src/bootstrap/Constants.py | 9 +- src/core/src/core_logic/PatchAssessor.py | 12 +-- src/core/src/core_logic/PatchInstaller.py | 16 +-- src/core/src/core_logic/Stopwatch.py | 45 +++++---- src/core/tests/Test_MaintenanceWindow.py | 12 +++ src/core/tests/Test_PatchAssessor.py | 15 ++- src/core/tests/Test_PatchInstaller.py | 17 +++- src/core/tests/Test_Stopwatch.py | 117 ++++++++++++++++++++++ 8 files changed, 206 insertions(+), 37 deletions(-) create mode 100644 src/core/tests/Test_Stopwatch.py diff --git a/src/core/src/bootstrap/Constants.py b/src/core/src/bootstrap/Constants.py index 7697ee2d..058df45c 100644 --- a/src/core/src/bootstrap/Constants.py +++ b/src/core/src/bootstrap/Constants.py @@ -99,14 +99,11 @@ class ConfigSettings(EnumBackport): PATCH_VERSION_UNKNOWN = "UNKNOWN" # Strings used in perf logs - class LogStrings: + class PerfLogTrackerParams: TASK = "task" TASK_STATUS = "task_status" PACKAGE_MANAGER = "package_manager" NUMBER_OF_TRIALS = "number_of_trials" - NUMBER_OF_ROUNDS = "number_of_rounds" - FAILED = "failed" - SUCCEEDED = "succeeded" ERROR_MSG = "error_msg" INSTALLED_PATCH_COUNT = "installed_patch_count" PATCH_OPERATION_SUCCESSFUL = "patch_operation_successful" @@ -119,6 +116,10 @@ class LogStrings: MACHINE_INFO = "machine_info" MESSAGE = "message" + class TaskStatus(EnumBackport): + SUCCEEDED = "succeeded" + FAILED = "failed" + # Patch Modes for Configure Patching class PatchModes(EnumBackport): IMAGE_DEFAULT = "ImageDefault" diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 652fe55f..7f047f8c 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -21,7 +21,7 @@ import shutil import time from core.src.bootstrap.Constants import Constants -from Stopwatch import Stopwatch +from core.src.core_logic.Stopwatch import Stopwatch class PatchAssessor(object): @@ -88,21 +88,21 @@ def start_assessment(self): else: error_msg = 'Error retrieving available patches: ' + repr(error) self.composite_logger.log_error(error_msg) - self.write_assessment_perf_logs(number_of_tries, Constants.LogStrings.FAILED, error_msg) + self.write_assessment_perf_logs(number_of_tries, Constants.TaskStatus.FAILED, error_msg) self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.DEFAULT_ERROR) if Constants.ERROR_ADDED_TO_STATUS not in repr(error): error.args = (error.args, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.status_handler.set_assessment_substatus_json(status=Constants.STATUS_ERROR) raise - self.write_assessment_perf_logs(number_of_tries, Constants.LogStrings.SUCCEEDED, "") + self.write_assessment_perf_logs(number_of_tries, Constants.TaskStatus.SUCCEEDED, "") self.composite_logger.log("\nPatch assessment completed.\n") return True def write_assessment_perf_logs(self, number_of_tries, task_status, error_msg): - assessment_perf_log = {Constants.LogStrings.TASK: Constants.ASSESSMENT, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.NUMBER_OF_TRIALS: str(number_of_tries), Constants.LogStrings.TASK_STATUS: task_status, - Constants.LogStrings.ERROR_MSG: error_msg} + assessment_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.ASSESSMENT, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), + Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, + Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) def raise_if_telemetry_unsupported(self): diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 0580c997..19dbdaad 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -19,7 +19,7 @@ import os import time from core.src.bootstrap.Constants import Constants -from Stopwatch import Stopwatch +from core.src.core_logic.Stopwatch import Stopwatch class PatchInstaller(object): """" Wrapper class for a single patch installation operation """ @@ -89,12 +89,12 @@ def start_installation(self, simulate=False): if package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): # We should not see this again error_msg = "Unexpected repeated package manager update occurred. Please re-run the update deployment." self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE) - self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.LogStrings.FAILED, error_msg) + self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.FAILED, error_msg) raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.composite_logger.log("\nInstalled update count: " + str(installed_update_count) + " (including dependencies)") - self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.LogStrings.SUCCEEDED, "") + self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.SUCCEEDED, "") # Reboot as per setting and environment state reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) @@ -109,11 +109,11 @@ def start_installation(self, simulate=False): def write_installer_perf_logs(self, patch_operation_successful, installed_patch_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, task_status, error_msg): perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() - patch_installation_perf_log = {Constants.LogStrings.TASK: Constants.INSTALLATION, Constants.LogStrings.PACKAGE_MANAGER: self.package_manager_name, - Constants.LogStrings.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), Constants.LogStrings.INSTALLED_PATCH_COUNT: str(installed_patch_count), - Constants.LogStrings.NUMBER_OF_ROUNDS: str(number_of_rounds), Constants.LogStrings.MAINTENANCE_WINDOW: str(maintenance_window.duration), - Constants.LogStrings.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), Constants.LogStrings.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded), - Constants.LogStrings.TASK_STATUS: task_status, Constants.LogStrings.ERROR_MSG: error_msg} + patch_installation_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.INSTALLATION, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, + Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, Constants.PerfLogTrackerParams.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), + Constants.PerfLogTrackerParams.INSTALLED_PATCH_COUNT: str(installed_patch_count), Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_rounds), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW: str(maintenance_window.duration), Constants.PerfLogTrackerParams.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) def raise_if_telemetry_unsupported(self): diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py index 631332c0..5873c5dc 100644 --- a/src/core/src/core_logic/Stopwatch.py +++ b/src/core/src/core_logic/Stopwatch.py @@ -16,43 +16,54 @@ from core.src.bootstrap.Constants import Constants + class Stopwatch(object): """Implements the stopwatch logic""" + # Stopwatch exception strings + STARTED_ALREADY = "Stopwatch is already started" + NOT_STARTED = "Stopwatch is not started" + STOPPED_ALREADY = "Stopwatch is already stoppped" + def __init__(self, env_layer, telemetry_writer, composite_logger): self.env_layer = env_layer self.telemetry_writer = telemetry_writer self.composite_logger = composite_logger self.start_time = None self.end_time = None - - # Stopwatch exception strings - self.STARTED_ALREADY = "Stopwatch is already started" - self.STOPPED_ALREADY = "Stopwatch is already stoppped" + self.time_taken = None + self.task_details = None def __del__(self): + # if start_time is None that means Stopwatch is not started and hence no need to log # call stop only if end_time is None otherwise stop() is already called. - if (self.end_time == None): + if self.start_time is not None and self.end_time is None: self.stop() - self.task_details = {Constants.LogStrings.START_TIME: str(self.start_time), Constants.LogStrings.END_TIME: str(self.end_time), Constants.LogStrings.TIME_TAKEN: str(self.time_taken), - Constants.LogStrings.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.LogStrings.MESSAGE: ""} - self.composite_logger.log(str(self.task_details)) + self.set_task_details("") + self.composite_logger.log("Stopwatch details before instance is destroyed: " + str(self.task_details)) def start(self): - if (self.start_time != None): - raise Exception(self.STARTED_ALREADY) + if self.start_time is not None: + raise Exception(Stopwatch.STARTED_ALREADY) self.start_time = self.env_layer.datetime.datetime_utcnow() def stop(self): - if (self.end_time != None): - raise Exception(self.STOPPED_ALREADY) + if self.start_time is None: + raise Exception(Stopwatch.NOT_STARTED) + if self.end_time is not None: + raise Exception(Stopwatch.STOPPED_ALREADY) self.end_time = self.env_layer.datetime.datetime_utcnow() self.time_taken = self.env_layer.datetime.total_minutes_from_time_delta(self.end_time - self.start_time) def stop_and_write_telemetry(self, message): - if (self.end_time != None): - raise Exception(self.STOPPED_ALREADY) + if self.start_time is None: + raise Exception(Stopwatch.NOT_STARTED) + if self.end_time is not None: + raise Exception(Stopwatch.STOPPED_ALREADY) self.stop() - self.task_details = {Constants.LogStrings.START_TIME: str(self.start_time), Constants.LogStrings.END_TIME: str(self.end_time), Constants.LogStrings.TIME_TAKEN: str(self.time_taken), - Constants.LogStrings.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.LogStrings.MESSAGE: str(message)} - self.composite_logger.log(str(self.task_details)) \ No newline at end of file + self.set_task_details(message) + self.composite_logger.log("Stopwatch details: " + str(self.task_details)) + + def set_task_details(self, message): + self.task_details = {Constants.PerfLogTrackerParams.START_TIME: str(self.start_time), Constants.PerfLogTrackerParams.END_TIME: str(self.end_time), Constants.PerfLogTrackerParams.TIME_TAKEN: str(self.time_taken), + Constants.PerfLogTrackerParams.MACHINE_INFO: self.telemetry_writer.machine_info, Constants.PerfLogTrackerParams.MESSAGE: str(message)} \ No newline at end of file diff --git a/src/core/tests/Test_MaintenanceWindow.py b/src/core/tests/Test_MaintenanceWindow.py index a871c960..c46e836f 100644 --- a/src/core/tests/Test_MaintenanceWindow.py +++ b/src/core/tests/Test_MaintenanceWindow.py @@ -79,5 +79,17 @@ def test_check_available_time_after_duration_complete(self): self.assertEqual(runtime.maintenance_window.is_package_install_time_available(), False) runtime.stop() + def test_get_percentage_maintenance_window_used(self): + argument_composer = ArgumentComposer() + argument_composer.start_time = (datetime.datetime.utcnow() - datetime.timedelta(hours=0, minutes=18)).strftime("%Y-%m-%dT%H:%M:%S.9999Z") + argument_composer.maximum_duration = "PT3H" + runtime = RuntimeCompositor(argument_composer.get_composed_arguments(), True) + perc_maintenance_window_used = runtime.maintenance_window.get_percentage_maintenance_window_used() + # 18 minutes of maintenance window used out of 3 hours (180 minutes). So, it should be 10%. + # The value should be slightly greater than 10 as it takes some time to trigger the method get_percentage_maintenance_window_used + self.assertGreaterEqual(perc_maintenance_window_used, 10) + self.assertLessEqual(perc_maintenance_window_used, 11) + runtime.stop() + if __name__ == '__main__': unittest.main() diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index 9b2daa94..a9c6f8b0 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -22,7 +22,7 @@ from core.src.service_interfaces.TelemetryWriter import TelemetryWriter from core.tests.library.ArgumentComposer import ArgumentComposer from core.tests.library.RuntimeCompositor import RuntimeCompositor - +from core.src.core_logic.Stopwatch import Stopwatch class TestPatchAssessor(unittest.TestCase): def setUp(self): @@ -147,6 +147,19 @@ def test_convert_iso8601_duration_to_total_seconds(self): self.assertRaises(Exception, lambda: self.runtime.patch_assessor.convert_iso8601_duration_to_total_seconds('6H5M14S')) self.assertRaises(Exception, lambda: self.runtime.patch_assessor.convert_iso8601_duration_to_total_seconds('')) + def test_write_assessment_perf_logs(self): + self.runtime.patch_assessor.stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time is None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is None) + self.runtime.patch_assessor.stopwatch.start() + self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time is not None) + self.runtime.patch_assessor.write_assessment_perf_logs(1, Constants.TaskStatus.SUCCEEDED, "") + self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is not None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is not None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is not None) + def raise_ex(self): raise Exception() diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index 47858f9f..5210c330 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -20,7 +20,7 @@ from core.src.bootstrap.Constants import Constants from core.tests.library.ArgumentComposer import ArgumentComposer from core.tests.library.RuntimeCompositor import RuntimeCompositor - +from core.src.core_logic.Stopwatch import Stopwatch class TestPatchInstaller(unittest.TestCase): def setUp(self): @@ -240,6 +240,21 @@ def test_raise_if_telemetry_unsupported(self): runtime.patch_installer.raise_if_telemetry_unsupported() runtime.stop() + def test_write_installer_perf_logs(self): + runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) + runtime.patch_installer.stopwatch = Stopwatch(runtime.env_layer, runtime.telemetry_writer, runtime.composite_logger) + self.assertTrue(runtime.patch_installer.stopwatch.start_time is None) + self.assertTrue(runtime.patch_installer.stopwatch.end_time is None) + self.assertTrue(runtime.patch_installer.stopwatch.time_taken is None) + self.assertTrue(runtime.patch_installer.stopwatch.task_details is None) + runtime.patch_installer.stopwatch.start() + self.assertTrue(runtime.patch_installer.stopwatch.start_time is not None) + runtime.patch_installer.write_installer_perf_logs(True, 10, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") + self.assertTrue(runtime.patch_installer.stopwatch.end_time is not None) + self.assertTrue(runtime.patch_installer.stopwatch.time_taken is not None) + self.assertTrue(runtime.patch_installer.stopwatch.task_details is not None) + runtime.stop() + if __name__ == '__main__': unittest.main() diff --git a/src/core/tests/Test_Stopwatch.py b/src/core/tests/Test_Stopwatch.py new file mode 100644 index 00000000..40baec93 --- /dev/null +++ b/src/core/tests/Test_Stopwatch.py @@ -0,0 +1,117 @@ +# Copyright 2023 Microsoft Corporation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +# Requires Python 2.7+ + +import unittest + +from core.tests.library.ArgumentComposer import ArgumentComposer +from core.tests.library.RuntimeCompositor import RuntimeCompositor +from core.src.core_logic.Stopwatch import Stopwatch + + +class TestStopwatch(unittest.TestCase): + def setUp(self): + self.runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) + self.container = self.runtime.container + + def tearDown(self): + self.runtime.stop() + + def test_start(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertTrue(stopwatch.start_time is None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.start() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + + def test_stop(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertTrue(stopwatch.start_time is None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.start() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.stop() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is not None) + self.assertTrue(stopwatch.time_taken is not None) + self.assertTrue(stopwatch.task_details is None) + + def test_stop_and_write_telemetry(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertTrue(stopwatch.start_time is None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.start() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.stop_and_write_telemetry("test") + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is not None) + self.assertTrue(stopwatch.time_taken is not None) + self.assertTrue(stopwatch.task_details is not None) + + def test_set_task_details(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertTrue(stopwatch.start_time is None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.start() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.stop() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.end_time is not None) + self.assertTrue(stopwatch.time_taken is not None) + self.assertTrue(stopwatch.task_details is None) + stopwatch.set_task_details("test") + self.assertTrue(stopwatch.task_details is not None) + + # test start Stopwatch twice + def test_started_already_exception(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + stopwatch.start() + self.assertRaises(Exception, stopwatch.start) + + # test stop Stopwatch when it was never started + def test_not_started_exception(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertRaises(Exception, stopwatch.stop) + + # test stop Stopwatch twice + def test_stopped_already_exception(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + stopwatch.start() + stopwatch.stop() + self.assertRaises(Exception, stopwatch.stop) + + +if __name__ == '__main__': + unittest.main() From 75f27c3f6f7f17fe5d7c917c67795ca2302ef49e Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 31 Jan 2023 22:36:58 +0530 Subject: [PATCH 07/15] Incorporated the comments. Some of the changes done are: (a) In function get_percentage_maintenance_window_used in MaintenanceWindow.py, catching more generic exception instead of ValueError. If duration is 0 then there can be ZeroDivideError which is not caught by Value Error. (b) Wrote a test case for above (c) Updated variable name number_of_rounds to retry_count (d) Created Enum for exception strings in Stopwatch.py (e) Added some more tests for PatchAssessor, PatchInstaller and Stopwatch --- src/core/src/core_logic/MaintenanceWindow.py | 2 +- src/core/src/core_logic/PatchInstaller.py | 8 +++---- src/core/src/core_logic/Stopwatch.py | 20 ++++++++-------- src/core/tests/Test_MaintenanceWindow.py | 8 +++++++ src/core/tests/Test_PatchAssessor.py | 25 ++++++++++++++------ src/core/tests/Test_PatchInstaller.py | 24 +++++++++++++------ src/core/tests/Test_Stopwatch.py | 12 ++++++++++ 7 files changed, 70 insertions(+), 29 deletions(-) diff --git a/src/core/src/core_logic/MaintenanceWindow.py b/src/core/src/core_logic/MaintenanceWindow.py index d83751ca..563d4ad9 100644 --- a/src/core/src/core_logic/MaintenanceWindow.py +++ b/src/core/src/core_logic/MaintenanceWindow.py @@ -82,7 +82,7 @@ def get_percentage_maintenance_window_used(self): total_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(dura) elapsed_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(current_time - start_time) percent_maintenance_window_used = (elapsed_time_in_minutes / total_time_in_minutes) * 100 - except ValueError as error: + except Exception as error: error_msg = "Error calculating percentage of maintenance window used." self.composite_logger.log_error("\n" + error_msg) self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.DEFAULT_ERROR) diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 19dbdaad..c5df83e0 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -76,7 +76,7 @@ def start_installation(self, simulate=False): # Install Updates installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) - number_of_rounds = 1 + retry_count = 1 # Repeat patch installation if flagged as required and time is available if not maintenance_window_exceeded and package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): self.composite_logger.log("\nInstalled update count (first round): " + str(installed_update_count)) @@ -84,17 +84,17 @@ def start_installation(self, simulate=False): package_manager.set_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False) # Resetting new_installed_update_count, update_run_successful, maintenance_window_exceeded = self.install_updates(maintenance_window, package_manager, simulate) installed_update_count += new_installed_update_count - number_of_rounds = number_of_rounds + 1 + retry_count = retry_count + 1 if package_manager.get_package_manager_setting(Constants.PACKAGE_MGR_SETTING_REPEAT_PATCH_OPERATION, False): # We should not see this again error_msg = "Unexpected repeated package manager update occurred. Please re-run the update deployment." self.status_handler.add_error_to_status(error_msg, Constants.PatchOperationErrorCodes.PACKAGE_MANAGER_FAILURE) - self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.FAILED, error_msg) + self.write_installer_perf_logs(update_run_successful, installed_update_count, retry_count, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.FAILED, error_msg) raise Exception(error_msg, "[{0}]".format(Constants.ERROR_ADDED_TO_STATUS)) self.composite_logger.log("\nInstalled update count: " + str(installed_update_count) + " (including dependencies)") - self.write_installer_perf_logs(update_run_successful, installed_update_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.SUCCEEDED, "") + self.write_installer_perf_logs(update_run_successful, installed_update_count, retry_count, maintenance_window, maintenance_window_exceeded, Constants.TaskStatus.SUCCEEDED, "") # Reboot as per setting and environment state reboot_manager.start_reboot_if_required_and_time_available(maintenance_window.get_remaining_time_in_minutes(None, False)) diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py index 5873c5dc..adf14b8c 100644 --- a/src/core/src/core_logic/Stopwatch.py +++ b/src/core/src/core_logic/Stopwatch.py @@ -16,14 +16,14 @@ from core.src.bootstrap.Constants import Constants - class Stopwatch(object): """Implements the stopwatch logic""" - # Stopwatch exception strings - STARTED_ALREADY = "Stopwatch is already started" - NOT_STARTED = "Stopwatch is not started" - STOPPED_ALREADY = "Stopwatch is already stoppped" + class StopwatchException(Constants.EnumBackport): + # Stopwatch exception strings + STARTED_ALREADY = "Stopwatch is already started" + NOT_STARTED = "Stopwatch is not started" + STOPPED_ALREADY = "Stopwatch is already stoppped" def __init__(self, env_layer, telemetry_writer, composite_logger): self.env_layer = env_layer @@ -44,22 +44,22 @@ def __del__(self): def start(self): if self.start_time is not None: - raise Exception(Stopwatch.STARTED_ALREADY) + raise Exception(str(Stopwatch.StopwatchException.STARTED_ALREADY)) self.start_time = self.env_layer.datetime.datetime_utcnow() def stop(self): if self.start_time is None: - raise Exception(Stopwatch.NOT_STARTED) + raise Exception(str(Stopwatch.StopwatchException.NOT_STARTED)) if self.end_time is not None: - raise Exception(Stopwatch.STOPPED_ALREADY) + raise Exception(str(Stopwatch.StopwatchException.STOPPED_ALREADY)) self.end_time = self.env_layer.datetime.datetime_utcnow() self.time_taken = self.env_layer.datetime.total_minutes_from_time_delta(self.end_time - self.start_time) def stop_and_write_telemetry(self, message): if self.start_time is None: - raise Exception(Stopwatch.NOT_STARTED) + raise Exception(str(Stopwatch.StopwatchException.NOT_STARTED)) if self.end_time is not None: - raise Exception(Stopwatch.STOPPED_ALREADY) + raise Exception(str(Stopwatch.StopwatchException.STOPPED_ALREADY)) self.stop() self.set_task_details(message) self.composite_logger.log("Stopwatch details: " + str(self.task_details)) diff --git a/src/core/tests/Test_MaintenanceWindow.py b/src/core/tests/Test_MaintenanceWindow.py index c46e836f..7b5b7006 100644 --- a/src/core/tests/Test_MaintenanceWindow.py +++ b/src/core/tests/Test_MaintenanceWindow.py @@ -91,5 +91,13 @@ def test_get_percentage_maintenance_window_used(self): self.assertLessEqual(perc_maintenance_window_used, 11) runtime.stop() + def test_get_percentage_maintenance_window_used_Fail(self): + argument_composer = ArgumentComposer() + # ZeroDivisionError should be thrown as duration is 0 + argument_composer.maximum_duration = "PT0H" + runtime = RuntimeCompositor(argument_composer.get_composed_arguments(), True) + self.assertRaises(Exception, runtime.maintenance_window.get_percentage_maintenance_window_used) + runtime.stop() + if __name__ == '__main__': unittest.main() diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index a9c6f8b0..0f831a8d 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -148,17 +148,28 @@ def test_convert_iso8601_duration_to_total_seconds(self): self.assertRaises(Exception, lambda: self.runtime.patch_assessor.convert_iso8601_duration_to_total_seconds('')) def test_write_assessment_perf_logs(self): - self.runtime.patch_assessor.stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) - self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time is None) - self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is None) - self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is None) - self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is None) - self.runtime.patch_assessor.stopwatch.start() + self.runtime.patch_assessor.start_assessment() self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time is not None) - self.runtime.patch_assessor.write_assessment_perf_logs(1, Constants.TaskStatus.SUCCEEDED, "") self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is not None) self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is not None) self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is not None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time < self.runtime.patch_assessor.stopwatch.end_time) + self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken > 0) + task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.ASSESSMENT)) + self.assertTrue(task_info in str(self.runtime.patch_assessor.stopwatch.task_details)) + task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) + self.assertTrue(task_status in str(self.runtime.patch_assessor.stopwatch.task_details)) + err_msg = "'{}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) + self.assertTrue(err_msg in str(self.runtime.patch_assessor.stopwatch.task_details)) + + + def test_stopwatch_properties_assessment_fail(self): + self.runtime.set_legacy_test_type('UnalignedPath') + self.assertRaises(Exception, self.runtime.patch_assessor.start_assessment) + self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time is not None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is None) + self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is None) def raise_ex(self): raise Exception() diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index 5210c330..1d37ac37 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -242,19 +242,29 @@ def test_raise_if_telemetry_unsupported(self): def test_write_installer_perf_logs(self): runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) - runtime.patch_installer.stopwatch = Stopwatch(runtime.env_layer, runtime.telemetry_writer, runtime.composite_logger) - self.assertTrue(runtime.patch_installer.stopwatch.start_time is None) - self.assertTrue(runtime.patch_installer.stopwatch.end_time is None) - self.assertTrue(runtime.patch_installer.stopwatch.time_taken is None) - self.assertTrue(runtime.patch_installer.stopwatch.task_details is None) - runtime.patch_installer.stopwatch.start() + runtime.patch_installer.start_installation(simulate=True) self.assertTrue(runtime.patch_installer.stopwatch.start_time is not None) - runtime.patch_installer.write_installer_perf_logs(True, 10, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") self.assertTrue(runtime.patch_installer.stopwatch.end_time is not None) self.assertTrue(runtime.patch_installer.stopwatch.time_taken is not None) self.assertTrue(runtime.patch_installer.stopwatch.task_details is not None) + self.assertTrue(runtime.patch_installer.stopwatch.start_time < runtime.patch_installer.stopwatch.end_time) + self.assertTrue(runtime.patch_installer.stopwatch.time_taken > 0) + task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.INSTALLATION)) + self.assertTrue(task_info in str(runtime.patch_installer.stopwatch.task_details)) + task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) + self.assertTrue(task_status in str(runtime.patch_installer.stopwatch.task_details)) + err_msg = "'{}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) + self.assertTrue(err_msg in str(runtime.patch_installer.stopwatch.task_details)) runtime.stop() + def test_stopwatch_properties_patch_install_fail(self): + runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) + runtime.set_legacy_test_type('FailInstallPath') + self.assertRaises(Exception, runtime.patch_installer.start_installation) + self.assertTrue(runtime.patch_installer.stopwatch.start_time is not None) + self.assertTrue(runtime.patch_installer.stopwatch.end_time is None) + self.assertTrue(runtime.patch_installer.stopwatch.time_taken is None) + self.assertTrue(runtime.patch_installer.stopwatch.task_details is None) if __name__ == '__main__': unittest.main() diff --git a/src/core/tests/Test_Stopwatch.py b/src/core/tests/Test_Stopwatch.py index 40baec93..e3fd3c00 100644 --- a/src/core/tests/Test_Stopwatch.py +++ b/src/core/tests/Test_Stopwatch.py @@ -112,6 +112,18 @@ def test_stopped_already_exception(self): stopwatch.stop() self.assertRaises(Exception, stopwatch.stop) + # test stop_and_write_telemetry when Stopwatch was never started + def test_stop_and_write_telemetry_not_started_exception(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + self.assertRaises(Exception, stopwatch.stop_and_write_telemetry, "") + + # test stop_and_write_telemetry when Stopwatch was already stopped + def test_stop_and_write_telemetry_stopped_already_exception(self): + stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) + stopwatch.start() + stopwatch.stop_and_write_telemetry("") + self.assertRaises(Exception, stopwatch.stop_and_write_telemetry, "") + if __name__ == '__main__': unittest.main() From efaa90da8066ccbd9c5aedc321ab598030d1059d Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 31 Jan 2023 23:01:35 +0530 Subject: [PATCH 08/15] Incorporating comments. Setting end_time, time_taken and task_details to None for start() in stopwatch so that same stopwatch can be reused Throwing exception if start_time is greater than current_time in get_percentage_maintenance_window_used --- src/core/src/core_logic/MaintenanceWindow.py | 2 ++ src/core/src/core_logic/Stopwatch.py | 3 +++ src/core/tests/Test_MaintenanceWindow.py | 8 ++++++++ 3 files changed, 13 insertions(+) diff --git a/src/core/src/core_logic/MaintenanceWindow.py b/src/core/src/core_logic/MaintenanceWindow.py index 563d4ad9..31c32824 100644 --- a/src/core/src/core_logic/MaintenanceWindow.py +++ b/src/core/src/core_logic/MaintenanceWindow.py @@ -77,6 +77,8 @@ def get_percentage_maintenance_window_used(self): try: current_time = self.env_layer.datetime.datetime_utcnow() start_time = self.env_layer.datetime.utc_to_standard_datetime(self.start_time) + if current_time < start_time: + raise Exception("Start time {} is greater than current time {}".format(str(start_time), str(current_time))) dur = datetime.datetime.strptime(self.duration, "%H:%M:%S") dura = timedelta(hours=dur.hour, minutes=dur.minute, seconds=dur.second) total_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(dura) diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py index adf14b8c..84595697 100644 --- a/src/core/src/core_logic/Stopwatch.py +++ b/src/core/src/core_logic/Stopwatch.py @@ -46,6 +46,9 @@ def start(self): if self.start_time is not None: raise Exception(str(Stopwatch.StopwatchException.STARTED_ALREADY)) self.start_time = self.env_layer.datetime.datetime_utcnow() + self.end_time = None + self.time_taken = None + self.task_details = None def stop(self): if self.start_time is None: diff --git a/src/core/tests/Test_MaintenanceWindow.py b/src/core/tests/Test_MaintenanceWindow.py index 7b5b7006..793a6bb9 100644 --- a/src/core/tests/Test_MaintenanceWindow.py +++ b/src/core/tests/Test_MaintenanceWindow.py @@ -99,5 +99,13 @@ def test_get_percentage_maintenance_window_used_Fail(self): self.assertRaises(Exception, runtime.maintenance_window.get_percentage_maintenance_window_used) runtime.stop() + def test_get_percentage_maintenance_window_used_start_time_greater_exception(self): + argument_composer = ArgumentComposer() + # Setting start time 1 hour later than current time + argument_composer.start_time = (datetime.datetime.utcnow() + datetime.timedelta(hours=1)).strftime("%Y-%m-%dT%H:%M:%S.9999Z") + runtime = RuntimeCompositor(argument_composer.get_composed_arguments(), True) + self.assertRaises(Exception, runtime.maintenance_window.get_percentage_maintenance_window_used) + runtime.stop() + if __name__ == '__main__': unittest.main() From 42fe28321400afbb7763f1477850e0040dd419e8 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 31 Jan 2023 23:05:24 +0530 Subject: [PATCH 09/15] Thow error if total_time_in_minutes is 0 in get_percentage_maintenance_window_used --- src/core/src/core_logic/MaintenanceWindow.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/core/src/core_logic/MaintenanceWindow.py b/src/core/src/core_logic/MaintenanceWindow.py index 31c32824..1745405d 100644 --- a/src/core/src/core_logic/MaintenanceWindow.py +++ b/src/core/src/core_logic/MaintenanceWindow.py @@ -82,6 +82,8 @@ def get_percentage_maintenance_window_used(self): dur = datetime.datetime.strptime(self.duration, "%H:%M:%S") dura = timedelta(hours=dur.hour, minutes=dur.minute, seconds=dur.second) total_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(dura) + if total_time_in_minutes == 0: + raise Exception("Total time in minutes is 0") elapsed_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(current_time - start_time) percent_maintenance_window_used = (elapsed_time_in_minutes / total_time_in_minutes) * 100 except Exception as error: From fdaf8f3bc86d566a7662acf50c70b96a9a22a29b Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Thu, 2 Feb 2023 08:30:05 +0530 Subject: [PATCH 10/15] The test test_write_assessment_perf_logs is succeeding when ran locally on pycharm but the same test fails when ran in Codecov in Github. Might be start_time and end_time are same when ran in Codecov in Github due to speed of test run would be very fast. The unit of time measured is in microseconds. So, if difference of start_time and end_time is less than 1 microsecond then start_time and end_time would be same. --- src/core/tests/Test_PatchAssessor.py | 4 ++-- src/core/tests/Test_PatchInstaller.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index 0f831a8d..4a63ec8f 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -153,8 +153,8 @@ def test_write_assessment_perf_logs(self): self.assertTrue(self.runtime.patch_assessor.stopwatch.end_time is not None) self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is not None) self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is not None) - self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time < self.runtime.patch_assessor.stopwatch.end_time) - self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken > 0) + self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time <= self.runtime.patch_assessor.stopwatch.end_time) + self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken >= 0) task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.ASSESSMENT)) self.assertTrue(task_info in str(self.runtime.patch_assessor.stopwatch.task_details)) task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index 1d37ac37..bfd46155 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -247,8 +247,8 @@ def test_write_installer_perf_logs(self): self.assertTrue(runtime.patch_installer.stopwatch.end_time is not None) self.assertTrue(runtime.patch_installer.stopwatch.time_taken is not None) self.assertTrue(runtime.patch_installer.stopwatch.task_details is not None) - self.assertTrue(runtime.patch_installer.stopwatch.start_time < runtime.patch_installer.stopwatch.end_time) - self.assertTrue(runtime.patch_installer.stopwatch.time_taken > 0) + self.assertTrue(runtime.patch_installer.stopwatch.start_time <= runtime.patch_installer.stopwatch.end_time) + self.assertTrue(runtime.patch_installer.stopwatch.time_taken >= 0) task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.INSTALLATION)) self.assertTrue(task_info in str(runtime.patch_installer.stopwatch.task_details)) task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) From e404b8ef351dfef734d25d0b03add5679b783855 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Fri, 3 Feb 2023 13:11:44 +0530 Subject: [PATCH 11/15] Incorporated PR comments. (a) Using numbered index placeholder (b) Do not explicitly throw exception if total_time_in_minutes == 0 in get_percentage_maintenance_window_used --- src/core/src/core_logic/MaintenanceWindow.py | 4 +--- src/core/tests/Test_PatchAssessor.py | 6 +++--- src/core/tests/Test_PatchInstaller.py | 6 +++--- 3 files changed, 7 insertions(+), 9 deletions(-) diff --git a/src/core/src/core_logic/MaintenanceWindow.py b/src/core/src/core_logic/MaintenanceWindow.py index 1745405d..da2ffa39 100644 --- a/src/core/src/core_logic/MaintenanceWindow.py +++ b/src/core/src/core_logic/MaintenanceWindow.py @@ -78,12 +78,10 @@ def get_percentage_maintenance_window_used(self): current_time = self.env_layer.datetime.datetime_utcnow() start_time = self.env_layer.datetime.utc_to_standard_datetime(self.start_time) if current_time < start_time: - raise Exception("Start time {} is greater than current time {}".format(str(start_time), str(current_time))) + raise Exception("Start time {0} is greater than current time {1}".format(str(start_time), str(current_time))) dur = datetime.datetime.strptime(self.duration, "%H:%M:%S") dura = timedelta(hours=dur.hour, minutes=dur.minute, seconds=dur.second) total_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(dura) - if total_time_in_minutes == 0: - raise Exception("Total time in minutes is 0") elapsed_time_in_minutes = self.env_layer.datetime.total_minutes_from_time_delta(current_time - start_time) percent_maintenance_window_used = (elapsed_time_in_minutes / total_time_in_minutes) * 100 except Exception as error: diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index 4a63ec8f..6d2ede9c 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -155,11 +155,11 @@ def test_write_assessment_perf_logs(self): self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is not None) self.assertTrue(self.runtime.patch_assessor.stopwatch.start_time <= self.runtime.patch_assessor.stopwatch.end_time) self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken >= 0) - task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.ASSESSMENT)) + task_info = "'{0}': '{1}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.ASSESSMENT)) self.assertTrue(task_info in str(self.runtime.patch_assessor.stopwatch.task_details)) - task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) + task_status = "'{0}': '{1}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) self.assertTrue(task_status in str(self.runtime.patch_assessor.stopwatch.task_details)) - err_msg = "'{}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) + err_msg = "'{0}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) self.assertTrue(err_msg in str(self.runtime.patch_assessor.stopwatch.task_details)) diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index bfd46155..1b611c23 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -249,11 +249,11 @@ def test_write_installer_perf_logs(self): self.assertTrue(runtime.patch_installer.stopwatch.task_details is not None) self.assertTrue(runtime.patch_installer.stopwatch.start_time <= runtime.patch_installer.stopwatch.end_time) self.assertTrue(runtime.patch_installer.stopwatch.time_taken >= 0) - task_info = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.INSTALLATION)) + task_info = "'{0}': '{1}'".format(str(Constants.PerfLogTrackerParams.TASK), str(Constants.INSTALLATION)) self.assertTrue(task_info in str(runtime.patch_installer.stopwatch.task_details)) - task_status = "'{}': '{}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) + task_status = "'{0}': '{1}'".format(str(Constants.PerfLogTrackerParams.TASK_STATUS), str(Constants.TaskStatus.SUCCEEDED)) self.assertTrue(task_status in str(runtime.patch_installer.stopwatch.task_details)) - err_msg = "'{}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) + err_msg = "'{0}': ''".format(str(Constants.PerfLogTrackerParams.ERROR_MSG)) self.assertTrue(err_msg in str(runtime.patch_installer.stopwatch.task_details)) runtime.stop() From a285b43702ad8ebe6bdf0f7bd80645bab2173ca0 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 7 Feb 2023 10:22:40 +0530 Subject: [PATCH 12/15] Swallow exception if any raised during writing performance logs. We don't want script to stop abruptly just due to some exception in writing performance logs. --- src/core/src/core_logic/PatchAssessor.py | 11 +++++++---- src/core/src/core_logic/PatchInstaller.py | 19 +++++++++++-------- 2 files changed, 18 insertions(+), 12 deletions(-) diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 7f047f8c..35de18d5 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -100,10 +100,13 @@ def start_assessment(self): return True def write_assessment_perf_logs(self, number_of_tries, task_status, error_msg): - assessment_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.ASSESSMENT, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), - Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, - Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} - self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) + try: + assessment_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.ASSESSMENT, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), + Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, + Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} + self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) + except Exception as error: + self.composite_logger.log_warning("Error in writing assessment performance logs. Error is: " + repr(error)) def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index c5df83e0..89967613 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -107,14 +107,17 @@ def start_installation(self, simulate=False): return overall_patch_installation_successful def write_installer_perf_logs(self, patch_operation_successful, installed_patch_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, task_status, error_msg): - perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() - - patch_installation_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.INSTALLATION, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, - Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, Constants.PerfLogTrackerParams.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), - Constants.PerfLogTrackerParams.INSTALLED_PATCH_COUNT: str(installed_patch_count), Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_rounds), - Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW: str(maintenance_window.duration), Constants.PerfLogTrackerParams.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), - Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} - self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + try: + perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() + + patch_installation_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.INSTALLATION, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, + Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, Constants.PerfLogTrackerParams.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), + Constants.PerfLogTrackerParams.INSTALLED_PATCH_COUNT: str(installed_patch_count), Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_rounds), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW: str(maintenance_window.duration), Constants.PerfLogTrackerParams.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} + self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + except Exception as error: + self.composite_logger.log_warning("Error in writing patch installation performance logs. Error is: " + repr(error)) def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: From 342afd1d68521fe68dbc659836adfed030bf2c0c Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Wed, 8 Feb 2023 13:26:14 +0530 Subject: [PATCH 13/15] (a) Do not throw exception in stopwatch. Add logs. (b) Add test cases --- src/core/src/core_logic/PatchAssessor.py | 2 +- src/core/src/core_logic/PatchInstaller.py | 2 +- src/core/src/core_logic/Stopwatch.py | 14 ++++---- src/core/tests/Test_PatchAssessor.py | 5 +++ src/core/tests/Test_PatchInstaller.py | 9 +++++ src/core/tests/Test_Stopwatch.py | 43 ++++++++++++++--------- 6 files changed, 48 insertions(+), 27 deletions(-) diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 35de18d5..5210f537 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -106,7 +106,7 @@ def write_assessment_perf_logs(self, number_of_tries, task_status, error_msg): Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) except Exception as error: - self.composite_logger.log_warning("Error in writing assessment performance logs. Error is: " + repr(error)) + self.composite_logger.log_debug("Error in writing assessment performance logs. Error is: " + repr(error)) def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 89967613..7bc8d13f 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -117,7 +117,7 @@ def write_installer_perf_logs(self, patch_operation_successful, installed_patch_ Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) except Exception as error: - self.composite_logger.log_warning("Error in writing patch installation performance logs. Error is: " + repr(error)) + self.composite_logger.log_debug("Error in writing patch installation performance logs. Error is: " + repr(error)) def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: diff --git a/src/core/src/core_logic/Stopwatch.py b/src/core/src/core_logic/Stopwatch.py index 84595697..def811f7 100644 --- a/src/core/src/core_logic/Stopwatch.py +++ b/src/core/src/core_logic/Stopwatch.py @@ -44,25 +44,23 @@ def __del__(self): def start(self): if self.start_time is not None: - raise Exception(str(Stopwatch.StopwatchException.STARTED_ALREADY)) + self.composite_logger.log_debug(str(Stopwatch.StopwatchException.STARTED_ALREADY)) self.start_time = self.env_layer.datetime.datetime_utcnow() self.end_time = None self.time_taken = None self.task_details = None def stop(self): - if self.start_time is None: - raise Exception(str(Stopwatch.StopwatchException.NOT_STARTED)) if self.end_time is not None: - raise Exception(str(Stopwatch.StopwatchException.STOPPED_ALREADY)) + self.composite_logger.log_debug(str(Stopwatch.StopwatchException.STOPPED_ALREADY)) self.end_time = self.env_layer.datetime.datetime_utcnow() + if self.start_time is None: + self.composite_logger.log_debug(str(Stopwatch.StopwatchException.NOT_STARTED)) + self.start_time = self.end_time + self.time_taken = self.env_layer.datetime.total_minutes_from_time_delta(self.end_time - self.start_time) def stop_and_write_telemetry(self, message): - if self.start_time is None: - raise Exception(str(Stopwatch.StopwatchException.NOT_STARTED)) - if self.end_time is not None: - raise Exception(str(Stopwatch.StopwatchException.STOPPED_ALREADY)) self.stop() self.set_task_details(message) self.composite_logger.log("Stopwatch details: " + str(self.task_details)) diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index 6d2ede9c..a2efa8fb 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -171,6 +171,11 @@ def test_stopwatch_properties_assessment_fail(self): self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is None) self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is None) + def test_write_assessment_perf_logs_catch_exception(self): + # Testing the catch Exception in the method write_assessment_perf_logs + # Exception should be thrown because stop_and_write_telemetry method is called without initializing stopwatch object + self.runtime.patch_assessor.write_assessment_perf_logs(1, Constants.TaskStatus.SUCCEEDED, "") + def raise_ex(self): raise Exception() diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index 1b611c23..5f30dfed 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -265,6 +265,15 @@ def test_stopwatch_properties_patch_install_fail(self): self.assertTrue(runtime.patch_installer.stopwatch.end_time is None) self.assertTrue(runtime.patch_installer.stopwatch.time_taken is None) self.assertTrue(runtime.patch_installer.stopwatch.task_details is None) + runtime.stop() + + def test_write_installer_perf_logs_catch_exception(self): + # Testing the catch Exception in the method write_installer_perf_logs + # Exception should be thrown because stop_and_write_telemetry method is called without initializing stopwatch object + runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) + runtime.patch_installer.write_installer_perf_logs(True, 1, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") + runtime.stop() + if __name__ == '__main__': unittest.main() diff --git a/src/core/tests/Test_Stopwatch.py b/src/core/tests/Test_Stopwatch.py index e3fd3c00..14acf0c5 100644 --- a/src/core/tests/Test_Stopwatch.py +++ b/src/core/tests/Test_Stopwatch.py @@ -95,34 +95,43 @@ def test_set_task_details(self): self.assertTrue(stopwatch.task_details is not None) # test start Stopwatch twice - def test_started_already_exception(self): + def test_started_already(self): stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) stopwatch.start() - self.assertRaises(Exception, stopwatch.start) + start1 = stopwatch.start_time + stopwatch.start() + start2 = stopwatch.start_time + self.assertTrue(start1 <= start2) + self.assertTrue(stopwatch.end_time is None) + self.assertTrue(stopwatch.time_taken is None) + self.assertTrue(stopwatch.task_details is None) # test stop Stopwatch when it was never started - def test_not_started_exception(self): + def test_not_started(self): stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) - self.assertRaises(Exception, stopwatch.stop) + stopwatch.stop() + self.assertTrue(stopwatch.start_time is not None) + self.assertTrue(stopwatch.start_time == stopwatch.end_time) + self.assertTrue(stopwatch.time_taken == 0) + self.assertTrue(stopwatch.task_details is None) # test stop Stopwatch twice - def test_stopped_already_exception(self): + def test_stopped_already(self): stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) stopwatch.start() stopwatch.stop() - self.assertRaises(Exception, stopwatch.stop) - - # test stop_and_write_telemetry when Stopwatch was never started - def test_stop_and_write_telemetry_not_started_exception(self): - stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) - self.assertRaises(Exception, stopwatch.stop_and_write_telemetry, "") + start_time1 = stopwatch.start_time + end_time1 = stopwatch.end_time + time_taken1 = stopwatch.time_taken + stopwatch.stop() + start_time2 = stopwatch.start_time + end_time2 = stopwatch.end_time + time_taken2 = stopwatch.time_taken + self.assertTrue(start_time1 == start_time2) + self.assertTrue(end_time1 <= end_time2) + self.assertTrue(time_taken1 <= time_taken2) + - # test stop_and_write_telemetry when Stopwatch was already stopped - def test_stop_and_write_telemetry_stopped_already_exception(self): - stopwatch = Stopwatch(self.runtime.env_layer, self.runtime.telemetry_writer, self.runtime.composite_logger) - stopwatch.start() - stopwatch.stop_and_write_telemetry("") - self.assertRaises(Exception, stopwatch.stop_and_write_telemetry, "") if __name__ == '__main__': From 99298c094dbff4a009d340095a523bb9b3dd7905 Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 14 Feb 2023 15:14:03 +0530 Subject: [PATCH 14/15] Removing catch exception in PatchAssessor and PatchInstaller where stopwatch functions are called as now there are no exceptions thrown in stopwatch functions --- src/core/src/core_logic/PatchAssessor.py | 11 ++++------- src/core/src/core_logic/PatchInstaller.py | 16 +++++++++------- src/core/tests/Test_PatchAssessor.py | 5 ----- src/core/tests/Test_PatchInstaller.py | 2 +- 4 files changed, 14 insertions(+), 20 deletions(-) diff --git a/src/core/src/core_logic/PatchAssessor.py b/src/core/src/core_logic/PatchAssessor.py index 5210f537..7f047f8c 100644 --- a/src/core/src/core_logic/PatchAssessor.py +++ b/src/core/src/core_logic/PatchAssessor.py @@ -100,13 +100,10 @@ def start_assessment(self): return True def write_assessment_perf_logs(self, number_of_tries, task_status, error_msg): - try: - assessment_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.ASSESSMENT, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), - Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, - Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} - self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) - except Exception as error: - self.composite_logger.log_debug("Error in writing assessment performance logs. Error is: " + repr(error)) + assessment_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.ASSESSMENT, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), + Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, + Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_tries)} + self.stopwatch.stop_and_write_telemetry(str(assessment_perf_log)) def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: diff --git a/src/core/src/core_logic/PatchInstaller.py b/src/core/src/core_logic/PatchInstaller.py index 7bc8d13f..11e56cca 100644 --- a/src/core/src/core_logic/PatchInstaller.py +++ b/src/core/src/core_logic/PatchInstaller.py @@ -107,18 +107,20 @@ def start_installation(self, simulate=False): return overall_patch_installation_successful def write_installer_perf_logs(self, patch_operation_successful, installed_patch_count, number_of_rounds, maintenance_window, maintenance_window_exceeded, task_status, error_msg): + perc_maintenance_window_used = -1 + try: perc_maintenance_window_used = maintenance_window.get_percentage_maintenance_window_used() - - patch_installation_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.INSTALLATION, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, - Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, Constants.PerfLogTrackerParams.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), - Constants.PerfLogTrackerParams.INSTALLED_PATCH_COUNT: str(installed_patch_count), Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_rounds), - Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW: str(maintenance_window.duration), Constants.PerfLogTrackerParams.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), - Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} - self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) except Exception as error: self.composite_logger.log_debug("Error in writing patch installation performance logs. Error is: " + repr(error)) + patch_installation_perf_log = {Constants.PerfLogTrackerParams.TASK: Constants.INSTALLATION, Constants.PerfLogTrackerParams.TASK_STATUS: str(task_status), Constants.PerfLogTrackerParams.ERROR_MSG: error_msg, + Constants.PerfLogTrackerParams.PACKAGE_MANAGER: self.package_manager_name, Constants.PerfLogTrackerParams.PATCH_OPERATION_SUCCESSFUL: str(patch_operation_successful), + Constants.PerfLogTrackerParams.INSTALLED_PATCH_COUNT: str(installed_patch_count), Constants.PerfLogTrackerParams.NUMBER_OF_TRIALS: str(number_of_rounds), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW: str(maintenance_window.duration), Constants.PerfLogTrackerParams.PERC_MAINTENANCE_WINDOW_USED: str(perc_maintenance_window_used), + Constants.PerfLogTrackerParams.MAINTENANCE_WINDOW_EXCEEDED: str(maintenance_window_exceeded)} + self.stopwatch.stop_and_write_telemetry(str(patch_installation_perf_log)) + def raise_if_telemetry_unsupported(self): if self.lifecycle_manager.get_vm_cloud_type() == Constants.VMCloudType.ARC and self.execution_config.operation not in [Constants.ASSESSMENT, Constants.INSTALLATION]: self.composite_logger.log("Skipping telemetry compatibility check for Arc cloud type when operation is not manual") diff --git a/src/core/tests/Test_PatchAssessor.py b/src/core/tests/Test_PatchAssessor.py index a2efa8fb..6d2ede9c 100644 --- a/src/core/tests/Test_PatchAssessor.py +++ b/src/core/tests/Test_PatchAssessor.py @@ -171,11 +171,6 @@ def test_stopwatch_properties_assessment_fail(self): self.assertTrue(self.runtime.patch_assessor.stopwatch.time_taken is None) self.assertTrue(self.runtime.patch_assessor.stopwatch.task_details is None) - def test_write_assessment_perf_logs_catch_exception(self): - # Testing the catch Exception in the method write_assessment_perf_logs - # Exception should be thrown because stop_and_write_telemetry method is called without initializing stopwatch object - self.runtime.patch_assessor.write_assessment_perf_logs(1, Constants.TaskStatus.SUCCEEDED, "") - def raise_ex(self): raise Exception() diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index 5f30dfed..d157988e 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -271,7 +271,7 @@ def test_write_installer_perf_logs_catch_exception(self): # Testing the catch Exception in the method write_installer_perf_logs # Exception should be thrown because stop_and_write_telemetry method is called without initializing stopwatch object runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) - runtime.patch_installer.write_installer_perf_logs(True, 1, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") + self.assertRaises(Exception, runtime.patch_installer.write_installer_perf_logs, True, 1, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") runtime.stop() From 6ca8ce04493734cb661d32ad98850374e813c57f Mon Sep 17 00:00:00 2001 From: Gaurav Ramrakhyani Date: Tue, 14 Feb 2023 15:30:04 +0530 Subject: [PATCH 15/15] Covering test for catch exception in the write_installer_perf_logs method --- src/core/tests/Test_PatchInstaller.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/core/tests/Test_PatchInstaller.py b/src/core/tests/Test_PatchInstaller.py index d157988e..d134026c 100644 --- a/src/core/tests/Test_PatchInstaller.py +++ b/src/core/tests/Test_PatchInstaller.py @@ -269,8 +269,11 @@ def test_stopwatch_properties_patch_install_fail(self): def test_write_installer_perf_logs_catch_exception(self): # Testing the catch Exception in the method write_installer_perf_logs - # Exception should be thrown because stop_and_write_telemetry method is called without initializing stopwatch object - runtime = RuntimeCompositor(ArgumentComposer().get_composed_arguments(), legacy_mode=True) + # ZeroDivisionError Exception should be thrown by the function get_percentage_maintenance_window_used because denominator will be zero if maximum_duration is zero + # This will cover the catch exception code but another exception will be thrown later due to calling stop_and_write_telemetry without initializing stopwatch + argument_composer = ArgumentComposer() + argument_composer.maximum_duration = "PT0H" + runtime = RuntimeCompositor(argument_composer.get_composed_arguments(), legacy_mode=True) self.assertRaises(Exception, runtime.patch_installer.write_installer_perf_logs, True, 1, 1, runtime.maintenance_window, False, Constants.TaskStatus.SUCCEEDED, "") runtime.stop()