Add log configuration handler to handle log level change in CONFIG DB

src/sonic-py-common/sonic_py_common/logger.py

@@ -1,6 +1,7 @@
 import os
 import sys
 import syslog
+from . import logger_config_handler
 
 """
 Logging functionality for SONiC Python applications
@@ -25,8 +26,14 @@ 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):
+
+    config_handler = logger_config_handler.LoggerConfigHandler()
+
+    def __init__(self, log_identifier=None,
+                       log_facility=DEFAULT_LOG_FACILITY,
+                       log_option=DEFAULT_LOG_OPTION,
+                       log_level=LOG_PRIORITY_NOTICE,
+                       enable_config_thread=False):
         self._syslog = syslog
 
         if log_identifier is None:
@@ -35,12 +42,63 @@ def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_o
         # Initialize syslog
         self._syslog.openlog(ident=log_identifier, logoption=log_option, facility=log_facility)
 
-        # Set the default minimum log priority to LOG_PRIORITY_NOTICE
-        self.set_min_log_priority(self.LOG_PRIORITY_NOTICE)
+        # Set the default log priority
+        self.set_min_log_priority(log_level)
+
+        Logger.config_handler.register(self, log_identifier, self.log_priority_to_str(log_level))
+
+        if enable_config_thread:
+            Logger.config_handler.start()
 
     def __del__(self):
         self._syslog.closelog()
 
+    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 == Logger.LOG_PRIORITY_NOTICE:
+            return 'NOTICE'
+        elif priority == Logger.LOG_PRIORITY_INFO:
+            return 'INFO'
+        elif priority == Logger.LOG_PRIORITY_DEBUG:
+            return 'DEBUG'
+        elif priority == Logger.LOG_PRIORITY_WARNING:
+            return 'WARN'
+        elif priority == Logger.LOG_PRIORITY_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 Logger.LOG_PRIORITY_DEBUG
+        elif priority_in_str == 'INFO':
+            return Logger.LOG_PRIORITY_INFO
+        elif priority_in_str == 'NOTICE':
+            return Logger.LOG_PRIORITY_NOTICE
+        elif priority_in_str == 'WARN':
+            return Logger.LOG_PRIORITY_WARNING
+        elif priority_in_str == 'ERROR':
+            return Logger.LOG_PRIORITY_ERROR
+        else:
+            self.log_error(f'Invalid log priority string: {priority_in_str}')
+            return Logger.LOG_PRIORITY_NOTICE
+
     #
     # Methods for setting minimum log priority
     #

src/sonic-py-common/sonic_py_common/logger_config_handler.py

@@ -0,0 +1,153 @@
+import queue
+import redis
+import time
+import threading
+
+CONFIG_DB = 4
+SUBSCRIBE_PATTERN = '__keyspace@4__:LOGGER|*'
+SUBSCRIBE_TIMEOUT = 1
+LOGGER_TABLE_NAME = 'LOGGER'
+LOGGER_FIELD_LEVEL = 'LOGLEVEL'
+TABLE_SEPARATOR = '|'
+MESSAGE_FIELD_CHANNEL = 'channel'
+MESSAGE_FIELD_DATA = 'data'
+MESSAGE_OP_HSET = 'hset'
+
+
+def format_table_key(db_name):
+    return '{}{}{}'.format(LOGGER_TABLE_NAME, TABLE_SEPARATOR, db_name)
+
+
+class LoggerConfigThread(threading.Thread):
+    def __init__(self):
+        super().__init__(daemon=True)
+        # queue to store logger instances that are pending registered
+        self.queue = queue.Queue()
+
+        # dict to store <db_key, log_instances>
+        self.log_registry = {}
+        self.running = False
+
+    def stop(self):
+        self.running = False
+
+    def run(self):
+        self.running = True
+        db = None
+
+        # Wait until DB is ready. Logger instance shall use default 
+        # log level before DB is ready.
+        while True:
+            if not self.running:
+                return
+            try:
+                # Cannot use redis related APIs defined in swsscommon because there is a potential
+                # issue in swsscommon.i which calls PyEval_RestoreThread in a C++ destructor.
+                # PyEval_RestoreThread may raise exception abi::__forced_unwind while python is
+                # exiting. C++ standard does not allow exception in a destructor and it would cause
+                # unexpected termination. A detailed explanation can be found in 
+                # PR description https://github.com/sonic-net/sonic-buildimage/pull/12255.
+                db = redis.Redis(db=4, encoding="utf-8", decode_responses=True)
+                pubsub = db.pubsub()
+                pubsub.psubscribe(SUBSCRIBE_PATTERN)
+                break
+            except:
+                time.sleep(5)
+                continue
+
+        while self.running:
+            # Process registered logger instance from the queue
+            while self.running:
+                try:
+                    item = self.queue.get_nowait()
+                    log_instance = item[0]
+                    db_key = item[1]
+                    default_level = item[2]
+                    table_key = format_table_key(db_key)
+                    log_level = db.hget(table_key, LOGGER_FIELD_LEVEL)
+                    if db_key not in self.log_registry:
+                        # register logger to DB if the db_key is new
+                        self.log_registry[db_key] = [log_instance]
+                        if not log_level:
+                            db.hset(table_key, LOGGER_FIELD_LEVEL, default_level)
+                    else:
+                        self.log_registry[db_key].append(log_instance)
+                    if log_level:
+                        log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level))
+                except queue.Empty:
+                    # no more registered logger instance, break the loop
+                    break
+
+            try:
+                message = pubsub.get_message()
+                if message:
+                    key = message[MESSAGE_FIELD_CHANNEL].split(':', 1)[1]
+                    db_name = key.split(TABLE_SEPARATOR)[1]
+                    op = message[MESSAGE_FIELD_DATA]
+
+                    if op != MESSAGE_OP_HSET or db_name not in self.log_registry:
+                        continue
+
+                    log_level = db.hget(key, LOGGER_FIELD_LEVEL)
+                    # update log level for all log instances with the given db_name
+                    for log_instance in self.log_registry[db_name]:
+                        log_instance.set_min_log_priority(log_instance.log_priority_from_str(log_level))
+                else:
+                    time.sleep(SUBSCRIBE_TIMEOUT)
+            except redis.exceptions.ConnectionError:
+                # redis server is done, exit
+                return
+
+
+class LoggerConfigHandler:
+    # global Logger configuration thread instance
+    log_config_thread = LoggerConfigThread()
+
+    # flag to indicate that log thread has started
+    log_thread_started = False
+
+    # lock to protect log_thread_started
+    log_thread_lock = threading.Lock()
+
+    @classmethod
+    def start(cls):
+        """Start logger configuration thread if it is not started yet
+        """
+        if not cls.log_thread_started:
+            with cls.log_thread_lock:
+                if not cls.log_thread_started:
+                    cls.log_config_thread.start()
+                    cls.log_thread_started = True
+
+    @classmethod
+    def stop(cls):
+        """Stop logger configuration thread, only used in UT
+        """
+        with cls.log_thread_lock:
+            if cls.log_thread_started:
+                cls.log_config_thread.stop()
+                cls.log_config_thread.join()
+                cls.reset()
+
+    @classmethod
+    def reset(cls):
+        """Reset logger configuration thread for multi-processing case.
+
+           Linux does not clone the thread while doing fork. In case user creates a sub process
+           and still want to set log level on fly, user must call this function before creating
+           logger instance.
+        """
+        cls.log_config_thread = LoggerConfigThread()
+        cls.log_thread_started = False
+
+    @classmethod
+    def register(cls, instance, db_key, default_level):
+        """Register logger instance. A new logger entry will be added to CONFIG DB LOGGER
+        table once logger configuration thread is started.
+
+        Args:
+            instance (object): logger instance.
+            db_key (str): key of LOGGER table. Usually use the log identifier as the key.
+            default_level (str): one of NOTICE, DEBUG, INFO, ERROR, WARNING.
+        """
+        cls.log_config_thread.queue.put((instance, db_key, default_level))

src/sonic-py-common/sonic_py_common/syslogger.py

@@ -3,16 +3,28 @@
 import os
 import socket
 import sys
+from . import logger_config_handler
+
+# customize python logging to support notice logger
+logging.NOTICE = logging.INFO + 1
+logging.addLevelName(logging.NOTICE, "NOTICE")
+SysLogHandler.priority_map['NOTICE'] = 'notice'
+
 
 class SysLogger:
     """
     SysLogger class for Python applications using SysLogHandler
     """
 
     DEFAULT_LOG_FACILITY = SysLogHandler.LOG_USER
-    DEFAULT_LOG_LEVEL = SysLogHandler.LOG_NOTICE
+    DEFAULT_LOG_LEVEL = logging.NOTICE
+
+    config_handler = logger_config_handler.LoggerConfigHandler()
 
-    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_config_thread=False):
         if log_identifier is None:
             log_identifier = os.path.basename(sys.argv[0])
 
@@ -29,6 +41,57 @@ def __init__(self, log_identifier=None, log_facility=DEFAULT_LOG_FACILITY, log_l
         self.logger.addHandler(handler)
 
         self.set_min_log_priority(log_level)
+
+        SysLogger.config_handler.register(self, log_identifier, self.log_priority_to_str(log_level))
+
+        if enable_config_thread:
+            SysLogger.config_handler.start()
+
+    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.NOTICE:
+            return 'NOTICE'
+        elif priority == logging.INFO:
+            return 'INFO'
+        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):
         """
@@ -53,7 +116,7 @@ def log_warning(self, msg, also_print_to_console=False):
         self.log(logging.WARNING, msg, also_print_to_console)
 
     def log_notice(self, msg, also_print_to_console=False):
-        self.log(logging.INFO, msg, also_print_to_console)
+        self.log(logging.NOTICE, msg, also_print_to_console)
 
     def log_info(self, msg, also_print_to_console=False):
         self.log(logging.INFO, msg, also_print_to_console)