From 077e3275b8d6208b0346322f1a2a7c3ac48a898a Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox <57339448+Junchao-Mellanox@users.noreply.github.com> Date: Sun, 27 Oct 2024 23:46:33 +0800 Subject: [PATCH] Enable runtime config log level (#19611) HLD link: sonic-net/SONiC#1522 - Why I did it SONiC provides two Python logger implementations: sonic_py_common.logger.Logger and sonic_py_common.syslogger.SysLogger. Both of them do not provide the ability to change log level at real time. Sometimes, in order to get more debug information, developer has to manually change the log level in code on a running switch and restart the Python daemon. This is not convenient. SONiC also provides a C/C++ logger implementation in sonic-platform-common.common.logger.cpp. This C/C++ logger implementation is also a wrapper of Linux standard syslog which is widely used by swss/syncd. It provides the ability to set log level on fly by starting a thread to listen to CONFIG DB LOGGER table change. SONiC infrastructure also provides the Python wrapper for sonic-platform-common.common.logger.cpp which is swsscommon.Logger. However, this logger implementation also has some drawbacks: swsscommon.Logger assumes redis DB is ready to connect. This is a valid assumption for swss/syncd. But it is not good for a Python logger implementation because some Python script may be called before redis server starting. swsscommon.Logger wraps Linux syslog which only support single log identifier for a daemon. So, swsscommon.Logger is not an option too. This PR is a Python logger enhancement which allows user setting log level at run time. - How I did it swsscommon.Logger depends on a thread to listen to CONFIG DB LOGGER table change. It refreshes log level for each logger instances once the thread detects a DB entry change. A thread is considered heavy in a python script, especially that there are many short and simple python scripts which also use logger. To keep python logger light weight, it uses a different design than swsscommon.Logger: A class level logger registry shall be added to SysLoggerclass Each logger instance shall register itself to logger register if enables runtime configuration Logger configuration shall be refreshed by CLI which send a SIGHUP signal to the daemon - How to verify it Manual test New unit test cases --- .../sonic_py_common/daemon_base.py | 4 +- .../sonic_py_common/syslogger.py | 80 ++++++++++++++++++- src/sonic-py-common/tests/test_syslogger.py | 57 +++++++++++++ 3 files changed, 135 insertions(+), 6 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..3d5449642cc4 100644 --- a/src/sonic-py-common/sonic_py_common/syslogger.py +++ b/src/sonic-py-common/sonic_py_common/syslogger.py @@ -4,6 +4,11 @@ import socket import sys +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 logging.addLevelName(logging.NOTICE, "NOTICE") @@ -18,12 +23,11 @@ class SysLogger: 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): - if log_identifier is None: - log_identifier = os.path.basename(sys.argv[0]) + def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_level=DEFAULT_LOG_LEVEL, enable_runtime_config=False): + 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[:]: @@ -35,6 +39,74 @@ 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.update_log_level() + + def update_log_level(self): + """Refresh log level. + + 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}|{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: + 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}|{self.log_identifier}', data) + 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 'WARN' + + 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.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 359120163b3f..35e0fd058606 100644 --- a/src/sonic-py-common/tests/test_syslogger.py +++ b/src/sonic-py-common/tests/test_syslogger.py @@ -32,3 +32,60 @@ 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.WARN + + 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) == 'WARN' + + @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 + 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 = log.update_log_level() + assert ret + assert not msg + + @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 + log = syslogger.SysLogger(log_identifier='log', enable_runtime_config=True) + + ret, msg = log.update_log_level() + assert not ret + assert msg