From edf88e66b2da42b3372ad026e77bcdf767df0cde Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Wed, 27 Sep 2023 12:26:52 +0300 Subject: [PATCH 01/10] Use swsscommon logger implementing python logger --- src/sonic-py-common/sonic_py_common/logger.py | 20 +++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index fa86221d6d..07bd1a4741 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -1,6 +1,7 @@ import os import sys import syslog +from swsscommon import swsscommon """ Logging functionality for SONiC Python applications @@ -26,20 +27,23 @@ class Logger(object): DEFAULT_LOG_FACILITY = LOG_FACILITY_USER DEFAULT_LOG_OPTION = LOG_OPTION_NDELAY - def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_option=DEFAULT_LOG_OPTION): - self._syslog = syslog - + def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_option=DEFAULT_LOG_OPTION, enable_set_log_level_on_fly=False): if log_identifier is None: log_identifier = os.path.basename(sys.argv[0]) # Initialize syslog - self._syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) + syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) + self._log = swsscommon.Logger.getInstance() # Set the default minimum log priority to LOG_PRIORITY_NOTICE self.set_min_log_priority(self.LOG_PRIORITY_NOTICE) + if enable_set_log_level_on_fly: + # Performance warning: linkToDbNative will potentially create a new thread. + # The thread listens to CONFIG DB for log level changes. + swsscommon.Logger.getInstance().linkToDbNative(log_identifier, 'NOTICE') def __del__(self): - self._syslog.closelog() + syslog.closelog() # # Methods for setting minimum log priority @@ -53,7 +57,7 @@ class Logger(object): Args: priority: The minimum priority at which to log messages """ - self._min_log_priority = priority + self._log.setMinPrio(priority) def set_min_log_priority_error(self): """ @@ -90,9 +94,9 @@ class Logger(object): # def log(self, priority, msg, also_print_to_console=False): - if self._min_log_priority >= priority: + if self._log.getMinPrio() >= priority: # Send message to syslog - self._syslog.syslog(priority, msg) + self._log.write(priority, msg) # Send message to console if also_print_to_console: From c9805776f920d56af1b24e4f7622082590b2fab0 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Thu, 23 Nov 2023 09:13:58 +0200 Subject: [PATCH 02/10] Add unit test for logger --- src/sonic-py-common/tests/logger_test.py | 45 ++++++++++++++++++++++++ 1 file changed, 45 insertions(+) create mode 100644 src/sonic-py-common/tests/logger_test.py diff --git a/src/sonic-py-common/tests/logger_test.py b/src/sonic-py-common/tests/logger_test.py new file mode 100644 index 0000000000..079120819b --- /dev/null +++ b/src/sonic-py-common/tests/logger_test.py @@ -0,0 +1,45 @@ +from unittest import mock +from sonic_py_common import logger + + +class TestLogger: + def test_log(self): + log = logger.Logger() + mock_log = mock.MagicMock() + mock_log.write = mock.MagicMock() + mock_log.getMinPrio.return_value = logger.Logger.LOG_PRIORITY_DEBUG + + log._log = mock_log + log.set_min_log_priority(logger.Logger.LOG_PRIORITY_DEBUG) + + log.log_debug('debug message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_DEBUG, 'debug message') + + log.log_info('info message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_INFO, 'info message') + + log.log_notice('notice message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_NOTICE, 'notice message') + + log.log_error('error message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_ERROR, 'error message') + + log.log_warning('warning message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_WARNING, 'warning message') + + mock_log.getMinPrio.return_value = logger.Logger.LOG_PRIORITY_INFO + mock_log.write.reset_mock() + log.log_debug('debug message') + mock_log.write.assert_not_called() + + log.log_info('info message', also_print_to_console=True) + log.log_info('info message') + mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_INFO, 'info message') + + def test_set_log_level(self): + log = logger.Logger() + log.set_min_log_priority_error() + log.set_min_log_priority_warning() + log.set_min_log_priority_notice() + log.set_min_log_priority_info() + log.set_min_log_priority_debug() From 274721640b33eef4f2d08a70654e3b53a5955b17 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Thu, 23 Nov 2023 09:48:54 +0200 Subject: [PATCH 03/10] Fix unit test for python 2 --- src/sonic-py-common/tests/logger_test.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/src/sonic-py-common/tests/logger_test.py b/src/sonic-py-common/tests/logger_test.py index 079120819b..432bf33c13 100644 --- a/src/sonic-py-common/tests/logger_test.py +++ b/src/sonic-py-common/tests/logger_test.py @@ -1,4 +1,12 @@ -from unittest import mock +import sys + +if sys.version_info.major == 3: + from unittest import mock +else: + # Expect the 'mock' package for python 2 + # https://pypi.python.org/pypi/mock + import mock + from sonic_py_common import logger From 0c30b1df119a615003088a5c840bfe213af6ed46 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Thu, 23 Nov 2023 11:25:53 +0200 Subject: [PATCH 04/10] Fix unit test failure for other daemon who depends on logger --- src/sonic-py-common/sonic_py_common/logger.py | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index 07bd1a4741..a8fa18a960 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -34,17 +34,31 @@ class Logger(object): # Initialize syslog syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) - self._log = swsscommon.Logger.getInstance() + self._log = self.get_log_instance() # Set the default minimum log priority to LOG_PRIORITY_NOTICE self.set_min_log_priority(self.LOG_PRIORITY_NOTICE) if enable_set_log_level_on_fly: # Performance warning: linkToDbNative will potentially create a new thread. # The thread listens to CONFIG DB for log level changes. - swsscommon.Logger.getInstance().linkToDbNative(log_identifier, 'NOTICE') + self._log.linkToDbNative(log_identifier, 'NOTICE') def __del__(self): syslog.closelog() + def get_log_instance(self): + if hasattr(swsscommon, 'Logger'): + return swsscommon.Logger.getInstance() + else: + # Workaround for unit test. In some SONiC Python package, it mocked swsscommon lib for unit test purpose, but it does not contain + # Logger class. To make those unit test happy, here provides a MagicMock object. + if sys.version_info.major == 3: + from unittest import mock + else: + # Expect the 'mock' package for python 2 + # https://pypi.python.org/pypi/mock + import mock + return mock.MagicMock() + # # Methods for setting minimum log priority # From 3d59feb2b10f0ba06f5374320ec47ba554d9e3f6 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Fri, 24 Nov 2023 04:10:15 +0200 Subject: [PATCH 05/10] Fix unit test issue --- src/sonic-py-common/sonic_py_common/logger.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index a8fa18a960..4594d3ccf9 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -57,7 +57,9 @@ class Logger(object): # Expect the 'mock' package for python 2 # https://pypi.python.org/pypi/mock import mock - return mock.MagicMock() + instance = mock.MagicMock() + instance.getMinPrio.return_value = self.LOG_PRIORITY_NOTICE + return instance # # Methods for setting minimum log priority From 4b26a2183a3db91c823dd887af3c98768d290e11 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Fri, 1 Dec 2023 10:00:37 +0000 Subject: [PATCH 06/10] Improve import --- src/sonic-py-common/sonic_py_common/logger.py | 39 ++++++++++--------- 1 file changed, 20 insertions(+), 19 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index 4594d3ccf9..a7bdac6c72 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -1,7 +1,23 @@ import os import sys import syslog -from swsscommon import swsscommon +try: + from swsscommon.swsscommon import Logger +except ImportError: + # Workaround for unit test. In some SONiC Python package, it mocked + # swsscommon lib for unit test purpose, but it does not contain Logger + # class. To make those unit test happy, here provides a MagicMock object. + if sys.version_info.major == 3: + from unittest import mock + else: + # Expect the 'mock' package for python 2 + # https://pypi.python.org/pypi/mock + import mock + Logger = mock.MagicMock() + instance = mock.MagicMock() + Logger.getInstance = instance + instance.getMinPrio.return_value = syslog.LOG_NOTICE + """ Logging functionality for SONiC Python applications @@ -27,14 +43,15 @@ class Logger(object): DEFAULT_LOG_FACILITY = LOG_FACILITY_USER DEFAULT_LOG_OPTION = LOG_OPTION_NDELAY - def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_option=DEFAULT_LOG_OPTION, enable_set_log_level_on_fly=False): + def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_option=DEFAULT_LOG_OPTION, + enable_set_log_level_on_fly=False): if log_identifier is None: log_identifier = os.path.basename(sys.argv[0]) # Initialize syslog syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) - self._log = self.get_log_instance() + self._log = Logger.getInstance() # Set the default minimum log priority to LOG_PRIORITY_NOTICE self.set_min_log_priority(self.LOG_PRIORITY_NOTICE) if enable_set_log_level_on_fly: @@ -45,22 +62,6 @@ class Logger(object): def __del__(self): syslog.closelog() - def get_log_instance(self): - if hasattr(swsscommon, 'Logger'): - return swsscommon.Logger.getInstance() - else: - # Workaround for unit test. In some SONiC Python package, it mocked swsscommon lib for unit test purpose, but it does not contain - # Logger class. To make those unit test happy, here provides a MagicMock object. - if sys.version_info.major == 3: - from unittest import mock - else: - # Expect the 'mock' package for python 2 - # https://pypi.python.org/pypi/mock - import mock - instance = mock.MagicMock() - instance.getMinPrio.return_value = self.LOG_PRIORITY_NOTICE - return instance - # # Methods for setting minimum log priority # From 50eff3c09748111d964a37c4b8a70425e8a913aa Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Wed, 6 Dec 2023 05:52:57 +0200 Subject: [PATCH 07/10] Fix UT --- src/sonic-py-common/sonic_py_common/logger.py | 8 ++++---- src/sonic-py-common/tests/logger_test.py | 2 ++ 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index a7bdac6c72..7b799d47bf 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -2,7 +2,7 @@ import os import sys import syslog try: - from swsscommon.swsscommon import Logger + from swsscommon.swsscommon import Logger as SwssLogger except ImportError: # Workaround for unit test. In some SONiC Python package, it mocked # swsscommon lib for unit test purpose, but it does not contain Logger @@ -13,9 +13,9 @@ except ImportError: # Expect the 'mock' package for python 2 # https://pypi.python.org/pypi/mock import mock - Logger = mock.MagicMock() + SwssLogger = mock.MagicMock() instance = mock.MagicMock() - Logger.getInstance = instance + SwssLogger.getInstance = instance instance.getMinPrio.return_value = syslog.LOG_NOTICE @@ -51,7 +51,7 @@ class Logger(object): # Initialize syslog syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) - self._log = Logger.getInstance() + self._log = SwssLogger.getInstance() # Set the default minimum log priority to LOG_PRIORITY_NOTICE self.set_min_log_priority(self.LOG_PRIORITY_NOTICE) if enable_set_log_level_on_fly: diff --git a/src/sonic-py-common/tests/logger_test.py b/src/sonic-py-common/tests/logger_test.py index 432bf33c13..1a5ed5df45 100644 --- a/src/sonic-py-common/tests/logger_test.py +++ b/src/sonic-py-common/tests/logger_test.py @@ -11,6 +11,7 @@ from sonic_py_common import logger class TestLogger: + @mock.patch('sonic_py_common.logger.SwssLogger.getInstance', mock.MagicMock()) def test_log(self): log = logger.Logger() mock_log = mock.MagicMock() @@ -44,6 +45,7 @@ class TestLogger: log.log_info('info message') mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_INFO, 'info message') + @mock.patch('sonic_py_common.logger.SwssLogger.getInstance', mock.MagicMock()) def test_set_log_level(self): log = logger.Logger() log.set_min_log_priority_error() From f9920345d8c658066507768aa99632655498dfbe Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Wed, 6 Dec 2023 11:50:24 +0200 Subject: [PATCH 08/10] Fix ut issue --- src/sonic-py-common/sonic_py_common/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index 7b799d47bf..7013cf5f4a 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -15,7 +15,7 @@ except ImportError: import mock SwssLogger = mock.MagicMock() instance = mock.MagicMock() - SwssLogger.getInstance = instance + SwssLogger.getInstance.return_value = instance instance.getMinPrio.return_value = syslog.LOG_NOTICE From 2050135bf1185e45b501ba87577f593567f96e49 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox Date: Tue, 12 Dec 2023 11:07:10 +0200 Subject: [PATCH 09/10] Fix build issue --- src/sonic-py-common/sonic_py_common/logger.py | 52 ++++++++++--------- src/sonic-py-common/tests/logger_test.py | 4 +- 2 files changed, 29 insertions(+), 27 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index 7013cf5f4a..2c44b9d7ac 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -1,23 +1,6 @@ import os import sys import syslog -try: - from swsscommon.swsscommon import Logger as SwssLogger -except ImportError: - # Workaround for unit test. In some SONiC Python package, it mocked - # swsscommon lib for unit test purpose, but it does not contain Logger - # class. To make those unit test happy, here provides a MagicMock object. - if sys.version_info.major == 3: - from unittest import mock - else: - # Expect the 'mock' package for python 2 - # https://pypi.python.org/pypi/mock - import mock - SwssLogger = mock.MagicMock() - instance = mock.MagicMock() - SwssLogger.getInstance.return_value = instance - instance.getMinPrio.return_value = syslog.LOG_NOTICE - """ Logging functionality for SONiC Python applications @@ -51,16 +34,37 @@ class Logger(object): # Initialize syslog syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) - self._log = SwssLogger.getInstance() - # Set the default minimum log priority to LOG_PRIORITY_NOTICE - self.set_min_log_priority(self.LOG_PRIORITY_NOTICE) + self._logger = None + if enable_set_log_level_on_fly: # Performance warning: linkToDbNative will potentially create a new thread. # The thread listens to CONFIG DB for log level changes. - self._log.linkToDbNative(log_identifier, 'NOTICE') + self.logger.linkToDbNative(log_identifier, 'NOTICE') def __del__(self): syslog.closelog() + + @property + def logger(self): + if self._logger is None: + try: + from swsscommon.swsscommon import Logger as SwssLogger + except ImportError: + # Workaround for unit test. In some SONiC Python package, it mocked + # swsscommon lib for unit test purpose, but it does not contain Logger + # class. To make those unit test happy, here provides a MagicMock object. + if sys.version_info.major == 3: + from unittest import mock + else: + # Expect the 'mock' package for python 2 + # https://pypi.python.org/pypi/mock + import mock + SwssLogger = mock.MagicMock() + instance = mock.MagicMock() + SwssLogger.getInstance.return_value = instance + instance.getMinPrio.return_value = syslog.LOG_NOTICE + self._logger = SwssLogger.getInstance() + return self._logger # # Methods for setting minimum log priority @@ -74,7 +78,7 @@ class Logger(object): Args: priority: The minimum priority at which to log messages """ - self._log.setMinPrio(priority) + self.logger.setMinPrio(priority) def set_min_log_priority_error(self): """ @@ -111,9 +115,9 @@ class Logger(object): # def log(self, priority, msg, also_print_to_console=False): - if self._log.getMinPrio() >= priority: + if self.logger.getMinPrio() >= priority: # Send message to syslog - self._log.write(priority, msg) + self.logger.write(priority, msg) # Send message to console if also_print_to_console: diff --git a/src/sonic-py-common/tests/logger_test.py b/src/sonic-py-common/tests/logger_test.py index 1a5ed5df45..5003844e66 100644 --- a/src/sonic-py-common/tests/logger_test.py +++ b/src/sonic-py-common/tests/logger_test.py @@ -11,14 +11,13 @@ from sonic_py_common import logger class TestLogger: - @mock.patch('sonic_py_common.logger.SwssLogger.getInstance', mock.MagicMock()) def test_log(self): log = logger.Logger() mock_log = mock.MagicMock() mock_log.write = mock.MagicMock() mock_log.getMinPrio.return_value = logger.Logger.LOG_PRIORITY_DEBUG - log._log = mock_log + log._logger = mock_log log.set_min_log_priority(logger.Logger.LOG_PRIORITY_DEBUG) log.log_debug('debug message') @@ -45,7 +44,6 @@ class TestLogger: log.log_info('info message') mock_log.write.assert_called_with(logger.Logger.LOG_PRIORITY_INFO, 'info message') - @mock.patch('sonic_py_common.logger.SwssLogger.getInstance', mock.MagicMock()) def test_set_log_level(self): log = logger.Logger() log.set_min_log_priority_error() From c027fefc175e8b623ce676bdd0df24d7ac5c7a28 Mon Sep 17 00:00:00 2001 From: Junchao-Mellanox <57339448+Junchao-Mellanox@users.noreply.github.com> Date: Fri, 29 Dec 2023 11:39:08 +0800 Subject: [PATCH 10/10] Lazy start log level thread --- src/sonic-py-common/sonic_py_common/logger.py | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/sonic-py-common/sonic_py_common/logger.py b/src/sonic-py-common/sonic_py_common/logger.py index 2c44b9d7ac..5a8aeaa173 100644 --- a/src/sonic-py-common/sonic_py_common/logger.py +++ b/src/sonic-py-common/sonic_py_common/logger.py @@ -27,20 +27,20 @@ class Logger(object): DEFAULT_LOG_OPTION = LOG_OPTION_NDELAY def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_option=DEFAULT_LOG_OPTION, - enable_set_log_level_on_fly=False): + enable_set_log_level_on_fly=False, db_name=None): if log_identifier is None: log_identifier = os.path.basename(sys.argv[0]) + if db_name is None: + self.db_name = log_identifier + else: + self.db_name = db_name + self.enable_set_log_level_on_fly = enable_set_log_level_on_fly # Initialize syslog syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility) self._logger = None - if enable_set_log_level_on_fly: - # Performance warning: linkToDbNative will potentially create a new thread. - # The thread listens to CONFIG DB for log level changes. - self.logger.linkToDbNative(log_identifier, 'NOTICE') - def __del__(self): syslog.closelog() @@ -64,6 +64,10 @@ class Logger(object): SwssLogger.getInstance.return_value = instance instance.getMinPrio.return_value = syslog.LOG_NOTICE self._logger = SwssLogger.getInstance() + if self.enable_set_log_level_on_fly: + # Performance warning: linkToDbNative will potentially create a new thread. + # The thread listens to CONFIG DB for log level changes. + self._logger.linkToDbNative(self.db_name, 'NOTICE') return self._logger #