彭某的技术折腾笔记

彭某的技术折腾笔记

Python 日志教程

40
2023-10-12

Python 日志教程

2023年10月11日

摘要

在规模稍大的项目中,由于代码行数过多,且文件分布广泛,逻辑也较为复杂。当程序行为出现异常时,定位 Bug 位置也会变得越发困难。虽然断点调试或者简单的输出语句能够在一定程度上寻找 Bug 出现的位置,但当偶发性的 Bug 出现时,却往往因为条件和 Bug 情形的信息不足而难以分析和复现。因此,在大型项目中使用日志也就是 log 对关键事件进行记录是十分重要的。本文将对 Python 中的日志工具进行一定的介绍。

日志的优势

在 Python 中,存在一个自带的模块,叫做 logging,其能够提供大量的用于日志记录的组件。使用 logging 模块而不是简单的 print 或是文件写入是因为 logging 能够获取例如当前文件名,时间等状态信息,并按照预先定义好的输出格式,按照一定的过滤规则将信息输出至不同的文件或是其他地方。一旦规则定义好,就可以简单直白的完成日志信息的记录,并且可以在每次运行时自动记录。极其利于 Bug 发生时的现场分析。

当然,对于常见的运行信息记录需求,都有各自适合的工具,大致如下表所示:

想要执行的任务 最适合的工具
显示命令行程序的结果 print()
提交普通操作发生时的事件报告(比如:状态监控和错误调查) logging.info()(当有诊断目的,需要详细输出信息时使用 logging.debug())
提交基于一个特殊运行时事件的警告信息 warnings.warn(): 适用于代码库中,该事件是应当可以避免的,需要修改客户端应用以消除警告

logging.warning(): 不需要修改客户端应用,但是该事件还是需要引起关注
报告错误而不引发异常(如在长时间运行中的服务端进程的错误处理) logging.error(), logging.exception()logging.critical() 分别适用于特定的错误及应用领域
对一个特殊的运行时事件报告错误 引发异常

日志模块逻辑

实例化

要使用日志,只需要导入 logging 模块即可,Python 自带,无需专门安装:

import logging

logging 模块的设计逻辑中,日志的记录是需要一个 logging 模块的实例来完成的,要实例化一个 logging 模块,只需要调用:

logger = logging.getLogger('NAME')

即可。之后的配置都将针对 logger 实例进行。

日志等级

logging 模块提供了一个信息分级的设置,可以将记录的信息按照重要程度分成 6 个默认等级,以供后续可以根据某条信息的重要等级决定是否将其记录在某个位置。例如:程序正常运行的状态记录存放入 log 文件即可,而报错信息则应该在 log 文件和控制台中同时展现。

logging 模块的 6 个默认等级,他们的具体值,以及用途如下表所示:

级别 用途
NOTSET 0 /
DEBUG 10 用于后续潜在 Debug 需求的细节信息
INFO 20 确认程序正常运行的信息
WARNING 30 发生了预期之外的事,但程序仍在正常运行,可能会在将来造成影响,例如磁盘空间过少
ERROR 40 出现一些问题,程序的某些功能无法运行
CRITICAL 50 严重问题,程序整体完全崩溃

虽然 logging 模块允许开发者自定义或是修改等级的值,但其实默认的 6 个等级在大部分情况下已经足够使用,因此本文不涉及添加或修改默认级别的教程。

在记录日志信息时,需要根据严重程度指定该条信息的等级。

组件架构记录逻辑

首先需要介绍的是,一个由 logging 模块实例化得到的 logger,后续的输出实际上是由 logger 中定义的 Handler 进行的。每一个 Handler 又可以有自己的 FilterFormatter 来过滤信息等级和格式化输出信息。因此,logging 模块的四大基本组件为:

  1. 日志器 - Logger
  2. 处理器 - Handler
  3. 过滤器 - Filter
  4. 格式器 - Formatter

有了这四个基本组件,logging 模块将按照以下流程生成日志:

  1. 代码中调用日志记录函数。
  2. Logger 级的 Formatter 将未达到预设级别阈值的信息过滤掉。
  3. 传递信息给 Handler(一个 Logger 可以有多个 Handler)。
  4. 每个 Handler 级的 Formatter 将未达到预设级别阈值的信息在各自的内部过滤掉。
  5. 每个 Handler 按照各自的 Formatter 生成格式化后的文本日志信息并输出至各自的目标位置。

至此便完成了整个日志记录流程。

使用方法

在了解了 logging 模块的设计逻辑及架构后,便可以学习如何记录日志。总体来说,有两个使用方式:模块级使用,实例化使用。

模块级使用

在无论是中文还是英文互联网上许多关于 logging 模块的教学中,都述说 logging 模块有一种最简单,最基本的使用方式是无需实例化,直接模块级的使用 logging 来进行日志记录。其实这种说法是不准确的。因为之所以可以模块级的使用 logging ,其实是因为在导入 logging 模块时,自动执行了模块中 __init__.py 的初始化脚本,而在此初始化脚本中,已经实例化了一个名为 rootlogger,此后模块级的调用都是使用的此实例。但是对于模块的使用者而言,如果不去深入了解,则把此方法当作所谓的“模块级调用”也不会有太大的问题。

默认配置

在默认的配置中,我们只要导入了 logging 模块,便可以直接调用 logging 模块中,不同重要级别的静态方法输出日志到控制台,例如:

logging.debug('Python debug')
logging.info('Python info')
logging.warning('Python warning')
logging.error('Python Error')
logging.critical('Python critical')

运行此代码可以发现,只有 warningerrorcritical 三个级别的信息在控制台中得到了输出,这是因为在默认的配置中 Filter 的级别就是 WARNING,低于此级别的信息都被过滤掉了。

如果只是使用默认配置,那么看似和 print 函数没有太大区别。要发挥 logging 模块的强大功能,则需要进行更多的自定义配置。

自定义配置

在模块级的使用中,有非常多的自定义选项可以使用 logging.baseConfig() 进行设置。然而,模块级的使用在跨源文件的日志记录场景下,会非常的令人迷惑,完全不利于配置的共享和代码的可读性。因此,只建议在极其简单的单源文件场景中,模块级的使用 logging,也因为此原因,高级的自定义配置方式仅会在后续的实例化使用方式里介绍。本章节仅会进行一些基础配置的教学。

自定义过滤级别

在默认配置中,过滤级别被设置为了 WARNING,也就是低于此级别的信息都被过滤掉,不会输出。要更改次设置,只需要在记录之前使用:

logging.basicConfig(level=logging.DEBUG)

即可将过滤级别设置为 DEBUG。要设置为其他过滤级别,只需要将 DEBUG 改成其他级别即可。

输出至文件

默认配置中,日志信息会被输出至控制台,然而很多情况下,我们会想要将其输出至文件以达到持久化记录的目的。要输出至文件,只需要:

logging.basicConfig(filename='log.log')

即可设置为将日志输出至 log.log 文件。

在默认的情况下,日志文件记录不会清空指定的文件,其会将新生成的日志条目追加至文件末尾。如果想要每次运行都清空日志文件重新记录,则可以:

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

即可将将文件模式设置为“清空并写入”。默认的“追加写入”模式的 filemode'a'

输出格式

在默认情况下,日志的输出是类似以下格式的:

WARNING:root:Python warning
ERROR:root:Python Error
CRITICAL:root:Python critical

由级别,logger 名称,以及日志信息内容组成。我们可以对其进行更改,例如:

logging.basicConfig(format='Log from PSC: %(levelname)s:%(message)s')

即可将输出内容变成:

Log from PSC: WARNING:Python warning
Log from PSC: ERROR:Python Error
Log from PSC: CRITICAL:Python critical

format 中的 %(var_name)s 即代表了命名中所指代的信息。完整的日志内容变量表如下:

属性名称 格式 描述
args 此属性不需要用户进行格式化。 合并到 msg 以产生 message 的包含参数的元组,或是其中的值将被用于合并的字典(当只有一个参数且其类型为字典时)。
asctime %(asctime)s 表示人类易读的 LogRecord 生成时间。 默认形式为 ‘2003-07-08 16:49:45,896’ (逗号之后的数字为时间的毫秒部分)。
created %(created)f LogRecord 被创建的时间(即 time.time() 的返回值)。
exc_info 此属性不需要用户进行格式化。 异常元组(例如 sys.exc_info)或者如未发生异常则为 None
filename %(filename)s pathname 的文件名部分。
funcName %(funcName)s 函数名包括调用日志记录.
levelname %(levelname)s 消息文本记录级别('DEBUG''INFO''WARNING''ERROR''CRITICAL')。
levelno %(levelno)s 消息数字的记录级别 (DEBUG, INFO, WARNING, ERROR, CRITICAL).
lineno %(lineno)d 发出日志记录调用所在的源代码行号(如果可用)。
message %(message)s 记入日志的消息,即 msg % args 的结果。 这是在发起调用 Formatter.format() 时设置的。
module %(module)s 模块 (filename 的名称部分)。
msecs %(msecs)d LogRecord 被创建的时间的毫秒部分。
msg 此属性不需要用户进行格式化。 在原始日志记录调用中传入的格式字符串。 与 args 合并以产生 message,或是一个任意对象 (参见 使用任意对象作为消息)。
name %(name)s 用于记录调用的日志记录器名称。
pathname %(pathname)s 发出日志记录调用的源文件的完整路径名(如果可用)。
process %(process)d 进程ID(如果可用)
processName %(processName)s 进程名(如果可用)
relativeCreated %(relativeCreated)d 以毫秒数表示的 LogRecord 被创建的时间,即相对于 logging 模块被加载时间的差值。
stack_info 此属性不需要用户进行格式化。 当前线程中从堆栈底部起向上直到包括日志记录调用并引发创建当前记录堆栈帧创建的堆栈帧信息(如果可用)。
thread %(thread)d 线程ID(如果可用)
threadName %(threadName)s 线程名(如果可用)
taskName %(taskName)s asyncio.Task 名称(如果可用)。

开发者只需要对其自由组合即可。

组合设置

开发者可以对上述设置进行组合,例如:

logging.basicConfig(filename='log.log', filemode='w', level=logging.DEBUG,
                    format='Log from PSC: %(levelname)s:%(message)s')

即可组合成一组设置。

覆盖设置

在默认情况下,一旦 logging.baseConfig() 被调用一次,后续如果想要修改设置,再对其进行调用将会是完全无效的,因为其被设计为了一次性设置。

例如:

logging.basicConfig(format='Old Setting: %(levelname)s:%(message)s')
logging.warning('Old Format Warning')

logging.basicConfig(format='New Setting: %(levelname)s:%(message)s')
logging.warning('New Format Warning')

输出为:

Old Setting: WARNING:Old Format Warning
Old Setting: WARNING:New Format Warning

可以看到,第二次设置完全没有生效。

如果一定想要修改设置,logging 也预留了一个 force 选项用于覆盖设置:

logging.basicConfig(format='Old Setting: %(levelname)s:%(message)s')
logging.warning('Old Format Warning')

logging.basicConfig(format='New Setting: %(levelname)s:%(message)s', force=True)
logging.warning('New Format Warning')

则输出变为了:

Old Setting: WARNING:Old Format Warning
New Setting: WARNING:New Format Warning

第二次设置生效。

实例化使用

要更好的使用 logging 模块,推荐使用实例化的方案,因为在这样的使用方法中,我们可以在一个专门的源文件中,配置好并得到一个 logger 对象,然后在其他的所有源文件中,直接导入这个 logger 对象即可使用。在多个源文件的大项目中十分适用。

代码配置

在代码中配置 logger 实例,只需按照以下步骤即可。

实例化

要实例化一个 logger,只需要调用 logging.getLogger() 并提供一个 logger 名(例如默认的 root)即可:

logger = logging.getLogger(__name__)

此后,所有的配置都将针对 logger 而不是 logging 模块进行。

预配置 Formatter

为了让日志信息按照我们想要的格式进行输出,需要编写一个 Formatter 规则,例如:

simple_formatter = logging.Formatter('%(levelname)s - %(message)s')

detailed_formatter = logging.Formatter('%(asctime)s - %(name)s - %(pathname)s - %(lineno)d - %(levelname)s - %(message)s')

具体的日志信息变量表可以查看上文的表格。

一旦 Formatter 规则定义完成,即可在后续的 Handler 中使用。

定义 Handler

由于一个 logger 可以拥有多个 Handler,本文将使用两个最常见的 Handler:用于输出至控制台的 StreamHandler 和用于输出至文件的 FileHandler 作为例子。

还有其他的类似用于输出至套接字的 SocketHandler 以及输出至 HTTP 的 HTTPHandler 等,如有需要可以查阅官方文档。

要定义 Handler,只需按照以下例子进行编写即可:

console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)
console_handler.setFormatter(simple_formatter)

log_file_handler = logging.FileHandler('log.log', mode='a')
log_file_handler.setLevel(logging.DEBUG)
log_file_handler.setFormatter(detailed_formatter)

此处定义了两个 Handler:一个是只将 WARNING 及以上级别的重要信息以简要的格式输出至终端的 console_handler,另一个是将 DEBUG 及以上级别的全部信息以详细的格式输出至文件的 log_file_handler,并且设置为追加写入模式。

一旦定义好 Handler,便可在后续添加至 logger

添加 Handler 至 Logger

至此,只需要将配置好的 Handler 添加至 Logger 即可:

logger.addHandler(console_handler)
logger.addHandler(log_file_handler)
使用 Logger

假设此前的 logger 定义在了 log_config.py 中,

此后,只需要在需要记录日志的文件中导入并调用 logger 并提供日志信息即可:

from log import logger

logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

由于 logger 的过滤级别被设置为了 DEBUG,因此所有信息都将被 logger 保留并呈递给两个 Handler

console_handler 会将 DEBUGINFO 的信息过滤掉,并按照 simpleFormatter 格式化后输出至终端:

WARNING - warn message
ERROR - error message
CRITICAL - critical message

log_file_handler 会所有级别的信息保留,并按照 detailedFormatter 格式化后追加输出至 log.log 文件:

2023-10-12 12:54:28,024 - log - /Users/psc/PycharmProjects/learn_tools/main.py - 23 - WARNING - warn message
2023-10-12 12:54:28,024 - log - /Users/psc/PycharmProjects/learn_tools/main.py - 24 - ERROR - error message
2023-10-12 12:54:28,025 - log - /Users/psc/PycharmProjects/learn_tools/main.py - 25 - CRITICAL - critical message

配置文件配置

除了可以在代码中配置 logger,还可以在一个额外的 YAML 文件中编写配置并导入,以达到配置和代码分离的清晰架构。YAML 的教程也在之前的文章中有过,具体内容可以去查阅。

前文所属的 logger 配置,如果写成 YAML 的配置文件即为:

version: 1
formatters:
  simple_formatter:
    format: '%(levelname)s - %(message)s'
  detailed_formatter:
    format: '%(asctime)s - %(name)s - %(pathname)s - %(lineno)d - %(levelname)s - %(message)s'
handlers:
  console_handler:
    class: logging.StreamHandler
    level: WARNING
    formatter: simple_formatter
  log_file_handler:
    class: logging.FileHandler
    level: DEBUG
    formatter: detailed_formatter
    filename: 'log.log'
loggers:
  example:
    level: DEBUG
    handlers:
      - console_handler
      - log_file_handler
#root:
#  level: DEBUG
#  handlers: [console_handler, log_file_handler]

注意由于模块要求,需要添加一个 version: 1 的键值对,没什么意义,只是有这个要求。

loggers 内部, example 即为未来 Python 代码中需要指定的 logger 名,需要一一对应。

由于我们选择指定 logger 名,因此不对 root logger 进行配置。

在 Python 中,我们只需要:

import logging.config
import ruamel.yaml as yaml

with open('log.yml', 'r') as f:
    log_config = yaml.safe_load(f)

logging.config.dictConfig(log_config)
logger = logging.getLogger('example')

即可读取配置文件,完成对 logger 的配置。

此后,只需要像往常一样正常在其他文件中导入配置好的 logger 并使用即可。

  • 0