logging 模块：级别、格式化与配置

引言

第九章「综合项目：命令行工具」已经走完三篇：第 1 篇用 sys.argv 与 if __name__ 搭起了命令行程序的骨架，第 2、3 篇用 argparse 把「入口参数」收拾利落。但一个命令行工具真正运行起来之后，还有一个绕不开的问题：程序运行过程中到底发生了什么？ 前几篇的示例都靠 print() 把结果打到屏幕上，而真实工具需要的不是「打印结果」，而是「记录过程」——什么时间、哪个模块、什么级别的事件、是否值得运维人员关注。

本篇引入标准库 logging 的入门知识：级别体系（DEBUG 到 CRITICAL）、basicConfig 的格式化与配置、root 日志器与它默认输出到 stderr 的行为，最后给出 print 与 logging 的取舍标准。前置知识：print 语句（第一章）、异常体系（第四章第 8 篇）、if __name__ 骨架（本篇第 1 篇）。本篇之后，第 5 篇讲 Handler 分流与文件轮转，第 6 篇讲退出码与机器可读输出——「日志走 stderr、数据走 stdout」的分离原则正是本篇打下的地基；第 8 篇的待办事项工具会把日志真正用起来。

概念与原理

为什么需要日志系统

print() 作为诊断工具有四个天然局限。其一，没有级别：调试细节、常规事件、出错信息混在一起，无法区分轻重。其二，不可开关：想关闭调试输出只能删代码，或者用环境变量包裹一堆 if。其三，格式随意：时间、来源模块、线程号这些信息每次都要自己拼。其四，占用 stdout：详情见后文——stdout 是命令行工具向调用方「交货」的通道，把诊断信息打印进 stdout 等于在货物里塞废纸。

诊断信息的消费者其实有三类：正在开发调试的你（需要 DEBUG/INFO 细节）、维护运行环境的运维（只看 WARNING/ERROR/CRITICAL）、事后复盘的人（需要可信的时间与来源）。logging 模块的设计逐一回应了这四个局限：级别过滤决定什么该留、命名空间（logger 名字）标明来源、统一的格式化语法管排版、可插拔的输出方向（Handler）决定去向——第四个留到下一篇展开。

级别体系：数字、语义与过滤

logging 定义五个标准级别，从低到高依次是：DEBUG（调试细节，只在排查问题时开启）、INFO（常规事件，程序按预期工作）、WARNING（潜在问题，当前仍能继续）、ERROR（出错事件，功能受损但程序未死）、CRITICAL（严重错误，程序可能无法继续）。它们背后是单调递增的数字，级别比较就是数字比较：

import logging

for level in (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL):
    print(level, logging.getLevelName(level))

10 DEBUG
20 INFO
30 WARNING
40 ERROR
50 CRITICAL

getLevelName() 是数字与名字互转的官方接口：传整数返回名字，传名字返回数字。模块级常量 logging.DEBUG 本身就是整数 10，logger.info(msg) 的语义就是「这条记录级别为 20」。为什么默认只显示 WARNING 及以上？一个正常工作的程序每分钟可能打出成百上千条 INFO，全显示出来毫无意义；把默认值设在 WARNING，等于「只报告值得注意的事」，需要细节的人再显式调低级别。注意级别名字大小写敏感：常量必须写 logging.INFO；如果向 basicConfig 传字符串级别（下文会用到），必须严格写 "INFO"，写 "info" 会当场抛 ValueError——实测见「易错点」。

一条日志记录经过两道过滤。第一道在 emit 之前：logger 先检查自己的有效级别（有效级别沿着命名空间向上找第一个设置过的级别），logger.debug(...) 只在 logger.isEnabledFor(logging.DEBUG) 为真时才真正构建记录，这是 logging 惰性设计的根基。第二道在输出之前：到达每个 Handler 时再按 Handler 自己的级别过滤一次。本篇只涉及第一道，第二道是下一篇的主角。

root 日志器与默认输出到 stderr

logging.debug/info/warning/error/critical 这些模块级函数，本质是 root 日志器（名字固定为 root）的便捷入口：logging.warning(msg) 等价于 logging.getLogger("root").warning(msg)。一个重要机制：这些便捷函数在 root 还没有任何处理器时，会隐式调用一次 basicConfig()，装上一个默认的 StreamHandler——目标 stderr、级别空（照单全收）、默认格式「级别:名字:消息」；真正负责过滤的是 root 默认的 WARNING 级别。模块内部另有一只更深的兜底处理器 lastResort，只在传播链上完全找不到处理器时才出手（例如某个 logger 设了 propagate=False 又没有自己的处理器——第 5 篇讲完传播链你就能读懂这个场景）。两个机制合起来产生一个经典后果：模块级日志一旦触发过默认输出，root 就带着处理器了，之后再调用 basicConfig 便不再生效——这正是「易错点 1」的机制，读文章时把两处对照着看。日志默认走 stderr 而不是 stdout，是刻意的设计：stdout 是工具「交货」的通道（第 6 篇的 --json 输出就走 stdout），诊断信息放在 stderr，两者互不污染——Shell 学习者熟知的 2>err.txt 正是为这条通道准备的。

级别怎么选，是工程习惯问题，不是语法问题。一条实用路线是：开发阶段全局 level=logging.DEBUG，把细节都放出来；发布前改回 INFO 或 WARNING；线上出问题时，再用「只把某个可疑模块降到 DEBUG」的方式精准排查——这要求日志按模块命名（下文 __name__ 惯例），否则只能全开全关。日志是写给未来的自己的人看的：宁可多记一条 WARNING 的上下文，也别让 ERROR 裸奔没有参数。

操作与实现

实测一：什么都不配置时，日志去哪了

先看默认行为。把下面的脚本存为 default_out.py 并运行：

import logging

logging.debug("DEBUG 细节，默认不显示")
logging.info("INFO 常规事件，默认不显示")
logging.warning("WARNING 潜在问题，默认显示")
logging.error("ERROR 出错事件，默认显示")

python default_out.py 1>out.txt 2>err.txt
echo "--- stdout 收到的字节数 ---"
wc -c < out.txt
echo "--- stderr 收到的 ---"
cat err.txt

--- stdout 收到的字节数 ---
0
--- stderr 收到的 ---
WARNING:root:WARNING 潜在问题，默认显示
ERROR:root:ERROR 出错事件，默认显示

两个事实同时得到验证：DEBUG/INFO 被过滤掉了，只留下 WARNING 与 ERROR；这些输出落在 stderr，stdout 空空如也。每行格式是「级别:logger 名:消息」，root 就是 root 日志器的名字。

实测二：basicConfig 配置级别与格式

logging.basicConfig() 是入门阶段唯一的配置入口，它可以一次设定 root 日志器的级别、格式与时间格式。所谓「basic」，是相对 Handler/Formatter 的精细组装（第 5 篇）而言的：

import logging

logging.basicConfig(
    level=logging.WARNING,
    format="[%(levelname)s] %(name)s: %(message)s",
)
logging.debug("DEBUG 被过滤")
logging.info("INFO 被过滤——级别过滤的实测")
logging.warning("WARNING 通过过滤")

[WARNING] root: WARNING 通过过滤

这就是级别过滤的实测：把级别抬高到 WARNING 后，logging.debug 与 logging.info 的各一条记录在构造之前就被拦下，屏幕上只剩下 WARNING。format 字符串里用 %(字段)s 占位，最常用的四个字段是：asctime 记录时刻（依赖 datefmt 指定格式）、name 日志器名字（来源）、levelname 级别名字、message 消息本体。日期时间是可选的，但工程日志几乎都会带上：

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s | %(name)s | %(levelname)s | %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)
logging.warning("带时间戳的警告")

2026-09-03 12:06:18 | root | WARNING | 带时间戳的警告

（时间戳取自运行时刻，因此你运行时会得到不同的值，其余字段固定。）datefmt 用的是 time.strftime 的语法：%Y 四位年份、%m 月份、%d 日、%H:%M:%S 时分秒。

实测三：logger 命名惯例 `name`

直接用模块级函数会丢失「谁打的日志」这个信息——所有记录都挂在 root 名下。工程惯例是每个模块创建自己的 logger：

import logging

logging.basicConfig(level=logging.INFO, format="[%(name)s] %(levelname)s: %(message)s")
logger = logging.getLogger(__name__)
logger.info("来自 %s 的记录", __name__)
logger.info("惰性格式化：%s", 42 * 42)

[__main__] INFO: 来自 __main__ 的记录
[__main__] INFO: 惰性格式化：1764

脚本直接运行时 __name__ 为 "__main__"；被 import 时它是模块的完整路径名（如 shop.order），天然形成课程第五章讲过的点分层级——第 5 篇会看到这个层级如何在过滤时生效。注意第二条消息的写法：logger.info("惰性格式化：%s", 42 * 42) 不拼接字符串，而是把消息模板与参数分开传。这样即便该级别被过滤，42 * 42 也不会被求值——这是 logging 性能设计的核心：过滤掉的日志要接近零成本。若写 logger.info(f"惰性格式化：{42 * 42}")，无论是否需要输出，f-string 都会先完成拼接。

实测四：print 与 logging 各走一条通道

把两者放进同一个脚本，观察流分离：

import logging

print("print 写给 stdout")
logging.basicConfig(level=logging.INFO)
logging.info("logging 写给 stderr")

python streams.py 1>out.txt 2>err.txt
echo "--- stdout 收到的 ---"
cat out.txt
echo "--- stderr 收到的 ---"
cat err.txt

--- stdout 收到的 ---
print 写给 stdout
--- stderr 收到的 ---
INFO:root:logging 写给 stderr

于是取舍标准就很清晰了，可概括为三条。第一，给最终用户看的「业务结果」用 print：它应该出现在 stdout，好让调用方用管道重定向、用第 6 篇的方式做机器可读输出。第二，给开发者/运维看的「运行过程」用 logging：级别、时间、来源、可关闭，全部免费。第三，一次性脚本、REPL 里试一句话，print 足够；任何要跑数小时、会被别人调用、出错要追溯的工具，上 logging。

易错点与陷阱

1. basicConfig 一生只生效一次

basicConfig 的文档行为是：只在 root 日志器还没有任何 Handler 时执行。以为调用两次就能换格式，是新手第一大坑：

import logging

logging.basicConfig(level=logging.INFO, format="第一个格式: %(message)s")
logging.basicConfig(level=logging.DEBUG, format="第二个格式: %(message)s")
logging.info("第二次 basicConfig 是否生效？")

第一个格式: 第二次 basicConfig 是否生效？

第二次调用被静默忽略：格式仍是第一个，级别也停留在 INFO（DEBUG 的记录被过滤）。比这更隐蔽的触发方式是别处先打了日志：如前文「概念与原理」所述，logging.info(...) 这类模块级函数在 root 无处理器时会隐式调用 basicConfig()，把默认处理器装上——等到你自己的 basicConfig 执行时，if not root.handlers 已经不成立，于是静默放弃。所以经过严格实测：先打一条默认日志再配置，自定义格式不会生效。工程上的对策是：配置只在程序入口（main() 里、if __name__ == "__main__" 块内）做一次，确保它先于一切日志调用执行。

2. 级别字符串大小写敏感

basicConfig(level="INFO") 合法，level="info" 直接抛异常：

import logging

try:
    logging.basicConfig(level="info")
except ValueError as exc:
    print("级别字符串大小写敏感:", exc)

级别字符串大小写敏感: Unknown level: 'info'

logging 内部用字典按名字精确查级别，只有 DEBUG/INFO/WARNING/ERROR/CRITICAL 五种大写写法合法。保存配置时若支持用户输入级别，记得先 .upper() 再校验。

3. 以为日志会进 stdout

默认输出在 stderr（本篇实测二已证明）。后果是：脚本里 python tool.py > 结果.txt 只能收到业务输出，日志一条都没有——这其实是好事，日志留在终端让运行者看见。真正要警惕的是反过来：用了 logging 却把业务数据也 print 到 stderr，或者把日志打到 stdout 污染第 6 篇的 JSON 输出。记住分工：数据走 stdout，过程走 stderr。

4. 只配格式忘了配级别

basicConfig(format=...) 不传 level 时，root 日志器保持默认的 WARNING，于是 logger.info(...) 全线静默。实测：

import logging

logging.basicConfig(format="%(message)s")
logging.info("INFO 不出现")
logging.warning("WARNING 出现")

WARNING 出现

调试时「怎么什么都没有」十有八九是这一条。诊断顺序：先确认级别设置，再看消息级别是否够高。

小结

本篇建立了日志的三块基石：级别体系（DEBUG<INFO<WARNING<ERROR<CRITICAL，数字 10/20/30/40/50，过滤在构造记录之前）、格式（basicConfig 的 level/format/datefmt，asctime/name/levelname/message 四个字段）、通道（root 日志器与 lastResort 默认把 WARNING 及以上写进 stderr）。同时明确了 print 与 logging 的分工：print 交付业务结果到 stdout，logging 记录运行过程到 stderr。四个易错点告诫我们：basicConfig 只生效一次、级别字符串大小写敏感、通道别走反、级别别忘了配。下一篇把这些配置拆开，用 Handler 把日志同时送到控制台与文件，并处理文件轮转。

练习与思考题

把本篇第 2 篇练习的 argparse 小工具加日志：INFO 记录收到的参数与计算结果，WARNING 记录「参数可疑」的情况。运行后用 python tool.py > out.txt 验证业务输出与日志互不干扰。
解释 logger.info("结果: %s", expensive()) 与 logger.info(f"结果: {expensive()}") 在级别被过滤时的行为差异，并说明日志为什么这样设计。
把实测三的时间格式改为 datefmt="%H:%M:%S"，只显示时分秒；再想想如果想让时间按 UTC 而非本地时间显示，应该查哪个参数（提示：logging.Formatter 的 converter 属性）。
验证「basicConfig 只生效一次」：先写任何一条 warning 触发出默认输出，再调用 basicConfig(format=...)，观察格式是否生效，并用「root 已有 Handler」解释原因。