[generic-config-updater] Adding logging to config-{replace, rollback, checkpoint, list-checkpoints} (sonic-net#1885)

#### What I did
Adding more logging to other CLI commands `config replace`, `config rollback`, `config checkpoint`, `config list-checkpoints` and `config delete-checkpoint`

Author: ghooo

generic_config_updater/generic_updater.py

@@ -29,118 +29,170 @@ def __init__(self,
                  changeapplier=None,
                  config_wrapper=None,
                  patch_wrapper=None):
-        self.logger = genericUpdaterLogging.get_logger(title="Patch Applier")
+        self.logger = genericUpdaterLogging.get_logger(title="Patch Applier", print_all_to_console=True)
         self.config_wrapper = config_wrapper if config_wrapper is not None else ConfigWrapper()
         self.patch_wrapper = patch_wrapper if patch_wrapper is not None else PatchWrapper()
         self.patchsorter = patchsorter if patchsorter is not None else PatchSorter(self.config_wrapper, self.patch_wrapper)
         self.changeapplier = changeapplier if changeapplier is not None else ChangeApplier()
 
     def apply(self, patch):
-        print_to_console=True
-        self.logger.log_notice("Patch application starting.", print_to_console)
-        self.logger.log_notice(f"Patch: {patch}", print_to_console)
+        self.logger.log_notice("Patch application starting.")
+        self.logger.log_notice(f"Patch: {patch}")
 
         # validate patch is only updating tables with yang models
-        self.logger.log_notice("Validating patch is not making changes to tables without YANG models.", print_to_console)
+        self.logger.log_notice("Validating patch is not making changes to tables without YANG models.")
         if not(self.patch_wrapper.validate_config_db_patch_has_yang_models(patch)):
             raise ValueError(f"Given patch is not valid because it has changes to tables without YANG models")
 
         # Get old config
-        self.logger.log_notice("Getting current config db.", print_to_console)
+        self.logger.log_notice("Getting current config db.")
         old_config = self.config_wrapper.get_config_db_as_json()
 
         # Generate target config
-        self.logger.log_notice("Simulating the target full config after applying the patch.", print_to_console)
+        self.logger.log_notice("Simulating the target full config after applying the patch.")
         target_config = self.patch_wrapper.simulate_patch(patch, old_config)
 
         # Validate target config
-        self.logger.log_notice("Validating target config according to YANG models.", print_to_console)
+        self.logger.log_notice("Validating target config according to YANG models.")
         if not(self.config_wrapper.validate_config_db_config(target_config)):
             raise ValueError(f"Given patch is not valid because it will result in an invalid config")
 
         # Generate list of changes to apply
-        self.logger.log_notice("Sorting patch updates.", print_to_console)
+        self.logger.log_notice("Sorting patch updates.")
         changes = self.patchsorter.sort(patch)
         changes_len = len(changes)
         self.logger.log_notice(f"The patch was sorted into {changes_len} " \
-                             f"change{'s' if changes_len != 1 else ''}{':' if changes_len > 0 else '.'}",
-                             print_to_console)
+                             f"change{'s' if changes_len != 1 else ''}{':' if changes_len > 0 else '.'}")
         for change in changes:
-            self.logger.log_notice(f"  * {change}", print_to_console)
+            self.logger.log_notice(f"  * {change}")
 
         # Apply changes in order
-        self.logger.log_notice("Applying changes in order.", print_to_console)
+        self.logger.log_notice("Applying changes in order.")
         for change in changes:
             self.changeapplier.apply(change)
 
         # Validate config updated successfully
-        self.logger.log_notice("Verifying patch updates are reflected on ConfigDB.", print_to_console)
+        self.logger.log_notice("Verifying patch updates are reflected on ConfigDB.")
         new_config = self.config_wrapper.get_config_db_as_json()
         if not(self.patch_wrapper.verify_same_json(target_config, new_config)):
             raise GenericConfigUpdaterError(f"After applying patch to config, there are still some parts not updated")
 
-        self.logger.log_notice("Patch application completed.", print_to_console)
+        self.logger.log_notice("Patch application completed.")
 
 class ConfigReplacer:
     def __init__(self, patch_applier=None, config_wrapper=None, patch_wrapper=None):
+        self.logger = genericUpdaterLogging.get_logger(title="Config Replacer", print_all_to_console=True)
         self.patch_applier = patch_applier if patch_applier is not None else PatchApplier()
         self.config_wrapper = config_wrapper if config_wrapper is not None else ConfigWrapper()
         self.patch_wrapper = patch_wrapper if patch_wrapper is not None else PatchWrapper()
 
     def replace(self, target_config):
+        self.logger.log_notice("Config replacement starting.")
+        self.logger.log_notice(f"Target config length: {len(json.dumps(target_config))}.")
+
+        self.logger.log_notice("Validating target config according to YANG models.")
         if not(self.config_wrapper.validate_config_db_config(target_config)):
             raise ValueError(f"The given target config is not valid")
 
+        self.logger.log_notice("Getting current config db.")
         old_config = self.config_wrapper.get_config_db_as_json()
+
+        self.logger.log_notice("Generating patch between target config and current config db.")
         patch = self.patch_wrapper.generate_patch(old_config, target_config)
+        self.logger.log_debug(f"Generated patch: {patch}.") # debug since the patch will printed again in 'patch_applier.apply'
 
+        self.logger.log_notice("Applying patch using 'Patch Applier'.")
         self.patch_applier.apply(patch)
 
+        self.logger.log_notice("Verifying config replacement is reflected on ConfigDB.")
         new_config = self.config_wrapper.get_config_db_as_json()
         if not(self.patch_wrapper.verify_same_json(target_config, new_config)):
             raise GenericConfigUpdaterError(f"After replacing config, there is still some parts not updated")
 
+        self.logger.log_notice("Config replacement completed.")
+
 class FileSystemConfigRollbacker:
     def __init__(self,
                  checkpoints_dir=CHECKPOINTS_DIR,
                  config_replacer=None,
                  config_wrapper=None):
+        self.logger = genericUpdaterLogging.get_logger(title="Config Rollbacker", print_all_to_console=True)
         self.checkpoints_dir = checkpoints_dir
         self.config_replacer = config_replacer if config_replacer is not None else ConfigReplacer()
         self.config_wrapper = config_wrapper if config_wrapper is not None else ConfigWrapper()
 
     def rollback(self, checkpoint_name):
+        self.logger.log_notice("Config rollbacking starting.")
+        self.logger.log_notice(f"Checkpoint name: {checkpoint_name}.")
+
+        self.logger.log_notice(f"Verifying '{checkpoint_name}' exists.")
         if not self._check_checkpoint_exists(checkpoint_name):
             raise ValueError(f"Checkpoint '{checkpoint_name}' does not exist")
 
+        self.logger.log_notice(f"Loading checkpoint into memory.")
         target_config = self._get_checkpoint_content(checkpoint_name)
 
+        self.logger.log_notice(f"Replacing config using 'Config Replacer'.")
         self.config_replacer.replace(target_config)
 
+        self.logger.log_notice("Config rollbacking completed.")
+
     def checkpoint(self, checkpoint_name):
+        self.logger.log_notice("Config checkpoint starting.")
+        self.logger.log_notice(f"Checkpoint name: {checkpoint_name}.")
+
+        self.logger.log_notice("Getting current config db.")
         json_content = self.config_wrapper.get_config_db_as_json()
 
+        # if current config are not valid, we might not be able to rollback to it. So fail early by not taking checkpoint at all.
+        self.logger.log_notice("Validating current config according to YANG models.")
         if not self.config_wrapper.validate_config_db_config(json_content):
             raise ValueError(f"Running configs on the device are not valid.")
 
+        self.logger.log_notice("Getting checkpoint full-path.")
         path = self._get_checkpoint_full_path(checkpoint_name)
 
+        self.logger.log_notice("Ensuring checkpoint directory exist.")
         self._ensure_checkpoints_dir_exists()
 
+        self.logger.log_notice(f"Saving config db content to {path}.")
         self._save_json_file(path, json_content)
 
+        self.logger.log_notice("Config checkpoint completed.")
+
     def list_checkpoints(self):
+        self.logger.log_info("Listing checkpoints starting.")
+        
+        self.logger.log_info(f"Verifying checkpoints directory '{self.checkpoints_dir}' exists.")
         if not self._checkpoints_dir_exist():
+            self.logger.log_info("Checkpoints directory is empty, returning empty checkpoints list.")
             return []
 
-        return self._get_checkpoint_names()
+        self.logger.log_info("Getting checkpoints in checkpoints directory.")
+        checkpoint_names = self._get_checkpoint_names()
+
+        checkpoints_len = len(checkpoint_names)
+        self.logger.log_info(f"Found {checkpoints_len} checkpoint{'s' if checkpoints_len != 1 else ''}{':' if checkpoints_len > 0 else '.'}")
+        for checkpoint_name in checkpoint_names:
+            self.logger.log_info(f"  * {checkpoint_name}")
+
+        self.logger.log_info("Listing checkpoints completed.")
+
+        return checkpoint_names
 
     def delete_checkpoint(self, checkpoint_name):
+        self.logger.log_notice("Deleting checkpoint starting.")
+        self.logger.log_notice(f"Checkpoint name: {checkpoint_name}.")
+
+        self.logger.log_notice(f"Checking checkpoint exists.")
         if not self._check_checkpoint_exists(checkpoint_name):
             raise ValueError(f"Checkpoint '{checkpoint_name}' does not exist")
 
+        self.logger.log_notice(f"Deleting checkpoint.")
         self._delete_checkpoint(checkpoint_name)
 
+        self.logger.log_notice("Deleting checkpoint completed.")
+
     def _ensure_checkpoints_dir_exists(self):
         os.makedirs(self.checkpoints_dir, exist_ok=True)
 

generic_config_updater/gu_common.py

@@ -695,15 +695,16 @@ def _get_model(self, model, name):
         return None
 
 class TitledLogger(logger.Logger):
-    def __init__(self, syslog_identifier, title, verbose):
+    def __init__(self, syslog_identifier, title, verbose, print_all_to_console):
         super().__init__(syslog_identifier)
         self._title = title
         if verbose:
             self.set_min_log_priority_debug()
+        self.print_all_to_console = print_all_to_console
 
     def log(self, priority, msg, also_print_to_console=False):
         combined_msg = f"{self._title}: {msg}"
-        super().log(priority, combined_msg, also_print_to_console)
+        super().log(priority, combined_msg, self.print_all_to_console or also_print_to_console)
 
 class GenericUpdaterLogging:
     def __init__(self):
@@ -712,7 +713,7 @@ def __init__(self):
     def set_verbose(self, verbose):
         self._verbose = verbose
 
-    def get_logger(self, title):
-        return TitledLogger(SYSLOG_IDENTIFIER, title, self._verbose)
+    def get_logger(self, title, print_all_to_console=False):
+        return TitledLogger(SYSLOG_IDENTIFIER, title, self._verbose, print_all_to_console)
 
 genericUpdaterLogging = GenericUpdaterLogging()