python logging module usage details

1.log4j fire

By the end of 2021, log4j was completely popular. Log4j, as one of the most important components in the whole java ecosystem, was exposed to high-risk vulnerabilities. Because of the vulnerabilities of log4j, countless small partners immediately spent all night fixing bug s. Today, let's not talk about the vulnerability of log4j, but about the logging module in python.

2. Basic structure of logging

logging mainly contains four basic components

Logger:

class Logger(Filterer):
    """
    Instances of the Logger class represent a single logging channel. A
    "logging channel" indicates an area of an application. Exactly how an
    "area" is defined is up to the application developer. Since an
    application can have any number of areas, logging channels are identified
    by a unique string. Application areas can be nested (e.g. an area
    of "input processing" might include sub-areas "read CSV files", "read
    XLS files" and "read Gnumeric files"). To cater for this natural nesting,
    channel names are organized into a namespace hierarchy where levels are
    separated by periods, much like the Java or Python package namespace. So
    in the instance given above, channel names might be "input" for the upper
    level, and "input.csv", "input.xls" and "input.gnu" for the sub-levels.
    There is no arbitrary limit to the depth of nesting.
    """

Logger is an "Application", that is, the API interface directly used in the Application. We can see the usage of logger in the following examples.

Handler

class Handler(Filterer):
    """
    Handler instances dispatch logging events to specific destinations.

    The base handler class. Acts as a placeholder which defines the Handler
    interface. Handlers can optionally use Formatter instances to format
    records as desired. By default, no formatter is specified; in this case,
    the 'raw' message as determined by record.message is logged.
    """

The Handler is responsible for distributing the logs to the specified destination.

Filter:

class Filter(object):
    """
    Filter instances are used to perform arbitrary filtering of LogRecords.

    Loggers and Handlers can optionally use Filter instances to filter
    records as desired. The base filter class only allows events which are
    below a certain point in the logger hierarchy. For example, a filter
    initialized with "A.B" will allow events logged by loggers "A.B",
    "A.B.C", "A.B.C.D", "A.B.D" etc. but not "A.BB", "B.A.B" etc. If
    initialized with the empty string, all events are passed.
    """

Filter can filter any log, and decide which logs to keep output and which logs not to display.

Formatter:

class Formatter(object):
    """
    Formatter instances are used to convert a LogRecord to text.

    Formatters need to know how a LogRecord is constructed. They are
    responsible for converting a LogRecord to (usually) a string which can
    be interpreted by either a human or an external system. The base Formatter
    allows a formatting string to be specified. If none is supplied, the
    the style-dependent default value, "%(message)s", "{message}", or
    "${message}", is used.

    The Formatter can be initialized with a format string which makes use of
    knowledge of the LogRecord attributes - e.g. the default value mentioned
    above makes use of the fact that the user's message and arguments are pre-
    formatted into a LogRecord's message attribute. Currently, the useful
    attributes in a LogRecord are described by:

    %(name)s            Name of the logger (logging channel)
    %(levelno)s         Numeric logging level for the message (DEBUG, INFO,
                        WARNING, ERROR, CRITICAL)
    %(levelname)s       Text logging level for the message ("DEBUG", "INFO",
                        "WARNING", "ERROR", "CRITICAL")
    %(pathname)s        Full pathname of the source file where the logging
                        call was issued (if available)
    %(filename)s        Filename portion of pathname
    %(module)s          Module (name portion of filename)
    %(lineno)d          Source line number where the logging call was issued
                        (if available)
    %(funcName)s        Function name
    %(created)f         Time when the LogRecord was created (time.time()
                        return value)
    %(asctime)s         Textual time when the LogRecord was created
    %(msecs)d           Millisecond portion of the creation time
    %(relativeCreated)d Time in milliseconds when the LogRecord was created,
                        relative to the time the logging module was loaded
                        (typically at application startup time)
    %(thread)d          Thread ID (if available)
    %(threadName)s      Thread name (if available)
    %(process)d         Process ID (if available)
    %(message)s         The result of record.getMessage(), computed just as
                        the record is emitted
    """

The Formatter determines the output format of the log.

3. Project practice

project-xxx
	logs
	Application.py
	config.py
	logger.conf
	...

The above is an example of an online project, application Py is the application, config Py is the entry API of logger Conf is the specific configuration of logging.

Where config Py is

import logging.config

logging.config.fileConfig("logger.conf")
console_logger = logging.getLogger()
logger = logging.getLogger(name="rotatingFileLogger")

The above code first defines the address of the configuration file, that is, the logger under the current peer directory Conf file.
At the same time, two types of logs are defined:
console_logger and logger. The specific configurations of these two logs are shown in logger Conf file.

4. Detailed explanation of configuration information

Look at logger Contents of conf

[loggers]
keys=root,rotatingFileLogger

[handlers]
keys=consoleHandler,rotatingFileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=INFO
handlers=consoleHandler

[logger_rotatingFileLogger]
level=INFO
handlers=consoleHandler,rotatingFileHandler
qualname=rotatingFileLogger
propagate=0


[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleFormatter
args=(sys.stdout,)


[handler_rotatingFileHandler]
class=handlers.RotatingFileHandler
level=INFO
formatter=simpleFormatter
args=("logs/rotating_logging.log", "a", 1*1024*1024, 5)

[formatter_simpleFormatter]
format=%(asctime)s - %(module)s - %(thread)d - %(levelname)s : %(message)s
datefmt=%Y-%m-%d %H:%M:%S

Focus on the content of the above configuration file

1.loggers: the configured logger information must contain a logger called root. When we use the parameterless function logging When getlogger (), root is returned by default. In our example above, console_logger = logging.getLogger() returns the root logger.

2.handlers: specify which handlers are required. In the above example, we have specified two, consolehandler and rotatingfilehandler, which will be configured for different handlers later.

3.Filters: Filter is not configured in the instance.

4.formatters: set the log format. In the example, it is simple formatter.

The above four items can be considered as global configuration, and the following logger_xxx, handler_xxx, formatter_xxx is a detailed configuration for the declaration in the global configuration.

With handler_ Take rotatingfilehandler as an example

[handler_rotatingFileHandler]
class=handlers.RotatingFileHandler
level=INFO
formatter=simpleFormatter
args=("logs/rotating_logging.log", "a", 1*1024*1024, 5)

First, we use handlers The rotatingfilehandler class performs logical processing.
At the same time, the level of logging is INFO and the format is simpleFormatter.

The order and meaning of args:
filename: file name, indicating where the file appears
when: time, in what time unit
Interval: time interval
backupCount: the number of backups, and the maximum number of logs saved
Encoding: encoding method
Delay: delay writing
utc: standard time.
In the above example, the log is rotated in the logs folder_ logging. Log, the generation method is append, the time interval is 1024*1024s, and the maximum number of files is 5.

5. Example test

First, let's do a simple test
Application.py

def log_demo():
    from config import logger
    import time

    curtime = time.strftime("%Y%m%d %H:%M:%S", time.localtime())
    logger.info("code begin run at: %s", curtime)
    print(curtime)
    time.sleep(2)
    endtime = time.strftime("%Y%m%d %H:%M:%S", time.localtime())
    logger.info("code end run at: %s", endtime)

log_demo()

After running the above code, the original logs folder is empty, and now the file rotating will be generated_ logging. Log, the file contents are as follows:

2022-01-03 21:05:30 - Application- 4492389824 - INFO : code begin run at: 20220103 21:05:30
2022-01-03 21:05:32 - Application- 4492389824 - INFO : code end run at: 20220103 21:05:32

If we record exception information

def log_demo():
    from config import logger
    import time

    curtime = time.strftime("%Y%m%d %H:%M:%S", time.localtime())
    logger.info("code begin run at: %s", curtime)
    try:
        result = 2 / 0
    except ZeroDivisionError as ex:
        logger.error("there is some exception: %s", repr(ex))

    endtime = time.strftime("%Y%m%d %H:%M:%S", time.localtime())
    logger.info("ccode end run at: %s", endtime)



log_demo()

The log is:

2022-01-03 21:13:01 - Application - 4472901056 - INFO : code begin run at: 20220103 21:13:01
2022-01-03 21:13:01 - Application - 4472901056 - ERROR : there is some exception: ZeroDivisionError('division by zero')
2022-01-03 21:13:01 - Application - 4472901056 - INFO : ccode end run at: 20220103 21:13:01

Although the above code has our own output exception log, there is no stack information of error code, and the stack information of error code is very important in daily debugging, operation and maintenance.

To achieve the goal is very simple, just put the logger Error becomes logger Exception, and the log output is:

2022-01-03 21:14:41 - Student - 4573265344 - INFO : code begin run at: 20220103 21:14:41
2022-01-03 21:14:41 - Student - 4573265344 - ERROR : there is some exception: ZeroDivisionError('division by zero')
Traceback (most recent call last):
  File "/xxx/xxx/Application.py", line 189, in log_demo
    result = 2 / 0
ZeroDivisionError: division by zero
2022-01-03 21:14:41 - Student - 4573265344 - INFO : ccode end run at: 20220103 21:14:41

Through the above log output, it is easy to locate the error code stack!

Keywords: Python Exception logging Handler

Added by dcuellar on Tue, 04 Jan 2022 14:23:57 +0200