Python日志管理

发表于

很多项目都会用到logger，之前不解为何print能搞定的事要用logging来实现，但是当我在写一个比较复杂的项目时，我发现logging真香。

简单入手

1
2
3
4
5
6
7
8
import logging

logging.debug('This is a debug message')
logging.info('This is an info message')
print("我是中间结果")
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

一般情况下会看到终端的输出是这样的：

1
2
3
4
我是中间结果
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

代码中期望输出5行信息，而终端的输出是3行，发现debug和info的信息不见了！这是因为不同的日志信息是有优先级的，默认情况下logging的优先级是warning，那么优先级低于warning的信息就会被过滤掉（详细流程之后会讲到），而日志优先级从高到低正好是按照debug、info、warning、error、critical的顺序。

配置参数

说实话logging的基础配置格式并不好看，信息完全挤作一团，所以为了更加详细地显示信息，必须更改默认格式，好在logging的配置也是很简单的。这里以logging.basicConfig为例。

日志等级

我们先解决最好配置的一个部分——日志等级。
既然logging给定了5个等级的信息，那么只能使用warning及以上就有些浪费了，特别是在搞开发的时候，debug过程中使用debug级别的信息给开发人员看，程序发行后提高日志过滤级别，这样用户就看不到debug时的敏感信息了。

日志等级定义在basicConfig中的level中定义，在代码中插入一行配置

1
2
3
4
5
6
7
import logging
logging.debug('This is a debug message')
logging.info('This is an info message')
print("我是中间结果")
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

现在程序可以输出所有的日志信息啦

1
2
3
4
5
6
DEBUG:root:This is a debug message
INFO:root:This is an info message
我是中间结果
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

输出重定向

日志的默认输出是一股脑全部怼到终端上，而我们有时候需要程序print一些中间结果，然而中间结果在纷杂的日志信息中“泯然众人矣”。有没有什么办法可以将日志信息和print信息分离呢？filename了解一下。

filename指定日志信息输入到哪个文件中。与之搭配的还有一个参数filemode，该参数指定以何种方式写入文件，默认是‘a’（append），这样上古日志也不会被覆盖掉。如果有强迫症一定要保持日志文件的整洁，那么‘w’（write）就可以将之前的日志覆盖掉。

1
logging.basicConfig(filename="log.txt", filemode='w', level=logging.DEBUG)

现在终端的输出干净多了，复杂的日志信息都到log.txt中去了。

1
我是中间结果

机制的小朋友已经发现filemode和文件输入输出open的参数类似，然后说：“一定还可以加上’b’选项，输出二进制的日志！”。如果有小朋友尝试一下就会在终端得到一连串的报错信息混杂着日志信息。是的，重定向失效了。搞得小朋友有很多问号。这说明日志不支持二进制输出，其实这个也很好理解，日志是给人看的，而没有小朋友愿意看二进制日志。

格式化

好看的日志信息是调式的动力（吧）。如何配置看着欢喜的日志呢？

logging提供了下面的参数，也就是占位符

格式 描述
%(levelno)s 日志级别的数值
%(levelname)s 日志级别名称
%(pathname)s 当前执行程序的路径
%(filename)s 当前执行程序名称
%(funcName)s 日志的当前函数
%(lineno)d 日志的当前行号
%(asctime)s 日志的时间
%(thread)d 线程id
%(threadName)s 线程名称
%(process)d 进程ID
%(message)s 日志信息

如果要输出“时间戳 - 信息”的格式，那么可以这样配置：

1
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(message)s')
1
2
3
4
5
6
2020-03-31 11:27:28,827 - This is a debug message
2020-03-31 11:27:28,827 - This is an info message
我是中间结果
2020-03-31 11:27:28,831 - This is a warning message
2020-03-31 11:27:28,832 - This is an error message
2020-03-31 11:27:28,833 - This is a critical message

现在终端的输出是不是规整多了？

如果有小朋友对时间格式不服，也可以手动设置，并且其参数和time模块的时间配置参数相同，只不过参数实在太多了，具体还请参考官方文档。

如果开发任务对具体的日期不作要求，那么只要保留时间就好了。下面这个例子只保留了“小时-分钟-秒”，是我最常用的格式：

1
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(message)s', datefmt='%H:%M:%S')

输出效果

1
2
3
4
5
6
11:36:27 - This is a debug message
11:36:27 - This is an info message
我是中间结果
11:36:27 - This is a warning message
11:36:27 - This is an error message
11:36:27 - This is a critical message

相信大家也都是不愿记住繁杂的格式的，那么只要能知道在这里能查询就好了。

自定义logging类

之前使用logger的方式是开箱即用式的，先import，然后配置完就直接开始用了，这样做的好处是简单易用，直接上手比较方便。这种开箱即用的设计有点类似matplotlib。

不过这样的做法是存在一些限制的，先说一下缺陷出在哪里，开箱即用的logger会让全局共享同一个logger，那么在一个项目中的basicConfig会影响到全局。比如一个项目中包含了300个模块，现在需要调试某一个模块，那么我们期望其他模块不要“吵闹”就比较麻烦了，否则300个模块中的日志都输出可太壮观了。

Logger

为了控制不同文件的日志输出，有必要产生多个不同logger。logging.getLogger(name)会产生一个Logger对象。

1
logger = logging.getLogger(name=__name__)

一般比较推荐用python的__name__作为name参数。

和logging不同的是，新产生的Logger对象不能直接使用basicConfig，如果要配置自定义logger的输出格式和输出目的，需要自定义Handler和Formatter。

Handler

Handler可以控制输出的目的地，可以是终端，也可以是文件，甚至还可以通过网络传输到其他服务器上。这些Handler分别可以用下面语句获得：

1
2
s_handler = logging.StreamHandler()          # 输出到流，默认是stdout
f_handler = logging.FileHandler('file.log')  # 输出到文件

那么拿到了Handler怎么用呢？Logger有一个addHandler接口，只要将Handler放进去就可以实现定向输出了。更重要的是，addHandler可以多词调用添加不同的输出目的地。

1
2
logger.addHandler(s_handler)
logger.addHandler(f_handler)

Formatter

格式的设置方法之前已经讲了，实例化的方式也是一句即可：

1
s_format = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s', datefmt="%H:%M:%S")

需要注意添加Formatter的位置不是Logger，而是Handler。

1
s_handler.setFormatter(s_format)

所以，Logger、Handler、Formatter的嵌套关系示意图如下：

1
Logger[ Handler[ Formatter ] ]

流程

对于需要进阶了解logging的人，下面这张图应该会很有帮助。

提示

实际上不论basicConfig有无显式调用，在使用logging输出信息的时候已经被调用了，就是说debug()、info()、warning()、error()、critical()这些函数会偷偷执行basicConfig()。并且basicConfig只能调用一次，之后再次调用将不再生效。这有何影响？这表明basicConfig()必须尽早配置。要不尝试一下下面的代码吧，你将得不到任何日志信息。

1
2
3
4
5
6
import logging

logging.debug('This is a debug message')
logging.info('This is an info message')

logging.basicConfig(level=logging.DEBUG)