python logging模块使用详解

1.log4j火了

2021年底，log4j彻底火了。log4j作为整个java生态里面最重要的组件之一，被爆出了高危漏洞，无数的小伙伴因为log4j的漏洞，马上投入了通宵达旦修bug的工作中。今天我们先不谈log4j的漏洞，谈谈python中的logging模块。

2.logging的基本结构

logging主要包含有四个基础组件

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 anapplication can have any number of areas, logging channels are identifiedby a unique string. Application areas can be nested (e.g. an areaof "input processing" might include sub-areas "read CSV files", "readXLS files" and "read Gnumeric files"). To cater for this natural nesting,channel names are organized into a namespace hierarchy where levels areseparated by periods, much like the Java or Python package namespace. Soin the instance given above, channel names might be "input" for the upperlevel, and "input.csv", "input.xls" and "input.gnu" for the sub-levels.There is no arbitrary limit to the depth of nesting."""

Logger是一个"Application"，即应用程序中直接使用的API接口，后面的例子我们可以看到Logger的使用方式。

Handler

class Handler(Filterer):"""Handler instances dispatch logging events to specific destinations.The base handler class. Acts as a placeholder which defines the Handlerinterface. Handlers can optionally use Formatter instances to formatrecords as desired. By default, no formatter is specified; in this case,the 'raw' message as determined by record.message is logged."""

Handler负责将日志分发到指定的目的地。

Filter:

class Filter(object):"""Filter instances are used to perform arbitrary filtering of LogRecords.Loggers and Handlers can optionally use Filter instances to filterrecords as desired. The base filter class only allows events which arebelow a certain point in the logger hierarchy. For example, a filterinitialized 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. Ifinitialized with the empty string, all events are passed."""

Filter可以对任意的日志进行过滤，决定了哪些日志保留输出，哪些日志不显示。

Formatter：

class Formatter(object):"""Formatter instances are used to convert a LogRecord to text.Formatters need to know how a LogRecord is constructed. They areresponsible for converting a LogRecord to (usually) a string which canbe interpreted by either a human or an external system. The base Formatterallows a formatting string to be specified. If none is supplied, thethe style-dependent default value, "%(message)s", "{message}", or"${message}", is used.The Formatter can be initialized with a format string which makes use ofknowledge of the LogRecord attributes - e.g. the default value mentionedabove makes use of the fact that the user's message and arguments are pre-formatted into a LogRecord's message attribute. Currently, the usefulattributes 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 loggingcall 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 asthe record is emitted"""

Formatter决定了日志的输出格式。

3.项目实战

project-xxxlogsApplication.pyconfig.pylogger.conf...

上面是某个线上项目的示例，Application.py是应用程序，config.py是logger的入口API，logger.conf是logging的具体配置。

其中config.py为

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

上述的代码，首先定义了配置文件的地址，即当前同级目录下的logger.conf文件。
同时，定义了两种日志：
console_logger与logger。而这两种日志的具体相关配置，在logger.conf文件中。

4.配置信息详解

再看看logger.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

着重分析一下上面的配置文件里面的内容

1.loggers:配置的logger信息，里面必须有一个叫root的logger。当我们使用无参函数logging.getLogger()时，默认返回root这个logger。在我们上面的实例中，console_logger = logging.getLogger()，返回的实际就是这个root的logger。

2.handlers:指定需要有哪些handler。在上面的例子中，我们指定了两个，consoleHandler,rotatingFileHandler，后面会针对不同的handler具体再进行配置。

3.Filters:实例中未针对Filter进行配置。

4.formatters:对日志格式进行设置，例子中是simpleFormatter。

以上四条可以认为是全局配置，下面的logger_xxx, handler_xxx, formatter_xxx是针对全局配置中的声明再一一进行详细配置。

以handler_rotatingFileHandler为例

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

首先，使用的是handlers.RotatingFileHandler这个类进行逻辑处理。
同时，日志记录的级别是INFO，格式为simpleFormatter。

args的顺序与含义：
filename: 文件名，表示文件出现的位置
when: 时间，按照什么时间单位滚动
interval: 时间间隔
backupCount: 备份数量，最多保存几份日志
encoding: 编码方式
delay: 延迟写入
utc: 标准时间。
上面的例子，日志在logs文件夹下的rotating_logging.log，生成方式为append，时间间隔为1024*1024s，最大文件数5个。

5.实例测试

首先我们做个简单的测试
Application.py

def log_demo():from config import loggerimport timecurtime = 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()

将上述代码运行以后，原来logs文件夹为空，现在会生成文件rotating_logging.log，文件内容如下：

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

如果我们记录异常信息

def log_demo():from config import loggerimport timecurtime = time.strftime("%Y%m%d %H:%M:%S", time.localtime())logger.info("code begin run at: %s", curtime)try:result = 2 / 0except 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()

记录日志为：

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

上面的代码，虽然有我们自己输出的异常日志，但是没有错误代码的堆栈信息，而错误代码的堆栈信息在日常调试运维中非常重要。

想要达到目的很简单，只需要将logger.error变成logger.exception即可，此时日志的输出为：

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_demoresult = 2 / 0
ZeroDivisionError: division by zero
2022-01-03 21:14:41 - Student - 4573265344 - INFO : ccode end run at: 20220103 21:14:41

通过上面的日志输出，就很容易定位到错误代码的堆栈！