Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix the issue of no INFO level syslog for caclmgrd #21291

Closed
wants to merge 3 commits into from

Conversation

ZhaohuiS
Copy link
Contributor

@ZhaohuiS ZhaohuiS commented Dec 27, 2024

Why I did it

Fix issue #21290

  1. No info level log found for systemctl caclmgrd service in syslog file in 202405 images, only warning log found in /var/log/syslog
  2. set_min_log_priority_info fuction doesn't work
Work item tracking
  • Microsoft ADO (number only):
    30611546

How I did it

After #17171, it added those log functions in daemon_base.py, actually, in those function, it didn't set priority, by default, it sets default level to NOTICE(https://github.com/sonic-net/sonic-buildimage/blame/9588a40abc27911a82aa2f116c17ce06c2cd7093/src/sonic-py-common/sonic_py_common/logger.py#L39), so even in log_info, without priority parameter, the default level is still NOTICE, the log which is printed with INFO level can't be printed into syslog.
Because both src/sonic-py-common/sonic_py_common/syslogger.py and src/sonic-py-common/sonic_py_common/logger.py implement these functions, we don't need to add those functions in daemon_base.py
The solution is remove them.
And by the way, in caclmgrd, it calls caclmgr.set_min_log_priority_info(), caclmgrd is an instance of DaemonBase whose parent class is Logger, set_min_log_priority_info both works for use_syslogger=True or use_syslogger=Flase in daemon_base.py init function.

  def log(self, priority, message, also_print_to_console=False):
        self.logger_instance.log(priority, message, also_print_to_console)

    def log_error(self, message, also_print_to_console=False):
        self.logger_instance.log_error(message, also_print_to_console)

    def log_warning(self, message, also_print_to_console=False):
        self.logger_instance.log_warning(message, also_print_to_console)

    def log_notice(self, message, also_print_to_console=False):
        self.logger_instance.log_notice(message, also_print_to_console)

    def log_info(self, message, also_print_to_console=False):
        self.logger_instance.log_info(message, also_print_to_console)

    def log_debug(self, message, also_print_to_console=False):
        self.logger_instance.log_debug(message, also_print_to_console)

https://github.com/sonic-net/sonic-buildimage/blame/9588a40abc27911a82aa2f116c17ce06c2cd7093/src/sonic-py-common/sonic_py_common/logger.py#L39

       # Set the default minimum log priority to LOG_PRIORITY_NOTICE
        self.set_min_log_priority(self.LOG_PRIORITY_NOTICE)

How to verify it

Test evidence:

from sonic_py_common import daemon_base

SYSLOG_IDENTIFIER = "TestSysLogger"
log3 = daemon_base.DaemonBase(SYSLOG_IDENTIFIER, use_syslogger=False)
log3.set_min_log_priority_info()

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, console", also_print_to_console=True)
log3.log_notice("log3: This is a notice message, console", also_print_to_console=True)
log3.log_warning("log3: This is a warning message,console", also_print_to_console=True)
log3.log_debug("log3: This is a debug message,console", also_print_to_console=True)
log3.log_error("log3: This is a error message,consle", also_print_to_console=True)

Console output:

log3: This is a info message, console
log3: This is a notice message, console
log3: This is a warning message,console
log3: This is a error message,consle

Syslog file output:

2025 Jan  6 10:16:49.077345 str2-7050cx3-acs-13 INFO TestSysLogger[723065]: log3: This is a info message
2025 Jan  6 10:16:49.077797 str2-7050cx3-acs-13 NOTICE TestSysLogger[723065]: log3: This is a notice message
2025 Jan  6 10:16:49.077910 str2-7050cx3-acs-13 WARNING TestSysLogger[723065]: log3: This is a warning message
2025 Jan  6 10:16:49.077994 str2-7050cx3-acs-13 ERR TestSysLogger[723065]: log3: This is a error message
2025 Jan  6 10:16:49.078074 str2-7050cx3-acs-13 INFO TestSysLogger[723065]: log3: This is a info message, console
2025 Jan  6 10:16:49.086310 str2-7050cx3-acs-13 NOTICE TestSysLogger[723065]: log3: This is a notice message, console
2025 Jan  6 10:16:49.086508 str2-7050cx3-acs-13 WARNING TestSysLogger[723065]: log3: This is a warning message,console
2025 Jan  6 10:16:49.086608 str2-7050cx3-acs-13 ERR TestSysLogger[723065]: log3: This is a error message,consle

set use_syslogger=True, same test results with use_syslogger=False.

Which release branch to backport (provide reason below if selected)

  • 201811
  • 201911
  • 202006
  • 202012
  • 202106
  • 202111
  • 202205
  • 202211
  • 202305
  • 202405

Tested branch (Please provide the tested image version)

Description for the changelog

Link to config_db schema for YANG module changes

A picture of a cute animal (not mandatory but encouraged)

Signed-off-by: Zhaohui Sun <zhaohuisun@microsoft.com>
@mssonicbld
Copy link
Collaborator

/azp run Azure.sonic-buildimage

Copy link

Azure Pipelines successfully started running 1 pipeline(s).

@ZhaohuiS
Copy link
Contributor Author

@Junchao-Mellanox
Why the issue happened in caclgmrd:

  1. caclmgrd inherited Logger class not SysLogger class before
  2. After Enable runtime config log level #19611, caclmgrd inherited SysLogger instead of Logger, because use_syslogger=True by default.
  3. Even caclmgr.set_min_log_priority_info() it sets min log priority to info, this function is in Logger class, SysLogger doesn't have this function. But DaemonBase still inherits Logger which implements set_min_log_priority_info, that's why even caclmgrd called this function, it didn't throw exception.
class DaemonBase(Logger):
    def __init__(self, log_identifier, use_syslogger=True, enable_runtime_log_config=False):
        super().__init__()
        if use_syslogger:
            self.logger_instance = SysLogger(log_identifier, enable_runtime_config=enable_runtime_log_config)
        else:
            self.logger_instance = Logger(
                log_identifier=log_identifier,
                log_facility=Logger.LOG_FACILITY_DAEMON,
                log_option=(Logger.LOG_OPTION_NDELAY | Logger.LOG_OPTION_PID)
            )
  1. How to fix it?

1). Change the default level to INFO instead of NOTICE, otherwise NOTICE will suppress all INFO level logs in SysLogger.
2). Implement set_min_log_priority_info those functions in SysLogger to support min priority level change.

@ZhaohuiS
Copy link
Contributor Author

@Junchao-Mellanox @xincunli-sonic could you please help review?

@Junchao-Mellanox
Copy link
Collaborator

Junchao-Mellanox commented Jan 2, 2025

Hi @ZhaohuiS , changing the default log level will affect many other daemons. I am not sure it is what we want. I suppose there are a few options:

  1. In cfgmgrd, set use_syslogger=False, or
  2. Fix daemonbase to support setting log level

@ZhaohuiS
Copy link
Contributor Author

ZhaohuiS commented Jan 2, 2025

Hi @ZhaohuiS , changing the default log level will affect many other daemons. I am not sure it is what we want. I suppose there are a few options:

  1. In cfgmgrd, set use_syslogger=False, or
  2. Fix daemonbase to support setting log level
    @Junchao-Mellanox
  1. By default, it chooses SysLogger, which is not consistent as before. caclmgrd is just one of them. Or suggest to set use_syslogger=False
  2. INFO is a default level in syslog. If you set default level to NOTICE, INFO will lost by default, which doesn't make sense. I strongly recommend to set it back to INFO, not NOTICE, which is a new one, probably not be aware of by others.

@Junchao-Mellanox
Copy link
Collaborator

Hi, I am ok with your first option. For the second one:

INFO is a default level in syslog. If you set default level to NOTICE, INFO will lost by default, which doesn't make sense. I strongly recommend to set it back to INFO, not NOTICE, which is a new one, probably not be aware of by others.

SONiC python logger default level is NOTICE since day 0, so, changing it will affect many other daemon, such as xcvrd, thermalctld, etc.

@ZhaohuiS ZhaohuiS requested a review from bingwang-ms January 6, 2025 05:36
@ZhaohuiS
Copy link
Contributor Author

ZhaohuiS commented Jan 6, 2025

@Junchao-Mellanox
Could you provide the evidence? From what I found, the default level is INFO. Please check:
https://docs.python.org/3/library/syslog.html
image

@Junchao-Mellanox
Copy link
Collaborator

Please check this line:

self.set_min_log_priority(self.LOG_PRIORITY_NOTICE)
. Please also review the history of this file.

Signed-off-by: Zhaohui Sun <zhaohuisun@microsoft.com>
@ZhaohuiS ZhaohuiS changed the title Set default syslog level to INFO instead of NOTICE Fix the issue of no INFO level syslog for caclmgrd Jan 6, 2025
@ZhaohuiS
Copy link
Contributor Author

ZhaohuiS commented Jan 6, 2025

@Junchao-Mellanox @xincunli-sonic could you please review it again?

@mssonicbld
Copy link
Collaborator

/azp run Azure.sonic-buildimage

Copy link

Azure Pipelines successfully started running 1 pipeline(s).

Signed-off-by: Zhaohui Sun <zhaohuisun@microsoft.com>
@mssonicbld
Copy link
Collaborator

/azp run Azure.sonic-buildimage

Copy link

Azure Pipelines successfully started running 1 pipeline(s).

@bingwang-ms
Copy link
Contributor

@xincunli-sonic Can you help review this change?

@ZhaohuiS
Copy link
Contributor Author

ZhaohuiS commented Jan 9, 2025

caclmgr.set_min_log_priority_info() it sets min log priority to info, this function is in Logger class, SysLogger doesn't have this function. But DaemonBase still inherits Logger which implements set_min_log_priority_info, that's why even caclmgrd called this function, it didn't throw exception. But it didn't make INFO level effect in SysLogger which is actually used in caclmgrd

Even change to use Logger by setting use_syslogger=False, it still doesn't work.
The root cause is that it added a new instance for logger, self.logger_instance, any instance inherited from DaemonBase class can't change the debug level, the level they changed is their own instance, not the self.logger_instance's level.

The current fix is still not valid. It forces to use log function from Logger class, which still doesn't make sense.
But it's very complicated to implement set_min_log_priority these functions in daemon_base.py, since SysLogger and Logger have total different level values.

For addressing no syslog issue for caclmgrd, fix it in the following PR:
sonic-net/sonic-host-services#200

There is still a problem for DaemonBase to set log level, track it in #21361

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants