Python logger enhancement to support setting log level at real time #1522

Junchao-Mellanox · 2023-11-28T10:08:13Z

Overview

SONiC provides a Python logger implementation in sonic_py_common.logger.Logger. This implementation is a simple wrapper of Python standard package syslog. It does 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 PR introduces an enhancement to allow user setting log level on fly.

PR

PR title	state	context
[sonic-buildimage] Enable runtime config log level
[sonic-utilities] Add a command to update log level and refresh configuration

liat-grozovik · 2023-12-14T09:44:37Z

@prgeor appreciate your feedback on the HLD

doc/syslog/python-logger-enhancement.md

liat-grozovik · 2024-02-12T13:56:48Z

@prgeor could you please refer to the latest doc following feedback and see if additional comments available?
@keboliu can you confirm all relevant PRs are tagged on this PR description?

prgeor · 2024-02-14T21:28:35Z

@prgeor could you please refer to the latest doc following feedback and see if additional comments available? @keboliu can you confirm all relevant PRs are tagged on this PR description?

@liat-grozovik ack

prgeor · 2024-02-15T01:04:52Z

@Junchao-Mellanox There is one flaw with existing implementation of Logging in sonic_py_common/logger.py where syslog() call impacts all the daemons running in the container. To understand what I am saying, take a look at this PR which is trying to fix this https://github.com/sonic-net/sonic-buildimage/pull/17171/files

We need log level which is local to that daemon which is logging. The existing Logger implementation pollutes the log identifier of other daemons as well.

Junchao-Mellanox · 2024-04-15T01:39:44Z

Hi @liat-grozovik,

This PR is pending on PR sonic-net/sonic-buildimage#17171 which is handled by @xincunli-sonic . For PR 17171, we have one open item:

log message always contain "localhost" instead of real hostname.

For this item, I can always reproduce on my side, but Xincun cannot reproduce on his side. So, I requested a debug session with him this week. I am waiting for his response.

liat-grozovik · 2024-05-22T15:40:54Z

thanks @Junchao-Mellanox for keeping handling it. now that the pending PR is merged, i assume you need new PR on top of it. once you have please update the PR description with the new code PR instead of the closed one.

@prgeor can we get your approval for the HLD?

prgeor · 2024-05-22T15:47:50Z

thanks @Junchao-Mellanox for keeping handling it. now that the pending PR is merged, i assume you need new PR on top of it. once you have please update the PR description with the new code PR instead of the closed one.

@prgeor can we get your approval for the HLD?

@liat-grozovik reviewing

prgeor · 2024-05-22T15:53:22Z

doc/syslog/python-logger-enhancement.md

+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:
+
+
+1. `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.


@Junchao-Mellanox How are you overcoming this limitation? I see that you are still writing to the DB which means redis server needs to be running

To overcome it, the implementation will:

At the beginning of the thread function, it will wait until redis is up. If the connect to redis fails, it will silently ignore the connection error and retry in 5 seconds.

In the while loop of thread function, catch connection error while reading from redis

prgeor

@Junchao-Mellanox to keep things simple, we an make use of config_db logger table for user to configure the log level for debugging purpose like below:-

 "LOGGER": {
            "xcvrd": {
                "LOGLEVEL": "DEBUG",
                "LOGOUTPUT": "SYSLOG"
            },

Use the Identifier specified in syslogger to fetch the current log level from config DB
For eg. The identfier could be Xcvrd, CmisMgr, StateUpdateTask etc.

The advantage is we don't need to create extra threads for handling this

Reading redis DB is not a costly affair

This would limit the change to syslogger

Please note, logger.py will be deprecated over time as its usage causes confusion and because of which we introduced syslogger

prgeor · 2024-05-22T16:38:59Z

@Junchao-Mellanox one main advantage of the above approach is enabling logging at module level. For eg. Xcvrd common or main thread can have one SysLogger("Xcvrd") instance for eg. CMIS mgr may have another SysLogger("CmisMgr") instance. The logging can be enabled per module within the same thread/process

Junchao-Mellanox · 2024-05-23T01:10:31Z

@Junchao-Mellanox to keep things simple, we an make use of config_db logger table for user to configure the log level for debugging purpose like below:-
 "LOGGER": {
            "xcvrd": {
                "LOGLEVEL": "DEBUG",
                "LOGOUTPUT": "SYSLOG"
            },
Use the Identifier specified in syslogger to fetch the current log level from config DB For eg. The identfier could be Xcvrd, CmisMgr, StateUpdateTask etc.

The advantage is we don't need to create extra threads for handling this

Reading redis DB is not a costly affair

This would limit the change to syslogger

Please note, logger.py will be deprecated over time as its usage causes confusion and because of which we introduced syslogger

Hi @prgeor , this is exactly the implementation will do.

Junchao-Mellanox · 2024-05-23T01:11:12Z

@Junchao-Mellanox one main advantage of the above approach is enabling logging at module level. For eg. Xcvrd common or main thread can have one SysLogger("Xcvrd") instance for eg. CMIS mgr may have another SysLogger("CmisMgr") instance. The logging can be enabled per module within the same thread/process

Totally agree. And this is exactly my implementation plan.

prgeor · 2024-05-30T01:44:35Z

@Junchao-Mellanox one main advantage of the above approach is enabling logging at module level. For eg. Xcvrd common or main thread can have one SysLogger("Xcvrd") instance for eg. CMIS mgr may have another SysLogger("CmisMgr") instance. The logging can be enabled per module within the same thread/process

Totally agree. And this is exactly my implementation plan.

@Junchao-Mellanox why do we need a thread?

prgeor · 2024-06-11T05:10:02Z

doc/syslog/python-logger-enhancement.md

+- "-l": log level. One of "DEBUG", "INFO", "NOTICE", "WARN", "ERROR"
+- "--service": container name. Optional. The signal will be sent to that container if present.
+- "--program": program name. Optional, only applicable when --service is present. The signal will be sent to that program running in the service.
+- "--pid": process ID. Optional. If --service is present, the signal will be sent to the PID running in the service; otherwise, the signal will be send to the PID running in host side.


@Junchao-Mellanox if user does not specify the optional argument --service, then also this will work?

If --service is not present, the command will try to send the signal to host side process which has the pid equals to --pid

prgeor · 2024-06-12T01:45:31Z

doc/syslog/python-logger-enhancement.md

+# Update the log level without refresh the configuration
+config syslog level -c xcvrd -l DEBUG
+
+# Update the log level and send SIGHUP to xcvrd running in PMON
+config syslog level -c xcvrd -l DEBUG --service pmon --program xcvrd
+
+# Update the log level and send SIGHUP to PID 20 running in PMON
+config syslog level -c xcvrd -l DEBUG --service pmon --pid 20
+
+# Update the log level and send SIGHUP to PID 20 running in host
+config syslog level -c xcvrd -l DEBUG --pid 20
+
+# Send SIGHUP to xcvrd running in PMON without update log level
+config syslog level --service pmon --program xcvrd
+
+# Send SIGHUP to PID 20 running in PMON without update log level
+config syslog level --service pmon --pid 20
+
+# Send SIGHUP to PID 20 running in host without update log level
+config syslog level --pid 20
+
+# Invalid, --program must be used together with --service
+config syslog level --program xcvrd
+


@Junchao-Mellanox can we have option signal instead of level to send signal?

Hi @prgeor , the requirement is to have one single command which update log level and make it effect, so, I have to add these two function together.

doc/syslog/python-logger-enhancement.md

prgeor · 2024-06-26T05:58:18Z

doc/syslog/python-logger-enhancement.md

+#### SysLogger class change
+
+- A new class level variable `log_registry` shall be added to `SysLogger`class. The type is `dict`.
+- A new argument `enable_runtime_config` shall be added to `SysLogger.__init__`. Default to False.
+- SysLogger instance shall register itself to `log_registry` if `enable_runtime_config` is True.
+- SysLogger instance shall read log level configuration from CONFIG DB if `enable_runtime_config` is True and DB entry is available.
+- SysLogger instance shall update its log level configuration to CONFIG DB if `enable_runtime_config` is True and DB entry is not available.
+- A new class level method `refresh_config` shall be added to `SysLogger` class. The method shall be called while receiving SIGHUP to update log configuration for each logger instance registered to `log_registry`.


@Junchao-Mellanox can we maintain the SysLogger Objects inside src/sonic-py-common/sonic_py_common/daemon_base.py so that the main thread will create the list of SysLogger objects required in DaemonBase.logger_instances[]? This way the main daemon process will be able to do the signal handling based upon the identifier assigned to each Syslogger debug level configured in the CONFIG_DB

liat-grozovik · 2024-07-09T16:59:20Z

@prgeor could you please help to review following the recent changes based on your feedback?

liat-grozovik · 2024-07-09T17:00:44Z

@Junchao-Mellanox is there code PR aligned now with the updated HLD? if so, can you please remove the closed PR and update the description with the relevant ones?

Junchao-Mellanox · 2024-07-10T01:06:39Z

Hi @liat-grozovik , I will remove the closed one. I will add the code PR once it is ready for review.

prgeor · 2024-07-12T05:36:02Z

doc/syslog/python-logger-enhancement.md

+
+- `SysLogger` class shall be changed to a singleton.
+- `SysLogger` instance shall load log level configuration from DB during initialization stage if DB configuration is available.
+- `SysLogger` instance shall save log level configuration to DB during initialization stage if DB configuration is not available.


@Junchao-Mellanox Why syslogger need to save log level to DB? The user will configure the log level which will be updated to DB and the main process would be woken up via signal to fetch the user set log level from the DB. There is no need to save log level within SysLogger class.

we need to register logger itself to DB so that swssloglevel -p will print all the available log identifiers. Like this:

swssloglevel -p SAI_API_ACL SAI_LOG_LEVEL_NOTICE SAI_API_ARS SAI_LOG_LEVEL_NOTICE SAI_API_ARS_PROFILE SAI_LOG_LEVEL_NOTICE SAI_API_BFD SAI_LOG_LEVEL_NOTICE SAI_API_BMTOR SAI_LOG_LEVEL_NOTICE SAI_API_BRIDGE SAI_LOG_LEVEL_NOTICE SAI_API_BUFFER SAI_LOG_LEVEL_NOTICE SAI_API_COUNTER SAI_LOG_LEVEL_NOTICE SAI_API_DASH_ACL SAI_LOG_LEVEL_NOTICE SAI_API_DASH_DIRECTION_LOOKUP SAI_LOG_LEVEL_NOTICE SAI_API_DASH_ENI SAI_LOG_LEVEL_NOTICE SAI_API_DASH_INBOUND_ROUTING SAI_LOG_LEVEL_NOTICE SAI_API_DASH_METER SAI_LOG_LEVEL_NOTICE SAI_API_DASH_OUTBOUND_CA_TO_PASAI_LOG_LEVEL_NOTICE SAI_API_DASH_OUTBOUND_ROUTING SAI_LOG_LEVEL_NOTICE SAI_API_DASH_PA_VALIDATION SAI_LOG_LEVEL_NOTICE SAI_API_DASH_VIP SAI_LOG_LEVEL_NOTICE SAI_API_DASH_VNET SAI_LOG_LEVEL_NOTICE SAI_API_DEBUG_COUNTER SAI_LOG_LEVEL_NOTICE SAI_API_DTEL SAI_LOG_LEVEL_NOTICE SAI_API_FDB SAI_LOG_LEVEL_NOTICE SAI_API_GENERIC_PROGRAMMABLE SAI_LOG_LEVEL_NOTICE SAI_API_HASH SAI_LOG_LEVEL_NOTICE SAI_API_HOSTIF SAI_LOG_LEVEL_NOTICE SAI_API_IPMC SAI_LOG_LEVEL_NOTICE SAI_API_IPMC_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_IPSEC SAI_LOG_LEVEL_NOTICE SAI_API_ISOLATION_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_L2MC SAI_LOG_LEVEL_NOTICE SAI_API_L2MC_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_LAG SAI_LOG_LEVEL_NOTICE SAI_API_MACSEC SAI_LOG_LEVEL_NOTICE SAI_API_MCAST_FDB SAI_LOG_LEVEL_NOTICE SAI_API_MIRROR SAI_LOG_LEVEL_NOTICE SAI_API_MPLS SAI_LOG_LEVEL_NOTICE SAI_API_MY_MAC SAI_LOG_LEVEL_NOTICE SAI_API_NAT SAI_LOG_LEVEL_NOTICE SAI_API_NEIGHBOR SAI_LOG_LEVEL_NOTICE SAI_API_NEXT_HOP SAI_LOG_LEVEL_NOTICE SAI_API_NEXT_HOP_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_POLICER SAI_LOG_LEVEL_NOTICE SAI_API_PORT SAI_LOG_LEVEL_NOTICE SAI_API_QOS_MAP SAI_LOG_LEVEL_NOTICE SAI_API_QUEUE SAI_LOG_LEVEL_NOTICE SAI_API_ROUTE SAI_LOG_LEVEL_NOTICE SAI_API_ROUTER_INTERFACE SAI_LOG_LEVEL_NOTICE SAI_API_RPF_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_SAMPLEPACKET SAI_LOG_LEVEL_NOTICE SAI_API_SCHEDULER SAI_LOG_LEVEL_NOTICE SAI_API_SCHEDULER_GROUP SAI_LOG_LEVEL_NOTICE SAI_API_SRV6 SAI_LOG_LEVEL_NOTICE SAI_API_STP SAI_LOG_LEVEL_NOTICE SAI_API_SWITCH SAI_LOG_LEVEL_NOTICE SAI_API_SYSTEM_PORT SAI_LOG_LEVEL_NOTICE SAI_API_TAM SAI_LOG_LEVEL_NOTICE SAI_API_TUNNEL SAI_LOG_LEVEL_NOTICE SAI_API_TWAMP SAI_LOG_LEVEL_NOTICE SAI_API_UDF SAI_LOG_LEVEL_NOTICE SAI_API_VIRTUAL_ROUTER SAI_LOG_LEVEL_NOTICE SAI_API_VLAN SAI_LOG_LEVEL_NOTICE SAI_API_WRED SAI_LOG_LEVEL_NOTICE buffermgrd NOTICE coppmgrd NOTICE fdbsyncd NOTICE fpmsyncd NOTICE gearsyncd NOTICE intfmgrd NOTICE nbrmgrd NOTICE neighsyncd NOTICE orchagent NOTICE portmgrd NOTICE portsyncd NOTICE sflowmgrd NOTICE syncd NOTICE teammgrd NOTICE teamsyncd NOTICE tlm_teamd NOTICE tunnelmgrd NOTICE vlanmgrd NOTICE vrfmgrd NOTICE vxlanmgrd NOTICE wjhcli NOTICE wjhd NOTICE

Also, if we don't register logger instance to db, swssloglevel tool will reject when we want to update the log. Like this:

root@sonic:/# swssloglevel -c invalid -l NOTICE Component not present in DB

prgeor · 2024-07-12T05:37:19Z

doc/syslog/python-logger-enhancement.md

+
+- `SysLogger` class shall be changed to a singleton
+- A new argument `enable_runtime_config` shall be added to `SysLogger.__init__`. Default to False.
+- `SysLogger` instance shall load log level configuration from DB during initialization stage if `enable_runtime_config` is True and DB config is available.


@Junchao-Mellanox why enable_runtime_config default is kept False? What is the intention?

Two reason here:

We want to keep backward compatible. Before the feature, there is no runtime config support for SysLogger.

Enabling runtime config will slow down the logger creation for a litter bit, we want each SysLogger instance to only enable it when need.

doc/syslog/python-logger-enhancement.md

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

…onic-net#1522) * Python logger update * Fix review comment * Change SysLogger class to be a singleton * Update python-logger-enhancement.md * Update python-logger-enhancement.md * Update python-logger-enhancement.md

Junchao-Mellanox mentioned this pull request Nov 28, 2023

Python logger enhancement to support setting log level at real time sonic-net/sonic-buildimage#17321

Closed

11 tasks

Junchao-Mellanox requested review from keboliu and prgeor November 28, 2023 10:10

keboliu approved these changes Nov 28, 2023

View reviewed changes

prgeor reviewed Jan 15, 2024

View reviewed changes

doc/syslog/python-logger-enhancement.md Outdated Show resolved Hide resolved

prgeor reviewed Jan 15, 2024

View reviewed changes

doc/syslog/python-logger-enhancement.md Show resolved Hide resolved

keboliu mentioned this pull request May 6, 2024

Extend CMIS host management debug capability #1536

Closed

Junchao-Mellanox force-pushed the python-logger-enhance branch from 51e668a to 072111b Compare May 21, 2024 07:34

prgeor reviewed May 22, 2024

View reviewed changes

Junchao-Mellanox force-pushed the python-logger-enhance branch 2 times, most recently from a54c8e4 to 5d4285d Compare June 7, 2024 01:19

Python logger update

776759f

Junchao-Mellanox force-pushed the python-logger-enhance branch from 5d4285d to 776759f Compare June 7, 2024 01:32

prgeor reviewed Jun 11, 2024

View reviewed changes

prgeor reviewed Jun 12, 2024

View reviewed changes

doc/syslog/python-logger-enhancement.md Outdated Show resolved Hide resolved

Fix review comment

599fbc0

prgeor reviewed Jun 26, 2024

View reviewed changes

Junchao-Mellanox and others added 2 commits July 1, 2024 05:47

Change SysLogger class to be a singleton

9cd7212

Update python-logger-enhancement.md

f3cb63f

prgeor reviewed Jul 12, 2024

View reviewed changes

doc/syslog/python-logger-enhancement.md Outdated Show resolved Hide resolved

Junchao-Mellanox added 2 commits July 12, 2024 13:45

Update python-logger-enhancement.md

7fc79b4

Update python-logger-enhancement.md

5f520a8

prgeor approved these changes Jul 16, 2024

View reviewed changes

prgeor merged commit 60f0443 into sonic-net:master Jul 16, 2024
1 check passed

Junchao-Mellanox mentioned this pull request Aug 27, 2024

Enable runtime config log level sonic-net/sonic-buildimage#19611

Merged

11 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Python logger enhancement to support setting log level at real time #1522

Python logger enhancement to support setting log level at real time #1522

Junchao-Mellanox commented Nov 28, 2023 •

edited

Loading

liat-grozovik commented Dec 14, 2023

liat-grozovik commented Feb 12, 2024

prgeor commented Feb 14, 2024

prgeor commented Feb 15, 2024

Junchao-Mellanox commented Apr 15, 2024

liat-grozovik commented May 22, 2024

prgeor commented May 22, 2024

prgeor May 22, 2024

Junchao-Mellanox May 23, 2024

prgeor left a comment

prgeor commented May 22, 2024

Junchao-Mellanox commented May 23, 2024

Junchao-Mellanox commented May 23, 2024

prgeor commented May 30, 2024

prgeor Jun 11, 2024

Junchao-Mellanox Jun 11, 2024

prgeor Jun 12, 2024

Junchao-Mellanox Jun 12, 2024

prgeor Jun 26, 2024

liat-grozovik commented Jul 9, 2024

liat-grozovik commented Jul 9, 2024

Junchao-Mellanox commented Jul 10, 2024

prgeor Jul 12, 2024

Junchao-Mellanox Jul 12, 2024 •

edited

Loading

prgeor Jul 12, 2024

Junchao-Mellanox Jul 12, 2024

		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:


		1. `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.

Python logger enhancement to support setting log level at real time #1522

Python logger enhancement to support setting log level at real time #1522

Conversation

Junchao-Mellanox commented Nov 28, 2023 • edited Loading

Overview

PR

liat-grozovik commented Dec 14, 2023

liat-grozovik commented Feb 12, 2024

prgeor commented Feb 14, 2024

prgeor commented Feb 15, 2024

Junchao-Mellanox commented Apr 15, 2024

liat-grozovik commented May 22, 2024

prgeor commented May 22, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prgeor left a comment

Choose a reason for hiding this comment

prgeor commented May 22, 2024

Junchao-Mellanox commented May 23, 2024

Junchao-Mellanox commented May 23, 2024

prgeor commented May 30, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

liat-grozovik commented Jul 9, 2024

liat-grozovik commented Jul 9, 2024

Junchao-Mellanox commented Jul 10, 2024

Choose a reason for hiding this comment

Junchao-Mellanox Jul 12, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Junchao-Mellanox commented Nov 28, 2023 •

edited

Loading

Junchao-Mellanox Jul 12, 2024 •

edited

Loading