From c6f6c4476b0681668363d218b0b8cc389b83ea08 Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Sat, 24 Aug 2024 08:02:07 +0000 Subject: [PATCH 1/7] Added new dynamic field 'last_sync_time' that shows when STORAGE_INFO for disk was last synced to STATE_DB --- sonic-stormond/scripts/stormond | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index dd1834156..2a573c74a 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -82,7 +82,8 @@ class DaemonStorage(daemon_base.DaemonBase): "total_fsio_writes", \ "disk_io_reads", \ "disk_io_writes", \ - "reserved_blocks"] + "reserved_blocks", \ + "last_sync_time"] # These are the fields that we are interested in saving to disk to protect against # reboots or crashes @@ -309,17 +310,20 @@ class DaemonStorage(daemon_base.DaemonBase): dynamic_kvp_dict["disk_io_reads"] = storage_object.get_disk_io_reads() dynamic_kvp_dict["disk_io_writes"] = storage_object.get_disk_io_writes() dynamic_kvp_dict["reserved_blocks"] = storage_object.get_reserved_blocks() + dynamic_kvp_dict["last_sync_time"] = time.time() dynamic_kvp_dict["total_fsio_reads"], dynamic_kvp_dict["total_fsio_writes"] = self._reconcile_fsio_rw_values(dynamic_kvp_dict, storage_device) + # Update storage device statistics to STATE_DB + self.update_storage_info_status_db(storage_device, dynamic_kvp_dict) + + # Log to syslog self.log_info("Storage Device: {}, Firmware: {}, health: {}%, Temp: {}C, FS IO Reads: {}, FS IO Writes: {}".format(\ storage_device, dynamic_kvp_dict["firmware"], dynamic_kvp_dict["health"], dynamic_kvp_dict["temperature"], dynamic_kvp_dict["total_fsio_reads"],dynamic_kvp_dict["total_fsio_writes"])) self.log_info("Latest FSIO Reads: {}, Latest FSIO Writes: {}".format(dynamic_kvp_dict["latest_fsio_reads"], dynamic_kvp_dict["latest_fsio_writes"])) self.log_info("Disk IO Reads: {}, Disk IO Writes: {}, Reserved Blocks: {}".format(dynamic_kvp_dict["disk_io_reads"], dynamic_kvp_dict["disk_io_writes"], \ dynamic_kvp_dict["reserved_blocks"])) - - # Update storage device statistics to STATE_DB - self.update_storage_info_status_db(storage_device, dynamic_kvp_dict) + self.log_info("Last successful sync time to STATE_DB: {}".format(dynamic_kvp_dict["last_sync_time"])) except Exception as ex: self.log_info("get_dynamic_fields_update_state_db() failed with: {}".format(str(ex))) From aa4249b034c70647090beb6a301e43df527be5a0 Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Sat, 24 Aug 2024 08:47:44 +0000 Subject: [PATCH 2/7] Moved 'start' message to actual starting point of the daemon --- sonic-stormond/scripts/stormond | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index 2a573c74a..eb67c43ea 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -49,6 +49,8 @@ class DaemonStorage(daemon_base.DaemonBase): self.log = syslogger.SysLogger(SYSLOG_IDENTIFIER) super(DaemonStorage, self).__init__(log_identifier) + self.log_info("Starting Storage Monitoring Daemon") + self.timeout = STORMOND_PERIODIC_STATEDB_SYNC_SECS self.fsstats_sync_interval = STORMOND_SYNC_TO_DISK_SECS self.stop_event = threading.Event() @@ -389,8 +391,6 @@ class DaemonStorage(daemon_base.DaemonBase): def main(): stormon = DaemonStorage(SYSLOG_IDENTIFIER) - stormon.log_info("Starting Storage Monitoring Daemon") - # Read and update Static Fields to the StateDB once stormon.get_static_fields_update_state_db() From 7f0ca27b6a1fed45bfa818539bd7c91ebf2698c1 Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Thu, 3 Oct 2024 09:53:58 +0000 Subject: [PATCH 3/7] Added functions for formatted and epoch time for user friendly time display --- sonic-stormond/scripts/stormond | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index eb67c43ea..f204056dc 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -14,6 +14,7 @@ import shutil import json import time +from datetime import datetime from sonic_py_common import daemon_base, device_info, syslogger from swsscommon import swsscommon from sonic_platform_base.sonic_storage.storage_devices import StorageDevices, BLKDEV_BASE_PATH @@ -70,8 +71,14 @@ class DaemonStorage(daemon_base.DaemonBase): self.fsio_rw_json = {disk:{} for disk in self.storage.devices} self.fsio_rw_statedb = {disk:{} for disk in self.storage.devices} + # This is the time format string + self.time_format_string = "%Y-%m-%d %H:%M:%S" + # This time is set at init and then subsequently after each FSIO JSON file sync - self.fsio_sync_time = time.time() + self.fsio_sync_time = self.get_formatted_time(time.time()) + + # This is the time at epoch + self.epoch = datetime(1970, 1, 1) # These are the various static and dynamic fields that are posted to state_db self.static_fields = ["device_model", "serial"] @@ -100,6 +107,15 @@ class DaemonStorage(daemon_base.DaemonBase): self._load_fsio_rw_json() self._determine_sot() + # This function is used to convert the epoch time to a user friendly formatted string + def get_formatted_time(self, time_since_epoch): + return datetime.fromtimestamp(time_since_epoch).strftime(self.time_format_string) + + # This function is used to convert the user friendly formatted string to epoch time + def get_epoch_time(self, formatted_time): + return int((datetime.strptime(formatted_time, self.time_format_string) - self.epoch).total_seconds()) + + def get_configdb_intervals(self): self.config_db = daemon_base.db_connect("CONFIG_DB") config_info = dict(self.config_db.hgetall('STORMOND_CONFIG|INTERVALS')) @@ -148,7 +164,7 @@ class DaemonStorage(daemon_base.DaemonBase): for field in self.statedb_json_sync_fields: json_file_dict[device][field] = self.state_db.hget('STORAGE_INFO|{}'.format(device), field) - self.fsio_sync_time = time.time() + self.fsio_sync_time = self.get_formatted_time(time.time()) json_file_dict["successful_sync_time"] = str(self.fsio_sync_time) with open(FSIO_RW_JSON_FILE, 'w+') as f: @@ -312,7 +328,7 @@ class DaemonStorage(daemon_base.DaemonBase): dynamic_kvp_dict["disk_io_reads"] = storage_object.get_disk_io_reads() dynamic_kvp_dict["disk_io_writes"] = storage_object.get_disk_io_writes() dynamic_kvp_dict["reserved_blocks"] = storage_object.get_reserved_blocks() - dynamic_kvp_dict["last_sync_time"] = time.time() + dynamic_kvp_dict["last_sync_time"] = self.get_formatted_time(time.time()) dynamic_kvp_dict["total_fsio_reads"], dynamic_kvp_dict["total_fsio_writes"] = self._reconcile_fsio_rw_values(dynamic_kvp_dict, storage_device) @@ -375,7 +391,7 @@ class DaemonStorage(daemon_base.DaemonBase): # If so, sync the appropriate fields to FSIO JSON file - elapsed_time = time.time() - self.fsio_sync_time + elapsed_time = time.time() - self.get_epoch_time(self.fsio_sync_time) if (elapsed_time > self.fsstats_sync_interval) or ((self.fsstats_sync_interval - elapsed_time) < self.timeout): if self.sync_fsio_rw_json(): self.write_sync_time_statedb() From 6a038af5cce6ef58037f07d237eab2ae5bc76fc2 Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Thu, 24 Oct 2024 21:35:00 +0000 Subject: [PATCH 4/7] Made changes per prgeor review comments --- sonic-stormond/scripts/stormond | 19 ++++++------------- 1 file changed, 6 insertions(+), 13 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index f204056dc..09dfb3ebd 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -75,10 +75,7 @@ class DaemonStorage(daemon_base.DaemonBase): self.time_format_string = "%Y-%m-%d %H:%M:%S" # This time is set at init and then subsequently after each FSIO JSON file sync - self.fsio_sync_time = self.get_formatted_time(time.time()) - - # This is the time at epoch - self.epoch = datetime(1970, 1, 1) + self.fsio_sync_time = time.time() # These are the various static and dynamic fields that are posted to state_db self.static_fields = ["device_model", "serial"] @@ -111,11 +108,7 @@ class DaemonStorage(daemon_base.DaemonBase): def get_formatted_time(self, time_since_epoch): return datetime.fromtimestamp(time_since_epoch).strftime(self.time_format_string) - # This function is used to convert the user friendly formatted string to epoch time - def get_epoch_time(self, formatted_time): - return int((datetime.strptime(formatted_time, self.time_format_string) - self.epoch).total_seconds()) - - + # This function is used to configure the polling and sync intervals for the daemon def get_configdb_intervals(self): self.config_db = daemon_base.db_connect("CONFIG_DB") config_info = dict(self.config_db.hgetall('STORMOND_CONFIG|INTERVALS')) @@ -164,8 +157,8 @@ class DaemonStorage(daemon_base.DaemonBase): for field in self.statedb_json_sync_fields: json_file_dict[device][field] = self.state_db.hget('STORAGE_INFO|{}'.format(device), field) - self.fsio_sync_time = self.get_formatted_time(time.time()) - json_file_dict["successful_sync_time"] = str(self.fsio_sync_time) + self.fsio_sync_time = time.time() + json_file_dict["successful_sync_time"] = str(self.get_formatted_time(self.fsio_sync_time)) with open(FSIO_RW_JSON_FILE, 'w+') as f: json.dump(json_file_dict, f) @@ -179,7 +172,7 @@ class DaemonStorage(daemon_base.DaemonBase): # Update the successful sync time to STATE_DB def write_sync_time_statedb(self): - self.state_db.hset("{}|{}".format(STORAGE_DEVICE_TABLE,FSSTATS_SYNC_TIME_KEY), "successful_sync_time", str(self.fsio_sync_time)) + self.state_db.hset("{}|{}".format(STORAGE_DEVICE_TABLE,FSSTATS_SYNC_TIME_KEY), "successful_sync_time", str(self.get_formatted_time(self.fsio_sync_time))) # Run a sanity check on the state_db. If successful, get total, latest # FSIO reads and writes for each storage device from STATE_DB @@ -391,7 +384,7 @@ class DaemonStorage(daemon_base.DaemonBase): # If so, sync the appropriate fields to FSIO JSON file - elapsed_time = time.time() - self.get_epoch_time(self.fsio_sync_time) + elapsed_time = time.time() - self.fsio_sync_time if (elapsed_time > self.fsstats_sync_interval) or ((self.fsstats_sync_interval - elapsed_time) < self.timeout): if self.sync_fsio_rw_json(): self.write_sync_time_statedb() From 91894b5194b77e6bf2a8d7d04f7f39d402513eb4 Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Thu, 7 Nov 2024 22:36:11 +0000 Subject: [PATCH 5/7] Pivot to SysLogger for all logging --- sonic-stormond/scripts/stormond | 52 ++++++++++++++++----------------- 1 file changed, 26 insertions(+), 26 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index 09dfb3ebd..0c87afa29 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -50,7 +50,7 @@ class DaemonStorage(daemon_base.DaemonBase): self.log = syslogger.SysLogger(SYSLOG_IDENTIFIER) super(DaemonStorage, self).__init__(log_identifier) - self.log_info("Starting Storage Monitoring Daemon") + self.log.log_info("Starting Storage Monitoring Daemon") self.timeout = STORMOND_PERIODIC_STATEDB_SYNC_SECS self.fsstats_sync_interval = STORMOND_SYNC_TO_DISK_SECS @@ -115,15 +115,15 @@ class DaemonStorage(daemon_base.DaemonBase): self.timeout = int(config_info.get('daemon_polling_interval', STORMOND_PERIODIC_STATEDB_SYNC_SECS)) self.fsstats_sync_interval = int(config_info.get('fsstats_sync_interval', STORMOND_SYNC_TO_DISK_SECS)) - self.log_info("Polling Interval set to {} seconds".format(self.timeout)) - self.log_info("FSIO JSON file Interval set to {} seconds".format(self.fsstats_sync_interval)) + self.log.log_info("Polling Interval set to {} seconds".format(self.timeout)) + self.log.log_info("FSIO JSON file Interval set to {} seconds".format(self.fsstats_sync_interval)) # Get the total and latest FSIO reads and writes from JSON file def _load_fsio_rw_json(self): try: if not os.path.exists(FSIO_RW_JSON_FILE): - self.log_info("{} not present.".format(FSIO_RW_JSON_FILE)) + self.log.log_info("{} not present.".format(FSIO_RW_JSON_FILE)) return # Load JSON file @@ -135,13 +135,13 @@ class DaemonStorage(daemon_base.DaemonBase): for field in self.statedb_json_sync_fields: if self.fsio_rw_json[storage_device][field] == None: - self.log_warning("{}:{} value = None in JSON file".format(storage_device, field)) + self.log.log_warning("{}:{} value = None in JSON file".format(storage_device, field)) return self.fsio_json_file_loaded = True except Exception as e: - self.log_error("JSON file could not be loaded: {}".format(str(e))) + self.log.log_error("JSON file could not be loaded: {}".format(str(e))) return @@ -149,7 +149,7 @@ class DaemonStorage(daemon_base.DaemonBase): # Sync the total and latest procfs reads and writes from STATE_DB to JSON file on disk def sync_fsio_rw_json(self): - self.log_info("Syncing total and latest procfs reads and writes from STATE_DB to JSON file") + self.log.log_info("Syncing total and latest procfs reads and writes from STATE_DB to JSON file") json_file_dict = {disk:{} for disk in self.storage.devices} try: @@ -166,7 +166,7 @@ class DaemonStorage(daemon_base.DaemonBase): return True except Exception as ex: - self.log_error("Unable to sync state_db to disk: {}".format(str(ex))) + self.log.log_error("Unable to sync state_db to disk: {}".format(str(ex))) return False @@ -197,12 +197,12 @@ class DaemonStorage(daemon_base.DaemonBase): self.fsio_rw_statedb[storage_device][field] = "0" if value is None else value if value is None: - self.log_warning("{}:{} value = None in StateDB".format(storage_device, field)) + self.log.log_warning("{}:{} value = None in StateDB".format(storage_device, field)) return self.statedb_storage_info_loaded = True except Exception as e: - self.log_error("Reading STATE_DB failed with: {}".format(str(e))) + self.log.log_error("Reading STATE_DB failed with: {}".format(str(e))) def _determine_sot(self): @@ -281,7 +281,7 @@ class DaemonStorage(daemon_base.DaemonBase): try: # Unlikely scenario if storage_object is None: - self.log_info("{} does not have an instantiated object. Static Information cannot be gathered.".format(storage_device)) + self.log.log_info("{} does not have an instantiated object. Static Information cannot be gathered.".format(storage_device)) continue static_kvp_dict = {} @@ -289,13 +289,13 @@ class DaemonStorage(daemon_base.DaemonBase): static_kvp_dict["device_model"] = storage_object.get_model() static_kvp_dict["serial"] = storage_object.get_serial() - self.log_info("Storage Device: {}, Device Model: {}, Serial: {}".format(storage_device, static_kvp_dict["device_model"], static_kvp_dict["serial"])) + self.log.log_info("Storage Device: {}, Device Model: {}, Serial: {}".format(storage_device, static_kvp_dict["device_model"], static_kvp_dict["serial"])) # update Storage Device Status to DB self.update_storage_info_status_db(storage_device, static_kvp_dict) except Exception as ex: - self.log_error("get_static_fields_update_state_db() failed with: {}".format(str(ex))) + self.log.log_error("get_static_fields_update_state_db() failed with: {}".format(str(ex))) # Get Dynamic attributes and update the State DB def get_dynamic_fields_update_state_db(self): @@ -304,7 +304,7 @@ class DaemonStorage(daemon_base.DaemonBase): for storage_device, storage_object in self.storage.devices.items(): try: if storage_object is None: - self.log_info("Storage device '{}' does not have an instantiated object. Dynamic Information cannot be gathered.".format(storage_device)) + self.log.log_info("Storage device '{}' does not have an instantiated object. Dynamic Information cannot be gathered.".format(storage_device)) continue # Fetch the latest dynamic info @@ -329,15 +329,15 @@ class DaemonStorage(daemon_base.DaemonBase): self.update_storage_info_status_db(storage_device, dynamic_kvp_dict) # Log to syslog - self.log_info("Storage Device: {}, Firmware: {}, health: {}%, Temp: {}C, FS IO Reads: {}, FS IO Writes: {}".format(\ + self.log.log_info("Storage Device: {}, Firmware: {}, health: {}%, Temp: {}C, FS IO Reads: {}, FS IO Writes: {}".format(\ storage_device, dynamic_kvp_dict["firmware"], dynamic_kvp_dict["health"], dynamic_kvp_dict["temperature"], dynamic_kvp_dict["total_fsio_reads"],dynamic_kvp_dict["total_fsio_writes"])) - self.log_info("Latest FSIO Reads: {}, Latest FSIO Writes: {}".format(dynamic_kvp_dict["latest_fsio_reads"], dynamic_kvp_dict["latest_fsio_writes"])) - self.log_info("Disk IO Reads: {}, Disk IO Writes: {}, Reserved Blocks: {}".format(dynamic_kvp_dict["disk_io_reads"], dynamic_kvp_dict["disk_io_writes"], \ + self.log.log_info("Latest FSIO Reads: {}, Latest FSIO Writes: {}".format(dynamic_kvp_dict["latest_fsio_reads"], dynamic_kvp_dict["latest_fsio_writes"])) + self.log.log_info("Disk IO Reads: {}, Disk IO Writes: {}, Reserved Blocks: {}".format(dynamic_kvp_dict["disk_io_reads"], dynamic_kvp_dict["disk_io_writes"], \ dynamic_kvp_dict["reserved_blocks"])) - self.log_info("Last successful sync time to STATE_DB: {}".format(dynamic_kvp_dict["last_sync_time"])) + self.log.log_info("Last successful sync time to STATE_DB: {}".format(dynamic_kvp_dict["last_sync_time"])) except Exception as ex: - self.log_info("get_dynamic_fields_update_state_db() failed with: {}".format(str(ex))) + self.log.log_info("get_dynamic_fields_update_state_db() failed with: {}".format(str(ex))) # Override signal handler from DaemonBase @@ -348,22 +348,22 @@ class DaemonStorage(daemon_base.DaemonBase): global exit_code if sig in FATAL_SIGNALS: - self.log_info("Caught signal '{}'".format(signal.Signals(sig).name)) + self.log.log_info("Caught signal '{}'".format(signal.Signals(sig).name)) if self.sync_fsio_rw_json(): self.write_sync_time_statedb() else: - self.log_warning("Unable to sync latest and total procfs RW to disk") + self.log.log_warning("Unable to sync latest and total procfs RW to disk") - self.log_info("Exiting with {}".format(signal.Signals(sig).name)) + self.log.log_info("Exiting with {}".format(signal.Signals(sig).name)) # Make sure we exit with a non-zero code so that supervisor will try to restart us exit_code = 128 + sig self.stop_event.set() elif sig in NONFATAL_SIGNALS: - self.log_info("Caught signal '{}' - ignoring...".format(signal.Signals(sig).name)) + self.log.log_info("Caught signal '{}' - ignoring...".format(signal.Signals(sig).name)) else: - self.log_warning("Caught unhandled signal '{}' - ignoring...".format(signal.Signals(sig).name)) + self.log.log_warning("Caught unhandled signal '{}' - ignoring...".format(signal.Signals(sig).name)) # Main daemon logic def run(self): @@ -389,7 +389,7 @@ class DaemonStorage(daemon_base.DaemonBase): if self.sync_fsio_rw_json(): self.write_sync_time_statedb() else: - self.log_warning("Unable to sync latest and total procfs RW to disk") + self.log.log_warning("Unable to sync latest and total procfs RW to disk") return True # @@ -406,7 +406,7 @@ def main(): while stormon.run(): pass - stormon.log_info("Shutting down Storage Monitoring Daemon") + stormon.log.log_info("Shutting down Storage Monitoring Daemon") return exit_code From d5c59696f4c2b12eaf6cc1dd5efd85723474d20e Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Tue, 19 Nov 2024 22:43:16 +0000 Subject: [PATCH 6/7] Increased log level so that they are seen in syslogs --- sonic-stormond/scripts/stormond | 34 +++++++++--------- sonic-stormond/tests/test_DaemonStorage.py | 40 +++++++++++----------- 2 files changed, 37 insertions(+), 37 deletions(-) diff --git a/sonic-stormond/scripts/stormond b/sonic-stormond/scripts/stormond index 0c87afa29..24a35e5a7 100755 --- a/sonic-stormond/scripts/stormond +++ b/sonic-stormond/scripts/stormond @@ -50,7 +50,7 @@ class DaemonStorage(daemon_base.DaemonBase): self.log = syslogger.SysLogger(SYSLOG_IDENTIFIER) super(DaemonStorage, self).__init__(log_identifier) - self.log.log_info("Starting Storage Monitoring Daemon") + self.log.log_notice("Starting Storage Monitoring Daemon") self.timeout = STORMOND_PERIODIC_STATEDB_SYNC_SECS self.fsstats_sync_interval = STORMOND_SYNC_TO_DISK_SECS @@ -115,15 +115,15 @@ class DaemonStorage(daemon_base.DaemonBase): self.timeout = int(config_info.get('daemon_polling_interval', STORMOND_PERIODIC_STATEDB_SYNC_SECS)) self.fsstats_sync_interval = int(config_info.get('fsstats_sync_interval', STORMOND_SYNC_TO_DISK_SECS)) - self.log.log_info("Polling Interval set to {} seconds".format(self.timeout)) - self.log.log_info("FSIO JSON file Interval set to {} seconds".format(self.fsstats_sync_interval)) + self.log.log_notice("Polling Interval set to {} seconds".format(self.timeout)) + self.log.log_notice("FSIO JSON file Interval set to {} seconds".format(self.fsstats_sync_interval)) # Get the total and latest FSIO reads and writes from JSON file def _load_fsio_rw_json(self): try: if not os.path.exists(FSIO_RW_JSON_FILE): - self.log.log_info("{} not present.".format(FSIO_RW_JSON_FILE)) + self.log.log_notice("{} not present.".format(FSIO_RW_JSON_FILE)) return # Load JSON file @@ -149,7 +149,7 @@ class DaemonStorage(daemon_base.DaemonBase): # Sync the total and latest procfs reads and writes from STATE_DB to JSON file on disk def sync_fsio_rw_json(self): - self.log.log_info("Syncing total and latest procfs reads and writes from STATE_DB to JSON file") + self.log.log_notice("Syncing total and latest procfs reads and writes from STATE_DB to JSON file") json_file_dict = {disk:{} for disk in self.storage.devices} try: @@ -281,7 +281,7 @@ class DaemonStorage(daemon_base.DaemonBase): try: # Unlikely scenario if storage_object is None: - self.log.log_info("{} does not have an instantiated object. Static Information cannot be gathered.".format(storage_device)) + self.log.log_notice("{} does not have an instantiated object. Static Information cannot be gathered.".format(storage_device)) continue static_kvp_dict = {} @@ -289,7 +289,7 @@ class DaemonStorage(daemon_base.DaemonBase): static_kvp_dict["device_model"] = storage_object.get_model() static_kvp_dict["serial"] = storage_object.get_serial() - self.log.log_info("Storage Device: {}, Device Model: {}, Serial: {}".format(storage_device, static_kvp_dict["device_model"], static_kvp_dict["serial"])) + self.log.log_notice("Storage Device: {}, Device Model: {}, Serial: {}".format(storage_device, static_kvp_dict["device_model"], static_kvp_dict["serial"])) # update Storage Device Status to DB self.update_storage_info_status_db(storage_device, static_kvp_dict) @@ -304,7 +304,7 @@ class DaemonStorage(daemon_base.DaemonBase): for storage_device, storage_object in self.storage.devices.items(): try: if storage_object is None: - self.log.log_info("Storage device '{}' does not have an instantiated object. Dynamic Information cannot be gathered.".format(storage_device)) + self.log.log_notice("Storage device '{}' does not have an instantiated object. Dynamic Information cannot be gathered.".format(storage_device)) continue # Fetch the latest dynamic info @@ -329,15 +329,15 @@ class DaemonStorage(daemon_base.DaemonBase): self.update_storage_info_status_db(storage_device, dynamic_kvp_dict) # Log to syslog - self.log.log_info("Storage Device: {}, Firmware: {}, health: {}%, Temp: {}C, FS IO Reads: {}, FS IO Writes: {}".format(\ + self.log.log_notice("Storage Device: {}, Firmware: {}, health: {}%, Temp: {}C, FS IO Reads: {}, FS IO Writes: {}".format(\ storage_device, dynamic_kvp_dict["firmware"], dynamic_kvp_dict["health"], dynamic_kvp_dict["temperature"], dynamic_kvp_dict["total_fsio_reads"],dynamic_kvp_dict["total_fsio_writes"])) - self.log.log_info("Latest FSIO Reads: {}, Latest FSIO Writes: {}".format(dynamic_kvp_dict["latest_fsio_reads"], dynamic_kvp_dict["latest_fsio_writes"])) - self.log.log_info("Disk IO Reads: {}, Disk IO Writes: {}, Reserved Blocks: {}".format(dynamic_kvp_dict["disk_io_reads"], dynamic_kvp_dict["disk_io_writes"], \ + self.log.log_notice("Latest FSIO Reads: {}, Latest FSIO Writes: {}".format(dynamic_kvp_dict["latest_fsio_reads"], dynamic_kvp_dict["latest_fsio_writes"])) + self.log.log_notice("Disk IO Reads: {}, Disk IO Writes: {}, Reserved Blocks: {}".format(dynamic_kvp_dict["disk_io_reads"], dynamic_kvp_dict["disk_io_writes"], \ dynamic_kvp_dict["reserved_blocks"])) - self.log.log_info("Last successful sync time to STATE_DB: {}".format(dynamic_kvp_dict["last_sync_time"])) + self.log.log_notice("Last successful sync time to STATE_DB: {}".format(dynamic_kvp_dict["last_sync_time"])) except Exception as ex: - self.log.log_info("get_dynamic_fields_update_state_db() failed with: {}".format(str(ex))) + self.log.log_notice("get_dynamic_fields_update_state_db() failed with: {}".format(str(ex))) # Override signal handler from DaemonBase @@ -348,20 +348,20 @@ class DaemonStorage(daemon_base.DaemonBase): global exit_code if sig in FATAL_SIGNALS: - self.log.log_info("Caught signal '{}'".format(signal.Signals(sig).name)) + self.log.log_notice("Caught signal '{}'".format(signal.Signals(sig).name)) if self.sync_fsio_rw_json(): self.write_sync_time_statedb() else: self.log.log_warning("Unable to sync latest and total procfs RW to disk") - self.log.log_info("Exiting with {}".format(signal.Signals(sig).name)) + self.log.log_notice("Exiting with {}".format(signal.Signals(sig).name)) # Make sure we exit with a non-zero code so that supervisor will try to restart us exit_code = 128 + sig self.stop_event.set() elif sig in NONFATAL_SIGNALS: - self.log.log_info("Caught signal '{}' - ignoring...".format(signal.Signals(sig).name)) + self.log.log_notice("Caught signal '{}' - ignoring...".format(signal.Signals(sig).name)) else: self.log.log_warning("Caught unhandled signal '{}' - ignoring...".format(signal.Signals(sig).name)) @@ -406,7 +406,7 @@ def main(): while stormon.run(): pass - stormon.log.log_info("Shutting down Storage Monitoring Daemon") + stormon.log.log_notice("Shutting down Storage Monitoring Daemon") return exit_code diff --git a/sonic-stormond/tests/test_DaemonStorage.py b/sonic-stormond/tests/test_DaemonStorage.py index dafb05fd9..76480b556 100644 --- a/sonic-stormond/tests/test_DaemonStorage.py +++ b/sonic-stormond/tests/test_DaemonStorage.py @@ -237,56 +237,56 @@ def test_signal_handler(self): stormon_daemon.sync_fsio_rw_json = MagicMock() stormon_daemon.stop_event.set = MagicMock() - stormon_daemon.log_info = MagicMock() - stormon_daemon.log_warning = MagicMock() + stormon_daemon.log.log_notice = MagicMock() + stormon_daemon.log.log_warning = MagicMock() # Test SIGHUP stormon_daemon.signal_handler(stormond.signal.SIGHUP, None) - assert stormon_daemon.log_info.call_count == 1 - stormon_daemon.log_info.assert_called_with("Caught signal 'SIGHUP' - ignoring...") - assert stormon_daemon.log_warning.call_count == 0 + assert stormon_daemon.log.log_notice.call_count == 1 + stormon_daemon.log.log_notice.assert_called_with("Caught signal 'SIGHUP' - ignoring...") + assert stormon_daemon.log.log_warning.call_count == 0 assert stormon_daemon.stop_event.set.call_count == 0 assert stormond.exit_code == 0 # Reset - stormon_daemon.log_info.reset_mock() - stormon_daemon.log_warning.reset_mock() + stormon_daemon.log.log_notice.reset_mock() + stormon_daemon.log.log_warning.reset_mock() stormon_daemon.stop_event.set.reset_mock() # Test SIGINT test_signal = stormond.signal.SIGINT stormon_daemon.signal_handler(test_signal, None) - assert stormon_daemon.log_info.call_count == 2 - stormon_daemon.log_info.assert_called_with("Exiting with SIGINT") - assert stormon_daemon.log_warning.call_count == 0 + assert stormon_daemon.log.log_notice.call_count == 2 + stormon_daemon.log.log_notice.assert_called_with("Exiting with SIGINT") + assert stormon_daemon.log.log_warning.call_count == 0 assert stormon_daemon.stop_event.set.call_count == 1 assert stormond.exit_code == (128 + test_signal) # Reset - stormon_daemon.log_info.reset_mock() - stormon_daemon.log_warning.reset_mock() + stormon_daemon.log.log_notice.reset_mock() + stormon_daemon.log.log_warning.reset_mock() stormon_daemon.stop_event.set.reset_mock() # Test SIGTERM test_signal = stormond.signal.SIGTERM stormon_daemon.signal_handler(test_signal, None) - assert stormon_daemon.log_info.call_count == 2 - stormon_daemon.log_info.assert_called_with("Exiting with SIGTERM") - assert stormon_daemon.log_warning.call_count == 0 + assert stormon_daemon.log.log_notice.call_count == 2 + stormon_daemon.log.log_notice.assert_called_with("Exiting with SIGTERM") + assert stormon_daemon.log.log_warning.call_count == 0 assert stormon_daemon.stop_event.set.call_count == 1 assert stormond.exit_code == (128 + test_signal) # Reset - stormon_daemon.log_info.reset_mock() - stormon_daemon.log_warning.reset_mock() + stormon_daemon.log.log_notice.reset_mock() + stormon_daemon.log.log_warning.reset_mock() stormon_daemon.stop_event.set.reset_mock() stormond.exit_code = 0 # Test an unhandled signal stormon_daemon.signal_handler(stormond.signal.SIGUSR1, None) - assert stormon_daemon.log_warning.call_count == 1 - stormon_daemon.log_warning.assert_called_with("Caught unhandled signal 'SIGUSR1' - ignoring...") - assert stormon_daemon.log_info.call_count == 0 + assert stormon_daemon.log.log_warning.call_count == 1 + stormon_daemon.log.log_warning.assert_called_with("Caught unhandled signal 'SIGUSR1' - ignoring...") + assert stormon_daemon.log.log_notice.call_count == 0 assert stormon_daemon.stop_event.set.call_count == 0 assert stormond.exit_code == 0 From a95ec94d30d5ea06aea19232b5ed217e93a229fd Mon Sep 17 00:00:00 2001 From: Ashwin Srinivasan Date: Sat, 23 Nov 2024 12:38:59 +0000 Subject: [PATCH 7/7] Code coverage improvement --- sonic-stormond/tests/test_DaemonStorage.py | 210 ++++++++++++++++++++- 1 file changed, 200 insertions(+), 10 deletions(-) diff --git a/sonic-stormond/tests/test_DaemonStorage.py b/sonic-stormond/tests/test_DaemonStorage.py index 76480b556..f342a95a3 100644 --- a/sonic-stormond/tests/test_DaemonStorage.py +++ b/sonic-stormond/tests/test_DaemonStorage.py @@ -1,7 +1,10 @@ import datetime import os import sys -from imp import load_source +import runpy + +from imp import load_source, reload +from sonic_py_common import syslogger # TODO: Clean this up once we no longer need to support Python 2 if sys.version_info.major == 3: @@ -30,8 +33,6 @@ log_identifier = 'storage_daemon_test' -#daemon_base.db_connect = MagicMock() - config_intvls = ''' daemon_polling_interval, 60, @@ -72,6 +73,7 @@ def new_mock_factory(self, key): assert(list(stormon_daemon.storage.devices.keys()) == ['sda']) + @patch('os.path.exists', MagicMock(return_value=True)) @patch('json.load', MagicMock(return_value=bad_fsio_json_dict)) @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) @@ -81,7 +83,8 @@ def test_load_fsio_rw_json_false(self): stormon_daemon = stormond.DaemonStorage(log_identifier) assert stormon_daemon.fsio_json_file_loaded == False - + + @patch('os.path.exists', MagicMock(return_value=True)) @patch('json.load', MagicMock(return_value=fsio_json_dict)) @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) @@ -113,16 +116,67 @@ def testget_configdb_intervals(self, mock_daemon_base): assert mock_daemon_base.call_count == 0 - + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_load_fsio_rw_statedb(self): + + keys_list = ['STORAGE_INFO|sda', 'STORAGE_INFO|FSSTATS_SYNC'] + + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.storage.devices = {'sda' : MagicMock()} + stormon_daemon.state_db.keys = MagicMock(return_value=keys_list) + stormon_daemon.state_db.hget = MagicMock() + + stormon_daemon._load_fsio_rw_statedb() + + assert stormon_daemon.statedb_storage_info_loaded == True + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_load_fsio_rw_statedb_exception(self): + + keys_list = ['STORAGE_INFO|sda', 'STORAGE_INFO|FSSTATS_SYNC'] + + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.storage.devices = {'sda' : MagicMock()} + stormon_daemon.state_db.keys = MagicMock(return_value=keys_list) + stormon_daemon.state_db.hget = MagicMock(side_effect=Exception) + stormon_daemon.log.log_error = MagicMock() + + stormon_daemon._load_fsio_rw_statedb() + + assert stormon_daemon.statedb_storage_info_loaded == False + assert stormon_daemon.log.log_error.call_count == 1 + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_load_fsio_rw_statedb_value_none(self): + + keys_list = ['STORAGE_INFO|sda', 'STORAGE_INFO|FSSTATS_SYNC'] + + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.storage.devices = {'sda' : MagicMock()} + stormon_daemon.state_db.keys = MagicMock(return_value=keys_list) + stormon_daemon.state_db.hget = MagicMock(return_value=None) + + stormon_daemon._load_fsio_rw_statedb() + + assert stormon_daemon.statedb_storage_info_loaded == False + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) @patch('json.dump', MagicMock()) def test_sync_fsio_rw_json_exception(self): stormon_daemon = stormond.DaemonStorage(log_identifier) with patch('builtins.open', new_callable=mock_open, read_data='{}') as mock_fd: + stormon_daemon.log.log_error = MagicMock() + stormon_daemon.get_formatted_time = MagicMock(side_effect=Exception) stormon_daemon.sync_fsio_rw_json() assert stormon_daemon.state_db.call_count == 0 + assert stormon_daemon.log.log_error.call_count == 1 + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) @patch('json.dump', MagicMock()) @@ -147,6 +201,17 @@ def test_reconcile_fsio_rw_values_init(self): assert writes == '2000' + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_determine_sot(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.statedb_storage_info_loaded = True + + stormon_daemon._determine_sot() + + assert stormon_daemon.use_statedb_baseline == True + assert stormon_daemon.use_fsio_json_baseline == False + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) def test_reconcile_fsio_rw_values_reboot(self): stormon_daemon = stormond.DaemonStorage(log_identifier) @@ -185,7 +250,19 @@ def test_update_storage_info_status_db(self): @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) - def test_get_static_fields(self): + def test_get_static_fields_no_storage_device_object(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.log.log_notice = MagicMock() + + stormon_daemon.storage.devices = {'sda' : None} + + stormon_daemon.get_static_fields_update_state_db() + + assert stormon_daemon.log.log_notice.call_count == 1 + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_get_static_fields_happy(self): stormon_daemon = stormond.DaemonStorage(log_identifier) mock_storage_device_object = MagicMock() @@ -199,6 +276,35 @@ def test_get_static_fields(self): assert stormon_daemon.device_table.get('sda') == {'device_model': 'Skynet', 'serial': 'T1000'} + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_get_static_fields_exception(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + + mock_storage_device_object = MagicMock() + mock_storage_device_object.get_model.return_value = "Skynet" + mock_storage_device_object.get_serial.return_value = "T1000" + + stormon_daemon.storage.devices = {'sda' : mock_storage_device_object} + stormon_daemon.log.log_error = MagicMock() + stormon_daemon.update_storage_info_status_db = MagicMock(side_effect=Exception) + + stormon_daemon.get_static_fields_update_state_db() + + assert stormon_daemon.log.log_error.call_count == 1 + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_get_dynamic_fields_no_storage_device_object(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.log.log_notice = MagicMock() + + stormon_daemon.storage.devices = {'sda' : None} + + stormon_daemon.get_dynamic_fields_update_state_db() + + assert stormon_daemon.log.log_notice.call_count == 1 + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) def test_get_dynamic_fields(self): stormon_daemon = stormond.DaemonStorage(log_identifier) @@ -219,7 +325,22 @@ def test_get_dynamic_fields(self): assert stormon_daemon.device_table.getKeys() == ['sda'] for field, value in dynamic_dict.items(): assert stormon_daemon.device_table.get('sda')[field] == value - + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_get_dynamic_fields_exception(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.log.log_notice = MagicMock() + + mock_storage_device_object = MagicMock() + mock_storage_device_object.fetch_parse_info = MagicMock(side_effect=Exception) + + stormon_daemon.storage.devices = {'sda' : mock_storage_device_object} + stormon_daemon.get_dynamic_fields_update_state_db() + + assert stormon_daemon.log.log_notice.call_count == 1 + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) @patch('json.dump', MagicMock()) @patch('time.time', MagicMock(return_value=1000)) @@ -291,18 +412,87 @@ def test_signal_handler(self): assert stormond.exit_code == 0 + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_signal_handler_sync_fsio_json_failed(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.sync_fsio_rw_json = MagicMock(return_value=False) + + stormon_daemon.stop_event.set = MagicMock() + stormon_daemon.log.log_notice = MagicMock() + stormon_daemon.log.log_warning = MagicMock() + + test_signal = stormond.signal.SIGTERM + stormon_daemon.signal_handler(test_signal, None) + assert stormon_daemon.log.log_notice.call_count == 2 + assert stormon_daemon.log.log_warning.call_count == 1 + assert stormon_daemon.stop_event.set.call_count == 1 + assert stormond.exit_code == (128 + test_signal) + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) def test_run(self): stormon_daemon = stormond.DaemonStorage(log_identifier) stormon_daemon.get_dynamic_fields_update_state_db = MagicMock() + stormon_daemon.sync_fsio_rw_json = MagicMock(return_value=True) + stormon_daemon.write_sync_time_statedb = MagicMock(return_value=True) + + def mock_intervals(): + stormon_daemon.timeout = 5 + stormon_daemon.fsstats_sync_interval = 15 + + stormon_daemon.fsio_sync_time = 0 + + with patch.object(stormon_daemon, 'get_configdb_intervals', new=mock_intervals): + rc = stormon_daemon.run() + + assert stormon_daemon.get_dynamic_fields_update_state_db.call_count == 1 + assert stormon_daemon.sync_fsio_rw_json.call_count == 1 + assert stormon_daemon.write_sync_time_statedb.call_count == 1 + assert rc == True + + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_run_stop_event(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.get_dynamic_fields_update_state_db = MagicMock() + stormon_daemon.stop_event.wait = MagicMock(return_value=True) + + def mock_intervals(): + stormon_daemon.timeout = 5 + stormon_daemon.fsstats_sync_interval = 15 + + with patch.object(stormon_daemon, 'get_configdb_intervals', new=mock_intervals): + rc = stormon_daemon.run() + + assert stormon_daemon.get_dynamic_fields_update_state_db.call_count == 1 + assert rc == False + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + def test_run_sync_fsio_rw_json_failed(self): + stormon_daemon = stormond.DaemonStorage(log_identifier) + stormon_daemon.get_dynamic_fields_update_state_db = MagicMock() + stormon_daemon.sync_fsio_rw_json = MagicMock(return_value=False) + stormon_daemon.log.log_warning = MagicMock() def mock_intervals(): - stormon_daemon.timeout = 10 - stormon_daemon.fsstats_sync_interval = 30 + stormon_daemon.timeout = 5 + stormon_daemon.fsstats_sync_interval = 15 + + stormon_daemon.fsio_sync_time = 0 with patch.object(stormon_daemon, 'get_configdb_intervals', new=mock_intervals): - stormon_daemon.run() + rc = stormon_daemon.run() assert stormon_daemon.get_dynamic_fields_update_state_db.call_count == 1 + assert stormon_daemon.sync_fsio_rw_json.call_count == 1 + assert stormon_daemon.log.log_warning.call_count == 1 + assert rc == True +class TestStormon(): + + @patch('sonic_py_common.daemon_base.db_connect', MagicMock()) + @patch('sonic_py_common.syslogger.SysLogger', MagicMock()) + def test_main(self): + stormond.DaemonStorage.run = MagicMock(return_value=False) + assert stormond.main()