Python标准库logging:日志记录

日志的基本配置

日志的概念

日志(log)指的是对程序在运行过程中所发生的一些情况或行为的记录。在平时 debug 中,并不是所有错误都容易调试。有一些错误是不容易复现的,可能会在软件运行很久后才产生,但这个错误可能是由很早之前的某个事件引发的。这个时候就需要一种方式监控并不断反馈程序运行的状况。日志则专门用于实现此功能,日志的存在方便于定位错误的位置并追踪错误产生的原因。

相比与简单的 print() ,日志输出的信息更加完善且规范,便于筛选与定位,并且可以通过简单的配置更改日志的各种输出需求。

日志的级别

对于日志记录,其中有一个非常重要的概念就是日志信息的级别(level)。级别用于区分信息的重要性,在检查日志时方便筛选重要信息。

在 Python 内,日志基本上分为以下 5 种级别:

debug
info
warning
error
critical

级别等级从上到下是依次提高。因此,如果日志中出现了 errorcritical 级别的信息,那么表明程序中出现了意料之外的错误,这个错误很可能是引起程序崩溃的原因。而 warning 只是正常的警告,可能是某些功能使用不当引起的。infodebug 则是软件运行过程中正常打印出来的一些信息,标识软件运行过程中的一些状态。

一般来说,debug 只用于调试,会记录一些无关紧要的辅助信息,输出信息的重要性最低,因此输出的信息较多,而级别越往上信息量一般会减少。如果日志中 errorcritical 信息比较多的话,说明软件的运行是不正常的,软件的设计可能有较大问题。

logging 是 Python 内置的日志模块。在 logging 库中,调用同名的函数即可生成对应等级的一条日志:

import logging

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

执行结果为:

$ python logging-demo.py WARNING:root:This is warning ERROR:root:This is error CRITICAL:root:This is critical

logging 的打印和 print() 的打印不同,它并不只显示日志消息,而是具有特定格式,这样方便筛选得到合适的日志记录。

另外注意一点,debuginfo 级别的日志没有打印,这是因为 logging 模块有一个默认的配置,这个配置包含了日志的输出级别:只有日志的级别大于等于配置的输出级别时,这条日志才会输出到控制台中显示。默认的输出级别是 warning ,也就说只有高于或等于 warning 级别的日志才会打印。

可以通过 basicConfig() 函数对日志做一些简单的配置,该函数需要放在输出第一条日志的语句前,否则配置将不会生效。basicConfig() 有一个参数 level 用于控制日志的输出级别。如果更改日志级别为 info

logging.basicConfig(level=logging.INFO)

重新执行后,显示的日志信息就会包含 info 以及更高级别的日志信息:

$ python logging-demo.py INFO:root:This is info WARNING:root:This is warning ERROR:root:This is error CRITICAL:root:This is critical

logging 中的等级实际上使用整数表示,数值越高则等级越高。例如最低的 NOTSET0 ,然后 DEBUG10 ,最高的 CRITICAL50 。除此之外,logging 还提供了 log(level, msg) 函数,可以通过第一个参数提供日志的等级。

因此,如果对 logging 提供的等级划分不满意,也可以自行添加等级,例如:

SUCCESS = 35
def success(msg, *args, **kwargs):
    logging.log(SUCCESS, msg, *args, **kwargs)

定义后最好通过 addLevelName 注册这个等级的信息,这样输出时才能得到正确的等级名:

logging.addLevelName(SUCCESS, 'SUCCESS')

在开发阶段,需要记录尽可能详细的内容,方便查找各种问题;而到了部署阶段,由于软件功能已经基本稳定,只需要记录比较重要的信息即可,这样在可以快速发现一些关键的问题。日志的等级便提供了这样的功能,只需要简单修改配置即可实现内容的过滤。

日志的文件记录

logging 中的 basicConfig() 除了可以设置 level 以外,还可以做一些其它的配置。例如,默认情况下日志将被打印到控制台中,这样既不利于回看日志,也不便于检索信息。filename 参数允许将日志保存到文件中,例如:

logging.basicConfig(level=logging.ERROR,
                    filename='demo.log')

重新执行后,就可以在当前目录下生成一个新文件 demo.log ,其中的内容为:

$ python logging-demo.py $ cat demo.log ERROR:root:This is error CRITICAL:root:This is critical

如果再次执行代码,文件中的内容会增加,而不是覆盖:

$ python logging-demo.py $ cat demo.log ERROR:root:This is error CRITICAL:root:This is critical ERROR:root:This is error CRITICAL:root:This is critical

这是由于在打开日志文件时,使用的读写方式是 'a' ,也就是在末尾追加内容的方式。可以通过 basicConfig()filemode 参数改变文件的打开方式,例如用表示覆盖的写方式 "w"

logging.basicConfig(level=logging.ERROR,
                    filename='demo.log',
                    filemode='w')

此时多次运行该程序,可以看到日志文件中的内容将会被覆盖:

$ python logging-demo.py $ python logging-demo.py $ cat demo.log ERROR:root:This is error CRITICAL:root:This is critical

除此之外,打开文件时还有一个比较重要的参数 encoding ,代表打开文件的编码。如果要在日志信息中包含中文,那么就需要指定编码,否则可能会产生乱码。

日志的格式

在使用 logging 模块的时候,它打印出的日志信息前还有通过冒号隔开的 LEVELroot,而不只包括提示的信息,这表明日志应该有一个默认的格式。

默认的格式可以通过检查 logging 模块的 BASIC_FORMAT 常量得知:

BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"

不难看出,日志的格式就是使用 Python 中的百分号形式的格式字符串表示的,logging 会使用对应的内容填充格式字符串的对应字段,因此只需要自行提供一个格式字符串,其中包含 logging 支持的字段名即可:

logging_format = '[%(asctime)s - %(levelname)s] %(message)s'

然后将其传入 basicConfig()format 参数中:

logging.basicConfig(level=logging.WARNING,
                    format=logging_format)

这样日志显示的内容为:

$ python logging-demo.py [2023-03-31 17:00:34,290 - WARNING] This is warning [2023-03-31 17:00:34,290 - ERROR] This is error [2023-03-31 17:00:34,291 - CRITICAL] This is critical

logging 支持的完整字段名可以查阅官方文档,可以根据实际需求创建合适的日志格式。

此外,如果不想使用默认的日期时间表示格式,可以通过 basicConfig()datefmt 参数提供日期时间格式,它和 Python 标准库 timestrftime() 所用的日期时间表示法相同,详见官方文档

日志的高级使用

创建新的日志对象

之前一直都是直接使用 logging 模块提供的日志函数,然后使用 basicConfig() 统一所有日志函数的格式、输出和过滤方式。但是这样做有一个问题:程序的不同模块可能需要将日志输出到不同的位置,或是具有不同的输出格式或过滤等级,但不可能在程序中频繁地通过 basicConfig() 切换日志形式。如果该程序需要作为一个第三方库在其它位置被使用,两者的日志处理也应该是隔离的。这就要求创建不同的日志处理对象。

logging 模块中,Logger 对象实现了组件化日志记录接口。可以通过 getLogger(name) 函数创建一个 Logger 对象:

logger = logging.getLogger('demo')

以相同 name 调用的 getLogger() 将会返回相同的日志对象。

此外,日志对象有一个层级的概念:日志对象可以像模块一样通过在 name 中使用点号 . 表示层级结构,每个点号 . 后面的日志对象是前面日志对象的子类。例如 "demo.test""demo" 的子类。

每个 Logger 对象也提供了同名的方法创建日志记录:

logger.debug('This is debug')
logger.info('This is info')
logger.warning('This is warning')
logger.error('This is error')
logger.critical('This is critical')

这时,默认的运行效果为:

$ python logging-demo.py This is warning This is error This is critical

可以看到,Logger 对象默认打印格式只有消息本身,并且默认只打印等级为 warning 及以上等级的日志。

为了配置一个 Logger 对象,接下来要引入 Handler 对象的概念。Handler 对象决定一条日志应该如何输出,包括将日志记录输出到合适的位置,以及采用合适的输出格式。

logging 模块提供了多种 Handler ,每种 Handler 分别用于不同的工作方式。以下创建了两个 Handler 对象,StreamHandler 用于将日志输出到指定的中(默认是标准错误流 sys.stderr ),而 FileHandler 则将日志输出到指定的文件对象:

handler_s = logging.StreamHandler()
handler_f = logging.FileHandler('demo.log', mode='w')

日志的层级使得日志处理时有一个向上传播的机制:某一级日志对象在处理日志记录后,会将该记录传给上一级日志对象处理,上一级日志对象也会继续这样。

因为是 Logger 对象具有层级,但真正处理日志的是 Handler 对象,因此在具有层级的情况下,只需要为顶级的 Logger 对象提供 Handler 即可,否则一条日志会被多次处理。

可以通过将一个 Logger 对象的 .propagate 属性设置为 False 来关闭这种传播机制。

一个 Logger 对象可以有多个 Handler ,通过 Logger 对象的 .addHandler() 方法可以添加一个 Handler

logger.addHandler(handler_s)
logger.addHandler(handler_f)

这时再运行代码,logger 通过这两个 Handler 对象,分别将日志信息发送到了控制台和 demo.log 文件中。更多实用的 Handler 可以查看官方文档

格式化和过滤记录

如果要自定义日志信息的最终输出格式,需要自定义 Formatter 对象。

例如,以下创建了两个 Formatter 对象,分别给它们提供不同的格式。Formatter 对象还支持在格式化字符串中使用不同格式的占位符:

formatter_s = logging.Formatter('[%(asctime)s - %(levelname)s] %(message)s')
formatter_f = logging.Formatter('({name}) [{asctime} - {levelname}] {message}',
                                datefmt='%Y/%m/%d %H:%M:%S', style='{')

然后通过 Handler 对象的 .setFormatter() 方法设置输出格式:

handler_f.setFormatter(formatter_f)
handler_s.setFormatter(formatter_s)

LoggerHandler 对象是多对多的关系,一个日志对象可以拥有多个输出方式;但是 HandlerFormatter 对象是多对一的关系,一个输出渠道只能拥有一种格式。所以为 Handler 添加 Formatter 用到的方法以 set 开头。

现在运行程序,可以看到两路不同的输出有着不同的输出格式:

$ python logging-demo.py [2023-04-01 15:58:33,678 - WARNING] This is warning [2023-04-01 15:58:33,679 - ERROR] This is error [2023-04-01 15:58:33,679 - CRITICAL] This is critical $ cat demo.log (demo) [2023/04/01 16:02:02 - WARNING] This is warning (demo) [2023/04/01 16:02:02 - ERROR] This is error (demo) [2023/04/01 16:02:02 - CRITICAL] This is critical

最后一个话题是关于信息的过滤。在前文中,使用 basicConfig()level 参数实现了对日志输出级别的控制。如果只是要根据等级过滤日志,可以使用 .setLevel(level) 方法实现。

不过要注意的是,LoggerHandler 都提供了 .setLevel() 方法,也就是说每条日志会被处理两次:当 Logger 对象接收一条日志记录时,它会先根据自己的等级决定是否要过滤该记录,交给 Handler 处理后,Handler 再根据自身的等级确定是否要过滤记录。因此,以下等级设置:

logger.setLevel(logging.INFO)
handler_s.setLevel(logging.ERROR)
handler_f.setLevel(logging.DEBUG)

在控制台会输出 info 及以上等级的日志,在文件中会写入 error 及以上等级的日志。

除了默认的按等级过滤的方式外,logging 还提供了自定义过滤器的方式:通过继承 Filter 类并重写 .filter() 方法,可以实现更复杂的过滤逻辑。

.filter() 方法在记录可以产生时返回 True ,在记录需要被过滤时返回 False 。该方法只接收一个参数 record ,它是一个特别的 LogRecord 对象,其中包含了表示运行状况的一些属性,它的属性名和 Formatter 的字段名其实是一样的。以下实现了这样一个示例,可以过滤某些特别函数中的日志记录:

class FuncFilter(logging.Filter):
    def __init__(self, funcName, filename=None):
        self.funcName = funcName
        self.filename = filename
    def filter(self, record):
        if ((self.filename is None or
             self.filename == record.filename)
            and record.funcName == self.funcName):
            return False
        else:
            return True

Filter 还有一个作用,就是可以在过滤时顺便向日志记录添加一些额外的上下文信息,详见官方文档

LoggerHandler 都可以添加一个和多个过滤器,它们的规则也是一样的:Logger 的过滤器先发挥作用,剩余的日志再交给 Handler 的过滤器处理。例如:

filter_main = FuncFilter(__file__, 'main')
handler_s.addFilter(filter_main)

这样会过滤掉当前文件 main() 函数的所有日志。


最后再总结一下日志的完整工作流程:

  1. Logger 对象被用户调用,产生一条日志
  2. 根据 .setLevel()Filter 决定日志是否被过滤
  3. 未被过滤的日志将发送给 Handler 处理,它根据自己的 .setLevel()Filter 再次决定日志是否被过滤
  4. 未被过滤的日志在被 Formatter 格式化后发送到合适的位置被记录

对于有层级的 Logger 对象,它同时还会将记录发送给上一级处理。

官方文档提供了这样一张图片,非常详细地说明了日志处理的完整流程:

实际上,之前通过 basicConfig() 的基本使用方式和上述流程也是相同的,只不过它默认生成了一个名为 'root'Logger 对象,并且自动为其准备了 HandlerFormatter

通过文件配置日志

之前已经完整地介绍了 logging 模块的完整使用流程,但是这一过程其实十分公式化,每次都要按部就班地创建一系列对象再逐个绑定不免有些麻烦。好在 logging 提供了文件配置的方式,可以通过配置文件快速生成一系列对象以及它们之间的关系。

logging 的标准配置文件是 .conf 文件,实质上是 ini 格式。接下来通过一个示例说明该配置文件的写法。

首先,该配置文件需要提供 loggershandlersformatters 字段表示日志所用到的所有对象,其中使用 keys 键名表示这些对象的名字:

[loggers]
keys=root

[handlers]
keys=stream_handler,file_handler

[formatters]
keys=simple_formatter,fancy_formatter

注意:通过文件形式配置的日志必须要提供名为 "root" 的日志对象。并且通过文件似乎无法同时配置 Filter 对象,解决方法是使用后面介绍的字典形式配置。

接下来,使用 logger_name 字段表示要配置 name 代表的 Logger 对象:

[logger_root]
level=INFO
handlers=stream_handler,file_handler

level 键表示该 Logger 对象要过滤的等级,handlers 键表示需要给它添加的 Handler 对象,它们的配置形式相同:

[handler_stream_handler]
class=StreamHandler
level=ERROR
formatter=simple_formatter
args=(sys.stderr,)

[handler_file_handler]
class=FileHandler
level=DEBUG
formatter=fancy_formatter
args=('demo.log', 'w', 'utf-8')

同样通过 handle_ 加上 Handler 名称表示的字段名代表要配置该 Handler 对象,class 代表所属的 Handler 类。由于不同的 Handler 类在构造时具有不同的参数,因此 args 键需要对应元组形式的值。

最后 formatter 的写法也类似:

[formatter_simple_formatter]
format=[%(asctime)s - %(levelname)s] %(message)s

[formatter_fancy_formatter]
format=({name}) [{asctime} - {levelname}] {message}
datefmt=%Y/%m/%d %H:%M:%S
style={

在编写完成 .conf 文件的基础上,导入文件的配置是非常简单的:

from logging.config import fileConfig

fileConfig('logging.conf')

然后就可以直接使用 Logger 对象,而无需再接触 HandlerFormatter 之类的对象:

logger = logging.getLogger('root')

logger.debug('This is debug')
logger.info('This is info')

另外一种配置方法是使用 Python 的字典,实际上任何能对应到 Python 字典的配置文件都可以使用这种配置方式,例如 JSON 。不管如何,只需要在将其解析为字典后,通过以下代码完成配置:

from logging.config import dictConfig

dictConfig(config)

Python 官方推荐的配置文件是 YAML 格式,不过需要先安装解析 YAML 的第三方库:

$ py -m pip install PyYaml

它的基本使用方式为:

import yaml

with open('logging.yaml') as yf:
    config = yaml.load(stream=yf.read(), Loader=yaml.FullLoader)

这种配置方式和 ini 格式很像,除去 Filter 外其它内容一个写法示例如下:

version: 1
formatters:
  simple:
    format: '[%(asctime)s - %(levelname)s] %(message)s'
  fancy:
    format: '({name}) [{asctime} - {levelname}] {message}'
    datefmt: '%Y/%m/%d %H:%M:%S'
    style: '{'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    filters: [func_main]
  file:
    class: logging.FileHandler
    level: DEBUG
    formatter: fancy
    filename: 'demo.log'
    mode: 'w'
    encoding: 'utf-8'
loggers:
  root:
    level: INFO
    handlers: [console, file]

两者的一些区别为:字典格式的配置不再需要提前书写对象名,而是通过二级属性提供,并且生成对象需要通过关键字形式传递参数。Filter 的一个写法如下:

filters:
  func_main:
    (): __main__.FuncFilter
    funcName: main
    filename: yamlconfig.py

参考资料/延伸阅读

Python 标准库 logging 官方文档

logging HOWTO 文档

logging cookbook 文档,其中包含一些更高级的内容,例如日志的多线程和异常处理、更多 Handler 的用法等。

京ICP备2021034974号
contact me by hello@frozencandles.fun