From 54fb450f93a7ce56d4c0008b75a4ca389dee748c Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Fri, 7 Jun 2024 09:24:44 +0300 Subject: [PATCH 1/5] Enable runtime config log level --- .../sonic_py_common/daemon_base.py | 4 +- .../sonic_py_common/syslogger.py | 118 +++++++++++++++++- src/sonic-py-common/tests/test_syslogger.py | 67 ++++++++++ 3 files changed, 186 insertions(+), 3 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/daemon_base.py b/src/sonic-py-common/sonic_py_common/daemon_base.py index 8bfd09cd881d..fd98a12b28e2 100644 --- a/src/sonic-py-common/sonic_py_common/daemon_base.py +++ b/src/sonic-py-common/sonic_py_common/daemon_base.py @@ -35,10 +35,10 @@ def db_connect(db_name, namespace=EMPTY_NAMESPACE): class DaemonBase(Logger): - def __init__(self, log_identifier, use_syslogger=True): + def __init__(self, log_identifier, use_syslogger=True, enable_runtime_log_config=False): super().__init__() if use_syslogger: - self.logger_instance = SysLogger(log_identifier) + self.logger_instance = SysLogger(log_identifier, enable_runtime_config=enable_runtime_log_config) else: self.logger_instance = Logger( log_identifier=log_identifier, diff --git a/src/sonic-py-common/sonic_py_common/syslogger.py b/src/sonic-py-common/sonic_py_common/syslogger.py index c45f0cde8425..65e71dfcb98c 100644 --- a/src/sonic-py-common/sonic_py_common/syslogger.py +++ b/src/sonic-py-common/sonic_py_common/syslogger.py @@ -3,6 +3,12 @@ import os import socket import sys +import threading + +CONFIG_DB = 'CONFIG_DB' +FIELD_LOG_LEVEL = 'LOGLEVEL' +FIELD_REQUIRE_REFRESH = 'require_manual_refresh' + # customize python logging to support notice logger logging.NOTICE = logging.INFO + 1 @@ -14,11 +20,14 @@ class SysLogger: """ SysLogger class for Python applications using SysLogHandler """ + + log_registry = {} + lock = threading.Lock() DEFAULT_LOG_FACILITY = SysLogHandler.LOG_USER DEFAULT_LOG_LEVEL = logging.NOTICE - def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_level=DEFAULT_LOG_LEVEL): + def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_level=DEFAULT_LOG_LEVEL, enable_runtime_config=False): if log_identifier is None: log_identifier = os.path.basename(sys.argv[0]) @@ -35,6 +44,113 @@ def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_l self.logger.addHandler(handler) self.set_min_log_priority(log_level) + + if enable_runtime_config: + self.register_for_runtime_config(log_identifier) + + def register_for_runtime_config(self, log_identifier): + """Register current log instance to log registry. If DB entry exists, + update log level according to DB configuration; otherwise, save current + log level to DB. + + Args: + log_identifier (str): key of LOGGER table + """ + with SysLogger.lock: + if log_identifier not in SysLogger.log_registry: + SysLogger.log_registry[log_identifier] = [self] + else: + SysLogger.log_registry[log_identifier].append(self) + + from swsscommon import swsscommon + try: + config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) + config_db.connect(CONFIG_DB) + log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) + if log_level_in_db: + self.set_min_log_priority(self.log_priority_from_str(log_level_in_db)) + else: + data = { + FIELD_LOG_LEVEL: self.log_priority_to_str(self._min_log_level), + FIELD_REQUIRE_REFRESH: 'true' + } + config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) + except Exception as e: + self.log_notice(f'DB is not available when initialize logger instance - {e}') + + @classmethod + def update_log_level(cls): + """Refresh log level for each log instances registered to cls.log_registry. + + Returns: + tuple: (refresh result, fail reason) + """ + with cls.lock: + if not cls.log_registry: + return True, '' + + from swsscommon import swsscommon + try: + config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) + config_db.connect(CONFIG_DB) + for log_identifier, log_instances in cls.log_registry.items(): + log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) + if log_level_in_db: + for log_instance in log_instances: + log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level_in_db)) + else: + for log_instance in log_instances: + data = { + FIELD_LOG_LEVEL: log_instance.log_priority_to_str(log_instance._min_log_level), + FIELD_REQUIRE_REFRESH: 'true' + } + config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) + break + return True, '' + except Exception as e: + return False, f'Failed to refresh log configuration - {e}' + + def log_priority_to_str(self, priority): + """Convert log priority to string. + Args: + priority (int): log priority. + Returns: + str: log priority in string. + """ + if priority == logging.INFO: + return 'INFO' + elif priority == logging.NOTICE: + return 'NOTICE' + elif priority == logging.DEBUG: + return 'DEBUG' + elif priority == logging.WARNING: + return 'WARN' + elif priority == logging.ERROR: + return 'ERROR' + else: + self.log_error(f'Invalid log priority: {priority}') + return 'NOTICE' + + def log_priority_from_str(self, priority_in_str): + """Convert log priority from string. + Args: + priority_in_str (str): log priority in string. + Returns: + _type_: log priority. + """ + if priority_in_str == 'DEBUG': + return logging.DEBUG + elif priority_in_str == 'INFO': + return logging.INFO + elif priority_in_str == 'NOTICE': + return logging.NOTICE + elif priority_in_str == 'WARN': + return logging.WARNING + elif priority_in_str == 'ERROR': + return logging.ERROR + else: + self.log_error(f'Invalid log priority string: {priority_in_str}') + return logging.NOTICE def set_min_log_priority(self, priority): """ diff --git a/src/sonic-py-common/tests/test_syslogger.py b/src/sonic-py-common/tests/test_syslogger.py index 359120163b3f..428cec6fbb0c 100644 --- a/src/sonic-py-common/tests/test_syslogger.py +++ b/src/sonic-py-common/tests/test_syslogger.py @@ -32,3 +32,70 @@ def test_notice_log(self, capsys): log.log_notice('this is a message') captured = capsys.readouterr() assert 'NOTICE' in captured.out + + def test_basic(self): + log = syslogger.SysLogger() + log.logger.log = mock.MagicMock() + log.log_error('error message') + log.log_warning('warning message') + log.log_notice('notice message') + log.log_info('info message') + log.log_debug('debug message') + log.log(logging.ERROR, 'error msg', also_print_to_console=True) + + def test_log_priority(self): + log = syslogger.SysLogger() + log.set_min_log_priority(logging.ERROR) + assert log.logger.level == logging.ERROR + + def test_log_priority_from_str(self): + log = syslogger.SysLogger() + assert log.log_priority_from_str('ERROR') == logging.ERROR + assert log.log_priority_from_str('INFO') == logging.INFO + assert log.log_priority_from_str('NOTICE') == logging.NOTICE + assert log.log_priority_from_str('WARN') == logging.WARN + assert log.log_priority_from_str('DEBUG') == logging.DEBUG + assert log.log_priority_from_str('invalid') == logging.NOTICE + + def test_log_priority_to_str(self): + log = syslogger.SysLogger() + assert log.log_priority_to_str(logging.NOTICE) == 'NOTICE' + assert log.log_priority_to_str(logging.INFO) == 'INFO' + assert log.log_priority_to_str(logging.DEBUG) == 'DEBUG' + assert log.log_priority_to_str(logging.WARN) == 'WARN' + assert log.log_priority_to_str(logging.ERROR) == 'ERROR' + assert log.log_priority_to_str(-1) == 'NOTICE' + + @mock.patch('swsscommon.swsscommon.SonicV2Connector') + def test_runtime_config(self, mock_connector): + mock_db = mock.MagicMock() + mock_db.get = mock.MagicMock(return_value='DEBUG') + mock_connector.return_value = mock_db + log1 = syslogger.SysLogger(log_identifier='log1', enable_runtime_config=True, log_level=logging.INFO) + assert 'log1' in syslogger.SysLogger.log_registry + assert log1.logger.level == logging.DEBUG + + mock_db.get.return_value = None + mock_db.hmset = mock.MagicMock() + log2 = syslogger.SysLogger(log_identifier='log2', enable_runtime_config=True, log_level=logging.INFO) + assert 'log2' in syslogger.SysLogger.log_registry + mock_db.hmset.assert_called_once() + + mock_db.get.return_value = 'ERROR' + ret, msg = syslogger.SysLogger.update_log_level() + assert ret + assert not msg + assert log1.logger.level == logging.ERROR + assert log2.logger.level == logging.ERROR + + @mock.patch('swsscommon.swsscommon.SonicV2Connector') + def test_runtime_config_negative(self, mock_connector): + mock_db = mock.MagicMock() + mock_db.get = mock.MagicMock(side_effect=Exception('')) + mock_connector.return_value = mock_db + syslogger.SysLogger(log_identifier='log', enable_runtime_config=True) + assert 'log' in syslogger.SysLogger.log_registry + + ret, msg = syslogger.SysLogger.update_log_level() + assert not ret + assert msg From f4d72ad50930abdf5fc72f78d3c10f2be0199838 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Mon, 29 Jul 2024 06:52:51 +0300 Subject: [PATCH 2/5] Remove lock --- .../sonic_py_common/syslogger.py | 58 +++++++++---------- 1 file changed, 27 insertions(+), 31 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/syslogger.py b/src/sonic-py-common/sonic_py_common/syslogger.py index 65e71dfcb98c..8968807706bc 100644 --- a/src/sonic-py-common/sonic_py_common/syslogger.py +++ b/src/sonic-py-common/sonic_py_common/syslogger.py @@ -3,7 +3,6 @@ import os import socket import sys -import threading CONFIG_DB = 'CONFIG_DB' FIELD_LOG_LEVEL = 'LOGLEVEL' @@ -22,7 +21,6 @@ class SysLogger: """ log_registry = {} - lock = threading.Lock() DEFAULT_LOG_FACILITY = SysLogHandler.LOG_USER DEFAULT_LOG_LEVEL = logging.NOTICE @@ -56,11 +54,10 @@ def register_for_runtime_config(self, log_identifier): Args: log_identifier (str): key of LOGGER table """ - with SysLogger.lock: - if log_identifier not in SysLogger.log_registry: - SysLogger.log_registry[log_identifier] = [self] - else: - SysLogger.log_registry[log_identifier].append(self) + if log_identifier not in SysLogger.log_registry: + SysLogger.log_registry[log_identifier] = [self] + else: + SysLogger.log_registry[log_identifier].append(self) from swsscommon import swsscommon try: @@ -85,30 +82,29 @@ def update_log_level(cls): Returns: tuple: (refresh result, fail reason) """ - with cls.lock: - if not cls.log_registry: - return True, '' - - from swsscommon import swsscommon - try: - config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) - config_db.connect(CONFIG_DB) - for log_identifier, log_instances in cls.log_registry.items(): - log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) - if log_level_in_db: - for log_instance in log_instances: - log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level_in_db)) - else: - for log_instance in log_instances: - data = { - FIELD_LOG_LEVEL: log_instance.log_priority_to_str(log_instance._min_log_level), - FIELD_REQUIRE_REFRESH: 'true' - } - config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) - break - return True, '' - except Exception as e: - return False, f'Failed to refresh log configuration - {e}' + if not cls.log_registry: + return True, '' + + from swsscommon import swsscommon + try: + config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) + config_db.connect(CONFIG_DB) + for log_identifier, log_instances in cls.log_registry.items(): + log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) + if log_level_in_db: + for log_instance in log_instances: + log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level_in_db)) + else: + for log_instance in log_instances: + data = { + FIELD_LOG_LEVEL: log_instance.log_priority_to_str(log_instance._min_log_level), + FIELD_REQUIRE_REFRESH: 'true' + } + config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) + break + return True, '' + except Exception as e: + return False, f'Failed to refresh log configuration - {e}' def log_priority_to_str(self, priority): """Convert log priority to string. From d81abd5af917201a3de918af552c4e2ba4357c27 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Wed, 31 Jul 2024 04:39:12 +0300 Subject: [PATCH 3/5] Fix review comments --- src/sonic-py-common/sonic_py_common/syslogger.py | 4 ++-- src/sonic-py-common/tests/test_syslogger.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/syslogger.py b/src/sonic-py-common/sonic_py_common/syslogger.py index 8968807706bc..b921f738691b 100644 --- a/src/sonic-py-common/sonic_py_common/syslogger.py +++ b/src/sonic-py-common/sonic_py_common/syslogger.py @@ -125,7 +125,7 @@ def log_priority_to_str(self, priority): return 'ERROR' else: self.log_error(f'Invalid log priority: {priority}') - return 'NOTICE' + return 'WARN' def log_priority_from_str(self, priority_in_str): """Convert log priority from string. @@ -146,7 +146,7 @@ def log_priority_from_str(self, priority_in_str): return logging.ERROR else: self.log_error(f'Invalid log priority string: {priority_in_str}') - return logging.NOTICE + return logging.WARNING def set_min_log_priority(self, priority): """ diff --git a/src/sonic-py-common/tests/test_syslogger.py b/src/sonic-py-common/tests/test_syslogger.py index 428cec6fbb0c..849d2c132bf5 100644 --- a/src/sonic-py-common/tests/test_syslogger.py +++ b/src/sonic-py-common/tests/test_syslogger.py @@ -55,7 +55,7 @@ def test_log_priority_from_str(self): assert log.log_priority_from_str('NOTICE') == logging.NOTICE assert log.log_priority_from_str('WARN') == logging.WARN assert log.log_priority_from_str('DEBUG') == logging.DEBUG - assert log.log_priority_from_str('invalid') == logging.NOTICE + assert log.log_priority_from_str('invalid') == logging.WARN def test_log_priority_to_str(self): log = syslogger.SysLogger() @@ -64,7 +64,7 @@ def test_log_priority_to_str(self): assert log.log_priority_to_str(logging.DEBUG) == 'DEBUG' assert log.log_priority_to_str(logging.WARN) == 'WARN' assert log.log_priority_to_str(logging.ERROR) == 'ERROR' - assert log.log_priority_to_str(-1) == 'NOTICE' + assert log.log_priority_to_str(-1) == 'WARN' @mock.patch('swsscommon.swsscommon.SonicV2Connector') def test_runtime_config(self, mock_connector): From 61c085394c76dbdab5787c6b2efd5423eea47e76 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Mon, 26 Aug 2024 05:10:59 +0300 Subject: [PATCH 4/5] Remove log_instances --- .../sonic_py_common/syslogger.py | 62 ++++--------------- src/sonic-py-common/tests/test_syslogger.py | 16 +---- 2 files changed, 14 insertions(+), 64 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/syslogger.py b/src/sonic-py-common/sonic_py_common/syslogger.py index b921f738691b..3d5449642cc4 100644 --- a/src/sonic-py-common/sonic_py_common/syslogger.py +++ b/src/sonic-py-common/sonic_py_common/syslogger.py @@ -19,18 +19,15 @@ class SysLogger: """ SysLogger class for Python applications using SysLogHandler """ - - log_registry = {} DEFAULT_LOG_FACILITY = SysLogHandler.LOG_USER DEFAULT_LOG_LEVEL = logging.NOTICE def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_level=DEFAULT_LOG_LEVEL, enable_runtime_config=False): - if log_identifier is None: - log_identifier = os.path.basename(sys.argv[0]) + self.log_identifier = log_identifier if log_identifier else os.path.basename(sys.argv[0]) # Initialize SysLogger - self.logger = logging.getLogger(log_identifier) + self.logger = logging.getLogger(self.log_identifier) # Reset all existing handlers for handler in self.logger.handlers[:]: @@ -44,26 +41,19 @@ def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_l self.set_min_log_priority(log_level) if enable_runtime_config: - self.register_for_runtime_config(log_identifier) - - def register_for_runtime_config(self, log_identifier): - """Register current log instance to log registry. If DB entry exists, - update log level according to DB configuration; otherwise, save current - log level to DB. + self.update_log_level() + + def update_log_level(self): + """Refresh log level. - Args: - log_identifier (str): key of LOGGER table - """ - if log_identifier not in SysLogger.log_registry: - SysLogger.log_registry[log_identifier] = [self] - else: - SysLogger.log_registry[log_identifier].append(self) - + Returns: + tuple: (refresh result, fail reason) + """ from swsscommon import swsscommon try: config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) config_db.connect(CONFIG_DB) - log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) + log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{self.log_identifier}', FIELD_LOG_LEVEL) if log_level_in_db: self.set_min_log_priority(self.log_priority_from_str(log_level_in_db)) else: @@ -71,37 +61,7 @@ def register_for_runtime_config(self, log_identifier): FIELD_LOG_LEVEL: self.log_priority_to_str(self._min_log_level), FIELD_REQUIRE_REFRESH: 'true' } - config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) - except Exception as e: - self.log_notice(f'DB is not available when initialize logger instance - {e}') - - @classmethod - def update_log_level(cls): - """Refresh log level for each log instances registered to cls.log_registry. - - Returns: - tuple: (refresh result, fail reason) - """ - if not cls.log_registry: - return True, '' - - from swsscommon import swsscommon - try: - config_db = swsscommon.SonicV2Connector(use_unix_socket_path=True) - config_db.connect(CONFIG_DB) - for log_identifier, log_instances in cls.log_registry.items(): - log_level_in_db = config_db.get(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', FIELD_LOG_LEVEL) - if log_level_in_db: - for log_instance in log_instances: - log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level_in_db)) - else: - for log_instance in log_instances: - data = { - FIELD_LOG_LEVEL: log_instance.log_priority_to_str(log_instance._min_log_level), - FIELD_REQUIRE_REFRESH: 'true' - } - config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{log_identifier}', data) - break + config_db.hmset(CONFIG_DB, f'{swsscommon.CFG_LOGGER_TABLE_NAME}|{self.log_identifier}', data) return True, '' except Exception as e: return False, f'Failed to refresh log configuration - {e}' diff --git a/src/sonic-py-common/tests/test_syslogger.py b/src/sonic-py-common/tests/test_syslogger.py index 849d2c132bf5..98d69ad972c2 100644 --- a/src/sonic-py-common/tests/test_syslogger.py +++ b/src/sonic-py-common/tests/test_syslogger.py @@ -71,22 +71,13 @@ def test_runtime_config(self, mock_connector): mock_db = mock.MagicMock() mock_db.get = mock.MagicMock(return_value='DEBUG') mock_connector.return_value = mock_db - log1 = syslogger.SysLogger(log_identifier='log1', enable_runtime_config=True, log_level=logging.INFO) - assert 'log1' in syslogger.SysLogger.log_registry - assert log1.logger.level == logging.DEBUG - - mock_db.get.return_value = None - mock_db.hmset = mock.MagicMock() - log2 = syslogger.SysLogger(log_identifier='log2', enable_runtime_config=True, log_level=logging.INFO) - assert 'log2' in syslogger.SysLogger.log_registry - mock_db.hmset.assert_called_once() + log = syslogger.SysLogger(log_identifier='log1', enable_runtime_config=True, log_level=logging.INFO) + assert log.logger.level == logging.DEBUG mock_db.get.return_value = 'ERROR' - ret, msg = syslogger.SysLogger.update_log_level() + ret, msg = log.update_log_level() assert ret assert not msg - assert log1.logger.level == logging.ERROR - assert log2.logger.level == logging.ERROR @mock.patch('swsscommon.swsscommon.SonicV2Connector') def test_runtime_config_negative(self, mock_connector): @@ -94,7 +85,6 @@ def test_runtime_config_negative(self, mock_connector): mock_db.get = mock.MagicMock(side_effect=Exception('')) mock_connector.return_value = mock_db syslogger.SysLogger(log_identifier='log', enable_runtime_config=True) - assert 'log' in syslogger.SysLogger.log_registry ret, msg = syslogger.SysLogger.update_log_level() assert not ret From 6bf8838a09d0f4e728e59a0fa1dbd109376bcfe8 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Tue, 27 Aug 2024 05:08:10 +0300 Subject: [PATCH 5/5] Fix ut issue --- src/sonic-py-common/tests/test_syslogger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/sonic-py-common/tests/test_syslogger.py b/src/sonic-py-common/tests/test_syslogger.py index 98d69ad972c2..35e0fd058606 100644 --- a/src/sonic-py-common/tests/test_syslogger.py +++ b/src/sonic-py-common/tests/test_syslogger.py @@ -84,8 +84,8 @@ def test_runtime_config_negative(self, mock_connector): mock_db = mock.MagicMock() mock_db.get = mock.MagicMock(side_effect=Exception('')) mock_connector.return_value = mock_db - syslogger.SysLogger(log_identifier='log', enable_runtime_config=True) + log = syslogger.SysLogger(log_identifier='log', enable_runtime_config=True) - ret, msg = syslogger.SysLogger.update_log_level() + ret, msg = log.update_log_level() assert not ret assert msg