Python logging模块用法快速攻略

无论使用哪种编程语言，最常用的调试代码的方式是：使用输出语句（比如 C 语言中使用 printf，Python 中使用 print() 函数）输出程序运行过程中一些关键的变量的值，查看它们的值是否正确，从而找到出错的地方。这种调试方法最大的缺点是，当找到问题所在之后，需要再将用于调试的输出语句删掉。

在 Python 中，有一种比频繁使用 print() 调试程序更简便的方法，就是使用 logging 模块，该模块可以很容易地创建自定义的消息记录，这些日志消息将描述程序执行何时到达日志函数调用，并列出指定的任何变量当时的值。

启用 logging 模块很简单，直接将下面的代码复制到程序开头：

import logging
logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s')

读者不需要关心这两行代码的具体工作原理，但基本上，当 Python 记录一个事件的日志时，它会创建一个 LogRecord 对象，保存关于该事件的信息。

假如我们编写了如下一个函数，其设计的初衷是用来计算一个数的阶乘，但该函数有些问题，需要调试：

import logging
logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s')
logging.debug('Start of program')
def factorial(n):
    logging.debug('Start of factorial(%s%%)' % (n))
    total = 1
    for i in range(n + 1):
        total *= i
        logging.debug('i is ' + str(i) + ', total is ' + str(total))
    logging.debug('End of factorial(%s%%)' % (n))
    return total
print(factorial(5))
logging.debug('End of program')

运行结果为：

2019-09-11 14:14:56,928 - DEBUG - Start of program
2019-09-11 14:14:56,945 - DEBUG - Start of factorial(5%)
2019-09-11 14:14:56,959 - DEBUG - i is 0, total is 0
2019-09-11 14:14:56,967 - DEBUG - i is 1, total is 0
2019-09-11 14:14:56,979 - DEBUG - i is 2, total is 0
2019-09-11 14:14:56,991 - DEBUG - i is 3, total is 0
2019-09-11 14:14:57,000 - DEBUG - i is 4, total is 0
2019-09-11 14:14:57,013 - DEBUG - i is 5, total is 0
2019-09-11 14:14:57,024 - DEBUG - End of factorial(5%)
0
2019-09-11 14:14:57,042 - DEBUG - End of program

可以看到，通过 logging.debug() 函数可以打印日志信息，这个 debug() 函数将调用 basicConfig() 打印一行信息，这行信息的格式是在 basicConfig() 函数中指定的，并且包括传递给 debug() 的消息。

分析程序的运行结果，factorial(5) 返回 0 作为 5 的阶乘的结果，这显然是不对的。for 循环应该用从 1 到 5 的数，乘以 total 的值，但 logging.debug() 显示的日志信息表明，i 变量从 0 开始，而不是 1。因为 0 乘任何数都是 0，所以接下来的迭代中，total 的值都是错的。日志消息提供了可以追踪的痕迹，帮助我们弄清楚程序运行过程哪里不对。

将代码行 for i in range（n + 1）：改为 for i in range（1，n + 1）：，再次运行程序，输出结果为：

2019-09-11 14:21:18,047 - DEBUG - Start of program
2019-09-11 14:21:18,067 - DEBUG - Start of factorial(5%)
2019-09-11 14:21:18,072 - DEBUG - i is 1, total is 1
2019-09-11 14:21:18,082 - DEBUG - i is 2, total is 2
2019-09-11 14:21:18,087 - DEBUG - i is 3, total is 6
2019-09-11 14:21:18,093 - DEBUG - i is 4, total is 24
2019-09-11 14:21:18,101 - DEBUG - i is 5, total is 120
2019-09-11 14:21:18,106 - DEBUG - End of factorial(5%)
120
2019-09-11 14:21:18,123 - DEBUG - End of program

Python logging日志级别

“日志级别”提供了一种方式，按重要性对日志消息进行分类。5 个日志级别如表 1 所示，从最不重要到最重要。利用不同的日志函数，消息可以按某个级别记入日志。

表 1 Python logging日志级别

级别	对应的函数	描述
DEBUG	logging.debug()	最低级别，用于小细节，通常只有在诊断问题时，才会关心这些消息。
INFO	logging.info()	用于记录程序中一般事件的信息，或确认一切工作正常。
WARNING	logging.warning()	用于表示可能的问题，它不会阻止程序的工作，但将来可能会。
ERROR	logging.error()	用于记录错误，它导致程序做某事失败。
CRITICAL	logging.critical()	最高级别，用于表示致命的错误，它导致或将要导致程序完全停止工作。

日志消息将会作为一个字符串，传递给这些函数。另外，日志级别只是一种建议，归根到底还是由程序员自己来决定日志消息属于哪一种类型。

举个例子：

>>>import logging
>>> logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s')
>>> logging.debug('Some debugging details.')
2019-09-11 14:32:34,249 - DEBUG - Some debugging details.
>>> logging.info('The logging module is working.')
2019-09-11 14:32:47,456 - INFO - The logging module is working.
>>> logging.warning('An error message is about to be logged.')
2019-09-11 14:33:02,391 - WARNING - An error message is about to be logged.
>>> logging.error('An error has occurred.')
2019-09-11 14:33:14,413 - ERROR - An error has occurred.
>>> logging.critical('The program is unable to recover!')
2019-09-11 14:33:24,071 - CRITICAL - The program is unable to recover!

日志级别的好处在于，我们可以改变想看到的日志消息的优先级。比如说，向 basicConfig() 函数传入 logging.DEBUG 作为 level 关键字参数，这将显示所有级别为 DEBUG 的日志消息。当开发了更多的程序后，我们可能只对错误感兴趣，在这种情况下，可以将 basicConfig() 的 level 参数设置为 logging.ERROR，这将只显示 ERROR 和 CRITICAL 消息，跳过 DEBUG、INFO 和 WARNING 消息。

Python logging禁用日志

在调试完程序后，可能并不希望所有这些日志消息出现在屏幕上，这时就可以使用 logging.disable() 函数禁用这些日志消息，从而不必进入到程序中，手工删除所有的日志调用。

logging.disable() 函数的用法是，向其传入一个日志级别，它会禁止该级别以及更低级别的所有日志消息。因此，如果想要禁用所有日志，只要在程序中添加 logging.disable(logging.CRITICAL) 即可，例如：

>>> import logging
>>> logging.basicConfig(level=logging.INFO, format=' %(asctime)s - %(levelname)s - %(message)s')
>>> logging.critical('Critical error! Critical error!')
2019-09-11 14:42:14,833 - CRITICAL - Critical error! Critical error!
>>> logging.disable(logging.CRITICAL)
>>> logging.critical('Critical error! Critical error!')
>>> logging.error('Error! Error!')

因为 logging.disable() 将禁用它之后的所有消息，所以可以将其添加到程序中更接近 import logging 的位置，这样更容易找到它，方便根据需要注释掉它，或取消注释，从而启用或禁用日志消息。

将日志消息输出到文件中

虽然日志消息很有用，但它们可能塞满屏幕，让你很难读到程序的输出。考虑到这种情况，可以将日志信息写入到文件，既能使屏幕保持干净，又能保存信息，一举两得。

将日志消息输出到文件中的实现方法很简单，只需要设置 logging.basicConfig() 函数中的 filename 关键字参数即可，例如：

>>> import logging
>>> logging.basicConfig(filename='demo.txt', level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')

此程序中，将日志消息存储到了 demo.txt 文件中，该文件就位于运行的程序文件所在的目录。