logging日志模块使用小记

背景

通常对一规模比较小的程序，我们会使用print函数去打印我们想看到的内容，但是当程序规模较大的时候print函数使用多了不方便管理，并且也影响代码的整洁性，如果程序上线，你遗忘了一些print函数在哪了，该怎么办。于是就出现了一种解决方案——日志。本文就参照Python之日志处理（logging模块）^[1]、以打印日志为荣之logging模块详细使用^[2]以及官方文档^[3]做一下总结。

1 关于日志

日志是一种可以追踪某些软件运行时所发生事件的方法。软件开发人员可以向他们的代码中调用日志记录相关的方法来表明发生了某些事情。一个事件可以用一个可包含可选变量数据的消息来描述。此外，事件也有重要性的概念，这个重要性也可以被称为严重性级别（level）。

日志还有的作用就是，通过log的分析，可以方便用户了解系统或软件、应用的运行情况；如果你的应用log足够丰富，也可以分析以往用户的操作行为、类型喜好、地域分布或其他更多信息；如果一个应用的log同时也分了多个级别，那么可以很轻易地分析得到该应用的健康状况，及时发现问题并快速定位、解决问题，补救损失。

简单来讲就是通过记录和分析日志可以了解一个系统或软件程序运行情况是否正常，也可以在应用程序出现故障时快速定位问题。也可以简单总结为以下3点：

• 程序调试
• 了解软件程序运行情况，是否正常
• 软件程序运行故障分析与问题定位

如果应用的日志信息足够详细和丰富，还可以用来做用户行为分析，如：分析用户的操作行为、类型洗好、地域分布以及其它更多的信息，由此可以实现改进业务、提高商业利益。

然后我们回去思考，我们输出的信息重要程度不同，有的很重要的，有的很鸡肋。在日志中会有相关的等级划分，如下：

• DEBUG
• INFO
• NOTICE
• WARNING
• ERROR
• CRITICAL
• ALERT
• EMERGENCY

接着，我们输出的日志是什么样的格式呢？日志信息需要包含哪些呢？日志的本质是对应一个事件的发生，而一个事件则有包含：

• 事件发生时间
• 事件发生位置
• 事件的严重程度--日志级别
• 事件内容

上面这些都是一条日志记录中可能包含的字段信息，还可以包括一些其他信息，如进程ID、进程名称、线程ID、线程名称等。

2 logging

Python的logging模块提供了标准的日志接口，你可以通过它存储各种格式的日志，主要用于输出运行日志，可以设置输出日志的等级、日志保存路径、日志文件回滚等。那么下面就来看看Python中的logging吧。

在logging中模型定义了一下几个日志等级，优先级依次递增，日志的信息量依次减少。

当然用户也可以自定义其他级别日志，但是不建议。

小常识：

• 开发应用程序或部署开发环境时，可以使用DEBUG或INFO级别的日志获取尽可能详细的日志信息来进行开发或部署调试；
• 应用上线或部署生产环境时，应该使用WARNING或ERROR或CRITICAL级别的日志来降低机器的I/O压力和提高获取错误日志信息的效率；
• 日志级别的指定通常都是在应用程序的配置文件中进行指定的；
• 当为某个应用程序指定一个日志级别后，应用程序会记录所有日志级别大于或等于指定日志级别的日志信息，而不是仅仅记录指定级别的日志信息。

2.1 logging模块的使用方式

logging模块提供了两种记录日志的方式：

• 使用logging提供的模块级别的函数
• 使用logging日志系统的四大组件

本质上来说，logging所提供的模块级别的日志记录函数也是对logging日志系统相关类的封装而已。下面先了解一下相关概念。

2.1.1 模块级别的常用函数

logging.basicConfig(**kwargs)函数用于指定“要记录的日志级别”、“日志格式”、“日志输出位置”、“日志文件的打开模式”等信息，其他几个都是用于记录各个级别日志的函数。

2.1.2 四大组件

2.2 使用模块级别的函数记录日志

2.2.1 小试牛刀-最简单的日志输出

简单的日志输出代码：

import logging

logging.debug("This is a debug log.")
logging.info("This is a info log.")
logging.warning("This is a warning log.")
logging.error("This is a error log.")
logging.critical('This is a critical log.')

输出结果如下：当然也可以这样写，输出结果与上面相同：

import logging

logging.log(logging.DEBUG, 'This is a debug log.')
logging.log(logging.INFO, 'This is a info log.')
logging.log(logging.WARNING, 'This is a warning log.')
logging.log(logging.ERROR, 'This is a error log.')
logging.log(logging.CRITICAL, 'This is a critical log.')

不过，从结果看出，有点问题：问题1：为啥只打印三条信息呢？

这是因为logging模块提供的日志记录函数所使用的日志器设置的日志级别是WARNING，因此只有WARNING级别的日志记录以及大于它的ERROR和CRITICAL级别的日志记录被输出了，而小于它的DEBUG和INFO级别的日志记录被丢弃了。

问题2：为什么会输出这种格式的日志信息？

上面输出结果中每行日志记录的各个字段含义分别是：日志级别:日志器名称:日志内容，之所以会这样输出，是因为logging模块提供的日志记录函数所使用的日志器设置的日志格式默认是BASIC_FORMAT，其值为："%(levelname)s:%(name)s:%(message)s"，也就是说，我们是可以更改输出格式的。

问题3：日志为何不输出到一个日志文件中？

logging模块提供的日志记录函数所使用的日志器设置的处理器所指定的日志输出位置默认为:sys.stderr，也就是说，如果想输出到日志文件中，我们配置一下即可。

2.2.2 看看logging.basicConfig()函数

在简单使用中提及到对于一些需求，我们需要对logging进行配置，那么如何配置呢？现在就来看看。logging.basicConfig()就是为logging日志系统做一些基本配置的，那么不要嫌烦，看看其中的一些参数吧：

2.2.3 logging模块定义的格式字符串字段

知道了一些配置参数，该了解一下如何配置信息了。来看看logging模块中定义好的可以用于format格式字符串中字段有哪些：

说明：使用格式最后一个字符如d,s表示数据类型，d表示数字类型，s表示字符类型。

2.2.4 经过配置的日志输出

设置日志级别：

import logging

logging.basicConfig(level=logging.DEBUG)

logging.log(logging.DEBUG, 'This is a debug log.')
logging.log(logging.INFO, 'This is a info log.')
logging.log(logging.WARNING, 'This is a warning log.')
logging.log(logging.ERROR, 'This is a error log.')
logging.log(logging.CRITICAL, 'This is a critical log.')

这是就可以看到输出量所有级别的日志了。除此之外，还可以配置日志的输出格式，增加输出日志文件，如下：

import logging

LOG_FORMAT = "%(asctime)s - %(levelname)s - %(message)s"  # 定义日志输出格式
logging.basicConfig(filename='my.log', level=logging.DEBUG, format=LOG_FORMAT)

logging.log(logging.DEBUG, 'This is a debug log.')
logging.log(logging.INFO, 'This is a info log.')
logging.log(logging.WARNING, 'This is a warning log.')
logging.log(logging.ERROR, 'This is a error log.')
logging.log(logging.CRITICAL, 'This is a critical log.')

程序运行：此时会发现控制台中已经没有输出日志内容了，但是在python代码文件的相同目录下会生成一个名为'my.log'的日志文件，该文件中的内容为：

2021-01-01 11:28:52,370 - DEBUG - This is a debug log.
2021-01-01 11:28:52,371 - INFO - This is a info log.
2021-01-01 11:28:52,371 - WARNING - This is a warning log.
2021-01-01 11:28:52,371 - ERROR - This is a error log.
2021-01-01 11:28:52,371 - CRITICAL - This is a critical log.

在上面的基础上，我们再来设置下日期/时间格式，

import logging

LOG_FORMAT = "%(asctime)s - %(levelname)s - %(message)s"  # 定义日志输出格式
DATE_FORMAT = "%m/%d/%Y %H:%M:%S %p"   # 定义日期输出格式
logging.basicConfig(filename='my.log', level=logging.DEBUG, format=LOG_FORMAT, datefmt=DATE_FORMAT)

logging.log(logging.DEBUG, 'This is a debug log.')
logging.log(logging.INFO, 'This is a info log.')
logging.log(logging.WARNING, 'This is a warning log.')
logging.log(logging.ERROR, 'This is a error log.')
logging.log(logging.CRITICAL, 'This is a critical log.')

日志结果如下：

01/01/2021 11:33:58 AM - DEBUG - This is a debug log.
01/01/2021 11:33:58 AM - INFO - This is a info log.
01/01/2021 11:33:58 AM - WARNING - This is a warning log.
01/01/2021 11:33:58 AM - ERROR - This is a error log.
01/01/2021 11:33:58 AM - CRITICAL - This is a critical log.

如果想获取更多信息，可以根据前面提到的参数自行定义咯。其实到这里，已经能够满足我们平时开发中需要的日志记录功能。

2.2.5 其他

这段内容也是从前人总结得来，也是需要注意的内容。

• logging.basicConfig() 函数是一个一次性的简单配置，也就是说只有在第一次调用该函数时会起作用，后续再次调用该函数时完全不会产生任何操作的，多次调用的设置并不是累加操作。

• 日志器（Logger）是有层级关系的，上面调用的logging模块级别的函数所使用的日志器是RootLogger类的实例，其名称为'root'，它是处于日志器层级关系最顶层的日志器，且该实例是以单例模式存在的。

• 如果要记录的日志中包含变量数据，可使用一个格式字符串作为这个事件的描述消息（logging.debug、logging.info等函数的第一个参数），然后将变量数据作为第二个参数*args的值进行传递，如:logging.warning('%s is %d years old.', 'Tom', 10)，输出内容为WARNING:root:Tom is 10 years old.

• logging.debug(), logging.info()等方法的定义中，除了msg和args参数外，还有一个**kwargs参数。它们支持3个关键字参数: exc_info, stack_info, extra.

• exc_info：其值为布尔值，如果该参数的值设置为True，则会将异常信息添加到日志消息中。如果没有异常信息则添加None到日志信息中。
• stack_info：其值为布尔值，默认值为False。如果该参数的值设置为True，栈信息将会被添加到日志信息中。
• extra：这是一个字典（dict）参数，它可以用来自定义消息格式中所包含的字段，但是它的key不能与logging模块定义的字段冲突。
• 一个使用的例子：在日志消息中添加exc_info和stack_info信息，并添加两个自定义的字段 ip和user，有如下代码：

import logging

LOG_FORMAT = "%(asctime)s - %(levelname)s - %(message)s"  # 定义日志输出格式
DATE_FORMAT = "%m/%d/%Y %H:%M:%S %p"   # 定义日期输出格式
logging.basicConfig(filename='my.log', level=logging.DEBUG, format=LOG_FORMAT, datefmt=DATE_FORMAT)

logging.warning("Some one delete the log file.", exc_info=True, stack_info=True, extra={'user': 'Tom', 'ip':'47.98.53.222'})

输出结果如下：

NoneType: None
Stack (most recent call last):
  File "F:/test/Temp/main.py", line 16, in <module>
    logging.warning("Some one delete the log file.", exc_info=True, stack_info=True, extra={'user': 'Tom', 'ip':'47.98.53.222'})

3 logging高级

这部分内容比较深入，了解之后也有助于更加灵活的构建日志。在介绍logging模块的高级用法之前，有必要对logging模块所包含的重要组件以及其工作流程做个全面、简要的介绍，有助于更好的理解我们所写的代码（将会触发什么样的操作）。下面就看看网络常说的logging日志模块四大组件。

3.1 四大组件

logging模块就是通过这些组件来完成日志处理的，上面所使用的logging模块级别的函数也是通过这些组件对应的类来实现的。

这些组件之间的关系如下：

• 日志器（logger）需要通过处理器（handler）将日志信息输出到目标位置，如：文件、sys.stdout、网络等；
• 不同的处理器（handler）可以将日志输出到不同的位置；
• 日志器（logger）可以设置多个处理器（handler）将同一条日志记录输出到不同的位置；
• 每个处理器（handler）都可以设置自己的过滤器（filter）实现日志过滤，从而只保留感兴趣的日志；
• 每个处理器（handler）都可以设置自己的格式器（formatter）实现同一条日志以不同的格式输出到不同的地方。

简单点说就是：日志器（logger）是入口，真正干活儿的是处理器（handler），处理器还可以通过过滤器（filter）和格式器（formatter）对要输出的日志内容做过滤和格式化等处理操作。这样一介绍似乎很多都明了了。

3.2 logging日志模块相关类及其常用方法

logging四大组件相关的类对应的就是Logger, Handler, Filter, Formatter这几个类了。下面也先看看一些概念，待会show you code。

3.2.1 Logger类

Logger对象主要涉及3个任务：

• 向应用程序代码暴露几个方法，使应用程序可以在运行时记录日志消息；
• 基于日志严重等级（默认的过滤设置）或filter对象来决定要对哪些日志进行后续处理；
• 将日志消息传送给所有感兴趣的日志handlers。

Logger对象最常用的方法分为两类：配置方法 和 消息发送方法。常用配置如下：

关于Logger.setLevel()方法：内建等级中，级别最低的是DEBUG，级别最高的是CRITICAL。例如setLevel(logging.INFO)，此时函数参数为INFO，那么该logger将只会处理INFO、WARNING、ERROR和CRITICAL级别的日志，而DEBUG级别的消息将会被忽略/丢弃。

logger对象配置完成后，可以使用下面的方法来创建日志记录：

可能你也注意到了Logger.exception()与Logger.error()，他们的区别在于：Logger.exception()将会输出堆栈追踪信息，另外通常只是在一个exception handler中调用该方法。Logger.log()与Logger.debug()、Logger.info()等方法相比，虽然需要多传一个level参数，显得不是那么方便，但是当需要记录自定义level的日志时还是需要该方法来完成。

说了一堆对象，那么该怎样得到一个Logger对象呢？一种方式是通过Logger类的实例化方法创建一个Logger类的实例，但是我们通常都是用第二种方式-- logging.getLogger() 方法。logging.getLogger()方法有一个可选参数name，该参数表示将要返回的日志器的名称标识，如果不提供该参数，则其值为'root'。若以相同的name参数值多次调用getLogger()方法，将会返回指向同一个logger对象的引用。

3.2.2 Handler类

Handler对象的作用是（基于日志消息的level）将消息分发到handler指定的位置（文件、网络、邮件等）。Logger对象可以通过addHandler()方法为自己添加0个或者更多个handler对象。比如，一个应用程序可能想要实现以下几个日志需求：

• 把所有日志都发送到一个日志文件中；
• 把所有严重级别大于等于error的日志发送到stdout（标准输出）；
• 把所有严重级别为critical的日志发送到一个email邮件地址。

这种场景就需要3个不同的handlers，每个handler负责发送一个特定严重级别的日志到一个特定的位置。一个handler中只有非常少数的方法是需要应用开发人员去关心。对于使用内建handler对象的应用开发人员来说，似乎唯一相关的handler方法就是下面这几个配置方法：

应用程序代码不应该直接实例化和使用Handler实例。因为Handler是一个基类，它只定义了素有handlers都应该有的接口，同时提供了一些子类可以直接使用或覆盖的默认行为。下面是一些常用的Handler：

3.2.3 Formater类

Formater对象用于配置日志信息的最终顺序、结构和内容。与logging.Handler基类不同的是，应用代码可以直接实例化Formatter类。另外，如果应用程序需要一些特殊的处理行为，也可以实现一个Formatter的子类来完成。Formatter类的构造方法定义如下：

logging.Formatter.__init__(fmt=None, datefmt=None, style='%')

可见，该构造方法接收3个可选参数：

• fmt：指定消息格式化字符串，如果不指定该参数则默认使用message的原始值
• datefmt：指定日期格式字符串，如果不指定该参数则默认使用"%Y-%m-%d %H:%M:%S"
• style：可取值为 '%', '{'和 '$'，如果不指定该参数则默认使用'%'

3.2.4 Filter类

Filter可以被Handler和Logger用来做比level更细粒度的、更复杂的过滤功能。Filter是一个过滤器基类，它只允许某个logger层级下的日志事件通过过滤。该类定义如下：

class logging.Filter(name='')
    filter(record)

比如，一个filter实例化时传递的name参数值为'A.B'，那么该filter实例将只允许名称为类似如下规则的loggers产生的日志记录通过过滤：'A.B'，'A.B,C'，'A.B.C.D'，'A.B.D'，而名称为'A.BB', 'B.A.B'的loggers产生的日志则会被过滤掉。如果name的值为空字符串，则允许所有的日志事件通过过滤。

filter方法用于具体控制传递的record记录是否能通过过滤，如果该方法返回值为0表示不能通过过滤，返回值为非0表示可以通过过滤。如果有需要，也可以在filter(record)方法内部改变该record，比如添加、删除或修改一些属性。还可以通过filter做一些统计工作，比如可以计算下被一个特殊的logger或handler所处理的record数量等。

3.3 logging日志流处理流程

logging日志处理流程。看起来，整体内容还不少。下面来洗洗品味这个图。

1. （在用户代码中进行）日志记录函数调用，如：logger.info(...)，logger.debug(...)等；
2. 判断要记录的日志级别是否满足日志器设置的级别要求（要记录的日志级别要大于或等于日志器设置的级别才算满足要求），如果不满足则该日志记录会被丢弃并终止后续的操作，如果满足则继续下一步操作；
3. 根据日志记录函数调用时传入的参数，创建一个日志记录（LogRecord类）对象；
4. 判断日志记录器上设置的过滤器是否拒绝这条日志记录，如果日志记录器上的某个过滤器拒绝，则该日志记录会被丢弃并终止后续的操作，如果日志记录器上设置的过滤器不拒绝这条日志记录或者日志记录器上没有设置过滤器则继续下一步操作--将日志记录分别交给该日志器上添加的各个处理器；
5. 判断要记录的日志级别是否满足处理器设置的级别要求（要记录的日志级别要大于或等于该处理器设置的日志级别才算满足要求），如果不满足记录将会被该处理器丢弃并终止后续的操作，如果满足则继续下一步操作；
6. 判断该处理器上设置的过滤器是否拒绝这条日志记录，如果该处理器上的某个过滤器拒绝，则该日志记录会被当前处理器丢弃并终止后续的操作，如果当前处理器上设置的过滤器不拒绝这条日志记录或当前处理器上没有设置过滤器测继续下一步操作；
7. 如果能到这一步，说明这条日志记录经过了层层关卡允许被输出了，此时当前处理器会根据自身被设置的格式器（如果没有设置则使用默认格式）将这条日志记录进行格式化，最后将格式化后的结果输出到指定位置（文件、网络、类文件的Stream等）；
8. 如果日志器被设置了多个处理器的话，上面的第5-8步会执行多次；
9. 这里才是完整流程的最后一步：判断该日志器输出的日志消息是否需要传递给上一级logger（之前提到过，日志器是有层级关系的）的处理器，如果propagate属性值为1则表示日志消息将会被输出到处理器指定的位置，同时还会被传递给parent日志器的handlers进行处理直到当前日志器的propagate属性为0停止，如果propagate值为0则表示不向parent日志器的handlers传递该消息，到此结束。

总的来说，一条日志信息要想被最终输出需要依次经过以下几次过滤：

• 日志器等级过滤；
• 日志器的过滤器过滤；
• 日志器的处理器等级过滤；
• 日志器的处理器的过滤器过滤；

日志的输出也是比较严格的。

3.4 使用logging四大组件记录日志

看了这么多的理论，该来尝试一个案例，show you code了。

案例任务要求如下：

1. 将所有级别的所有日志都写入磁盘文件中
2. all.log文件中记录所有的日志信息，日志格式为：日期和时间 - 日志级别 - 日志信息
3. error.log文件中单独记录error及以上级别的日志信息，日志格式为：日期和时间 - 日志级别 - 文件名[:行号] - 日志信息
4. all.log在每天凌晨进行日志切割

根据要求小小地分析一下：

• 要记录所有级别的日志，那么日志器的有效level需要设置为最低级别--DEBUG;
• 日志需要被发送到两个不同的目的地，因此需要为日志器设置两个handler；另外，两个目的地都是磁盘文件，因此这两个handler都是与FileHandler相关的；
• all.log要求按照时间进行日志切割，因此需要用logging.handlers.TimedRotatingFileHandler; 而error.log没有要求日志切割，因此可以使用FileHandler;
• 两个日志文件的格式不同，因此需要对这两个handler分别设置格式器；

那么下面就开干，代码如下：

import logging
from logging import handlers
import datetime

logger = logging.getLogger('mylogger')  # 创建logger类
logger.setLevel(logging.DEBUG)  # 设置级别

# 设置全部日志根据时间分割的处理器
rf_handler = logging.handlers.TimedRotatingFileHandler('all.log', when='midnight', interval=1, backupCount=7, atTime=datetime.time(0, 0, 0, 0))
# 为输出日志信息设置格式
rf_handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(message)s"))

# 设置错误日志处理器
f_handler = logging.FileHandler('error.log')
# 单独为错误日志设置处理等级
f_handler.setLevel(logging.ERROR)
# 为输出日志信息设置格式
f_handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(filename)s[:%(lineno)d] - %(message)s"))

# 处理器添加
logger.addHandler(rf_handler)
logger.addHandler(f_handler)

# 日志记录查看
logger.debug('debug message')
logger.info('info message')
logger.warning('warning message')
logger.error('error message')
logger.critical('critical message')

运行结果all.log， error.log分别如下， all.log

2021-01-03 18:35:51,881 - DEBUG - debug message
2021-01-03 18:35:51,882 - INFO - info message
2021-01-03 18:35:51,882 - WARNING - warning message
2021-01-03 18:35:51,882 - ERROR - error message
2021-01-03 18:35:51,883 - CRITICAL - critical message

error.log

2021-01-03 18:35:51,882 - ERROR - main.py[:37] - error message
2021-01-03 18:35:51,883 - CRITICAL - main.py[:38] - critical message

当然，要想深入的话还是有很多要整的。特别是配置logging，对于开发者来说，不能把一些内容写死了，耦合性太高并不好。使用Python代码显式的创建loggers, handlers和formatters并分别调用它们的配置函数；创建一个日志配置文件，然后使用fileConfig()函数来读取该文件的内容；创建一个包含配置信息的dict，然后把它传递个dictConfig()函数等都可以。

4 总结

上面大致记录这么多，对于日志各个语言有不同的方式，内容其实也不少，不过也是比较有用的。后期如果再有一些的新的需要的任务，再做相关的文档记录。

参考资料

剑指Offer刷题集| Python基础