sonic-buildimage Add SysLogger for new implementation.

trafficstars

Summary This PR introduces the SysLogger to address an issue where the original Logger.py could override the SYSLOG_IDENTIFIER if a new Logger instance is created.
Why I did it? This change was made because the SysLog was displaying NOTICE pmon#CCmisApi: instead of NOTICE pmon#ycable:. This discrepancy led to confusion during debugging and incorrect component identification in log analysis.
How I did it I implemented an instance-level syslog using the logging.handlers module to prevent the SYSLOG_IDENTIFIER from being overridden.
How did you verify/test it?

Run code snippet

import SysLogger
from daemon_base import DaemonBase

# 1. SysLogger
SYSLOG_IDENTIFIER = "TestSysLogger"

# Global logger instance
log = SysLogger.SysLogger(SYSLOG_IDENTIFIER)

log.log_info("This is a info message")
log.log_notice("This is a notice message")
log.log_warning("This is a warning message")
log.log_debug("This is a debug message")
log.log_error("This is a error message")

log.log_info("This is a info message", also_print_to_console=True)
log.log_notice("This is a notice message", also_print_to_console=True)
log.log_warning("This is a warning message", also_print_to_console=True)
log.log_debug("This is a debug message", also_print_to_console=True)
log.log_error("This is a error message", also_print_to_console=True)


# 2. Daemonbase with default syslog.

log2 = DaemonBase(SYSLOG_IDENTIFIER)

log2.log_info("log2: This is a info message")
log2.log_notice("log2: This is a notice message")
log2.log_warning("log2: This is a warning message")
log2.log_debug("log2: This is a debug message")
log2.log_error("log2: This is a error message")

log2.log_info("log2: This is a info message", also_print_to_console=True)
log2.log_notice("log2: This is a notice message", also_print_to_console=True)
log2.log_warning("log2: This is a warning message", also_print_to_console=True)
log2.log_debug("log2: This is a debug message", also_print_to_console=True)
log2.log_error("log2: This is a error message", also_print_to_console=True)

# 3. Daemonbase with SysLogger.

log3 = DaemonBase(SYSLOG_IDENTIFIER, use_syslogger=True)

log3.log_info("log3: This is a info message")
log3.log_notice("log3: This is a notice message")
log3.log_warning("log3: This is a warning message")
log3.log_debug("log3: This is a debug message")
log3.log_error("log3: This is a error message")

log3.log_info("log3: This is a info message", also_print_to_console=True)
log3.log_notice("log3: This is a notice message", also_print_to_console=True)
log3.log_warning("log3: This is a warning message", also_print_to_console=True)
log3.log_debug("log3: This is a debug message", also_print_to_console=True)
log3.log_error("log3: This is a error message", also_print_to_console=True)

Sample output

Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a info message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a error message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a info message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: This is a error message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a error message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger[967382]: log2: This is a error message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a info message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a error message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a info message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a notice message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a warning message
Jan  5 20:28:18 xincun-dev-vm TestSysLogger: log3: This is a error message

Which release branch to backport (provide reason below if selected)
[x] 202205
[x] 202305

Signed-off-by: Xincun Li [email protected]

Nov 14 '23 20:11 xincunli-sonic

@nazariig could you help review?

Nov 15 '23 15:11 prgeor

/azp run

Feb 13 '24 23:02 bingwang-ms

Commenter does not have sufficient privileges for PR 17171 in repo sonic-net/sonic-buildimage

Feb 13 '24 23:02 azure-pipelines[bot]

/azp run Azure.sonic-buildimage

Feb 13 '24 23:02 qiluo-msft

Azure Pipelines successfully started running 1 pipeline(s).

Feb 13 '24 23:02 azure-pipelines[bot]

What is the performance impaction of this change? Could you provide test data?

Mar 13 '24 02:03 Junchao-Mellanox

In XCVRD, there is a global logger instance, and there are also daemons. After your change, global logger instance will use log class Logger, daemons will use new log class "SysLogger". Will they affect each other?

Mar 13 '24 02:03 Junchao-Mellanox

I did some simple test with this new logger class. I found a few issues:

SysLogger.log_xxx does not work. It is probably caused by wrong log level used in the new log class. For example, "SysLogHandler.LOG_ERR" is used for log_error. I guess we should not use it, but "logging.ERROR". (the same issue with INFO, NOTICE, WARNING). My test:

if __name__ == "__main__":
    log1 = SysLogger(log_identifier="test1")
    log1.log_error("from log1")    #  DOES NOT WORK
    log1.logger.error('error')         # WORK
    log1.log(logging.ERROR, "also work")  # WORK

the new logger class cannot display hostname correctly. It only displays "localhost" instead of real hostname. I did not dig into it too much, no root cause found yet. (But it seems your example displays hostname correctly, did you do anything extra)

With old logger class, the message:
Mar 13 03:54:35.213887 sonic ERR test1: from log1

With new logger class, the message:
Mar 13 03:54:35.213887 localhost ERR test1: from log1

My test code:

import os
import sys
import logging
from logging.handlers import SysLogHandler


class SysLogger:
    """
    SysLogger class for Python applications using SysLogHandler
    """

    DEFAULT_LOG_FACILITY = SysLogHandler.LOG_USER
    DEFAULT_LOG_LEVEL = SysLogHandler.LOG_INFO

    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])

        # Initialize SysLogger
        self.logger = logging.getLogger(log_identifier)

        # Reset all existing handlers
        for handler in self.logger.handlers[:]:
            self.logger.removeHandler(handler)

        handler = SysLogHandler(facility=log_facility)
        formatter = logging.Formatter("%(name)s: %(message)s")
        handler.setFormatter(formatter)
        self.logger.addHandler(handler)

        self.set_min_log_priority(log_level)

    def set_min_log_priority(self, priority):
        """
        Sets the minimum log priority level. All log messages
        with a priority lower than this will not be logged
        """
        self._min_log_level = priority
        self.logger.setLevel(priority)

    # Methods for logging messages
    def log(self, priority, msg, also_print_to_console=False):
        self.logger.log(priority, msg)

        if also_print_to_console:
            print(msg)

    # Convenience methods
    def log_error(self, msg, also_print_to_console=False):
        self.log(SysLogHandler.LOG_ERR, msg, also_print_to_console)

    def log_warning(self, msg, also_print_to_console=False):
        self.log(SysLogHandler.LOG_WARNING, msg, also_print_to_console)

    def log_notice(self, msg, also_print_to_console=False):
        self.log(SysLogHandler.LOG_NOTICE, msg, also_print_to_console)

    def log_info(self, msg, also_print_to_console=False):
        self.log(SysLogHandler.LOG_INFO, msg, also_print_to_console)

    def log_debug(self, msg, also_print_to_console=False):
        self.log(SysLogHandler.LOG_DEBUG, msg, also_print_to_console)


if __name__ == "__main__":
    log1 = SysLogger(log_identifier="test1")
    log1.log_error("from log1")    #  DOES NOT WORK
    log1.logger.error('error')         # WORK
    log1.log(logging.ERROR, "also work")  # WORK

SONiC Version: 202305

Mar 13 '24 03:03 Junchao-Mellanox

Hi @xincunli-sonic ,

I checked your latest code. It seems the host name issue has been fixed. But the following issue is still there:

SysLogger.log_xxx does not work. It is probably caused by wrong log level used in the new log class. For example, "SysLogHandler.LOG_ERR" is used for log_error. I guess we should not use it, but "logging.ERROR". (the same issue with INFO, NOTICE, WARNING). My test:

if __name__ == "__main__":
    log1 = SysLogger(log_identifier="test1")
    log1.log_error("from log1")    #  DOES NOT WORK
    log1.logger.error('error')         # WORK
    log1.log(logging.ERROR, "also work")  # WORK

Apr 15 '24 03:04 Junchao-Mellanox

/azpw run

Apr 23 '24 18:04 xincunli-sonic

/AzurePipelines run

Apr 23 '24 18:04 mssonicbld

Azure Pipelines successfully started running 1 pipeline(s).

Apr 23 '24 18:04 azure-pipelines[bot]

/azpw run

May 01 '24 16:05 xincunli-sonic

/AzurePipelines run

May 01 '24 16:05 mssonicbld

Azure Pipelines successfully started running 1 pipeline(s).

May 01 '24 16:05 azure-pipelines[bot]

/azpw run

May 02 '24 00:05 xincunli-sonic

/AzurePipelines run

May 02 '24 00:05 mssonicbld

Azure Pipelines successfully started running 1 pipeline(s).

May 02 '24 00:05 azure-pipelines[bot]

/azpw run

May 02 '24 17:05 xincunli-sonic

/AzurePipelines run

May 02 '24 17:05 mssonicbld

Azure Pipelines successfully started running 1 pipeline(s).

May 02 '24 17:05 azure-pipelines[bot]

@xincunli-sonic could you please help to prioritize this PR feedback and checkers? this infra is required for additional PR related here as well and we should have it on 202405

May 06 '24 06:05 liat-grozovik

Hi @xincunli-sonic , I suppose the checker failure is related to the code change. The unit test tried to connect to a unix socket of a logger server, but the unix socket does not exist.

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.11/logging/handlers.py", line 1007, in emit
    self.socket.send(msg)
OSError: [Errno 9] Bad file descriptor

May 06 '24 08:05 Junchao-Mellanox

Hi @prgeor , could you please kindly review this?

May 09 '24 01:05 Junchao-Mellanox

@liat-grozovik can you merge?

May 15 '24 00:05 prgeor

i removed the backport ask for old branches as 202205 and 202305. if this is must lets discuss. i assume this is not needed for 202311 as well.

May 15 '24 05:05 liat-grozovik

sonic-buildimage sonic-buildimage copied to clipboard

Add SysLogger for new implementation.

sonic-buildimage
sonic-buildimage copied to clipboard