Python日志记录最佳实践：从print到结构化日志一次说透

写 Python 也快十年了我见过太多项目把 logging 当成可有可无的摆设 print 满天飞线上出问题全靠用户截图反馈真正出事故的时候连个现场都找不到。日志这东西平时看着没用真到服务宕机、数据对不上、接口莫名超时的时候它就是你手里唯一的黑匣子。这篇我把自己这些年总结出的 Python 日志记录Logging最佳实践一次性整理出来从 Logger、Handler、Formatter 这些核心概念到生产环境可以直接抄走的 dictConfig 配置再到几个我踩过无数次的坑一次讲清楚。适合刚接触 logging 不久、想把日志方案系统化的开发者也适合被线上日志问题折腾过、想把项目日志彻底理顺的老手。1. 为什么“记日志”这件事值得认真对待1.1 日志不是 print 的升级版很多新手觉得 print 和 logging 差不多反正都能把信息打出来。但这两者的区别就好比在墙上用粉笔写个记号和建立一套带日期、分类、可检索的档案系统。print 只是把字符串扔到标准输出输出完就没了没有级别没有时间戳没有来源信息程序一重启连痕迹都找不到。而 logging 提供了一整套流水线你可以控制什么级别才输出、输出到哪里、用什么格式、要不要带堆栈还可以在运行时动态调整级别。print 还有一个隐蔽的问题它在输出时如果程序异常崩溃缓冲的数据可能来不及刷盘而 logging 配合合适的 handler能把信息更可靠地保留下来。这也是为什么稍微正经点的项目都应该用 logging 而不是 print。我见过一个老项目全部用 print 排障结果每次都要靠人肉盯着控制台而且 print 的内容还没法按模块屏蔽第三方库刷屏时你根本看不到自己的日志。1.2 没有日志的排障等于盲人摸象分享一个亲身经历。某服务每天凌晨有个定时任务偶发失败但项目里没有任何日志。排查的时候完全靠猜是数据库连接被回收了内存不够还是进程被重启了没有证据大家只能轮番猜最后临时插桩、等复现折腾了两周才发现是某个第三方 SDK 的线程池在低概率下抛了异常异常被上层静默吞掉。如果当时有一条带堆栈的 ERROR 日志几分钟就能定位。这件事之后我在所有项目里都把日志当成一等公民。一个可观测性好的系统不一定需要多贵的监控平台先把日志打对、打全、打得有结构排障效率能翻好几倍。日志就是程序的“黑匣子”它不产生业务价值但在出问题时能救命。2. 吃透 logging 的核心机制再动手2.1 四个核心对象Logger、Handler、Formatter、FilterPython 的 logging 模块设计得有点像一条流水线理解这条流水线上的四个角色你就掌握了 logging 的一大半。Logger日志的入口。你在代码里调用 logger.info() 时它负责接单判断这条日志的级别够不够放行然后决定交给哪些 handler。Handler真正干活输出的对象决定日志写到控制台、文件、网络还是消息队列。同一个 logger 可以挂多个 handler也就是说同一条日志可以同时进文件和终端。Formatter排版员负责把日志事件渲染成一行的文本比如加上时间、模块名、行号、级别。Filter安检员在日志发送到 handler 前做更细粒度的过滤比如按内容、按用户、按请求上下文过滤。用快递来类比Logger 是快递柜的接单口Handler 是运输渠道陆运、空运Formatter 是打包贴单的人Filter 是安检机。快递从接单口进入过安检被打包再通过不同渠道送出去。你想改哪个环节就动哪个对象这种设计让日志体系非常灵活。2.2 级别、传播机制和“看不见的根 Logger”logging 定义了五个标准级别DEBUG、INFO、WARNING、ERROR、CRITICAL对应数值分别是 10、20、30、40、50。logger 的 effective level 如果没设置就继承父 logger最终追溯到根 logger如果根 logger 也没设置默认是 WARNING。这也是为什么你在子模块里调 logger.info() 看不到输出——默认级别只放行 WARNING 以上的日志。传播机制是另一个容易踩坑的地方。默认情况下任何 logger 处理完成后只要没有把 propagate 设为 False日志事件还会继续向上传给父 logger直到根 logger。如果你的业务 logger 挂着文件 handler根 logger 又挂着自己的 handler一条日志就会被重复写两遍。很多“为什么日志打了两遍”的报障根源都在这里。后面我会专门展开怎么排查。2.3 先想清楚谁产生日志谁消费日志在写配置之前我会先问自己两组问题谁产生日志是应用自己的业务代码还是第三方库还是框架内部的日志谁消费日志是开发者在终端临时看还是统一收集到日志采集系统还是归档到文件里很多项目日志混乱就是因为所有日志堆在一起级别混着格式不统一第三方库的海量调试日志和业务日志混在一个文件里。我的习惯是应用自己的日志用独立的 logger 名比如 myapp.service.order第三方库保留它们自己的 logger 名在 root 上统一控制它们的级别和去向。这样既不让第三方库刷屏也不丢失关键错误。3. 生产环境里最值得养成的几个习惯3.1 不要直接用 root logger按模块获取 logger把日志全打到根 logger 上一开始很省事工程一复杂就崩所有第三方库都在和你在同一个根 logger 上输出你没法单独控制它们的量也没法按业务模块拆分文件。正确做法是每个模块里用 logging.getLogger(name)这样 logger 名天然带上包路径比如 myapp.service.order既方便按模块过滤又不会和其他库的名称空间撞车。我见过很多项目在入口处用 basicConfig 打天下然后到处 import logging 直接调 logging.info()。短期能用但一旦要按模块调整级别、按业务拆文件就得推倒重来。与其返工不如一开始就按模块化方式组织。3.2 配置用 dictConfig别再用 basicConfig 硬编码basicConfig 只能在根 logger 上做最简单的设置无法精细管理多个 logger、多个 handler、多个 formatter。生产环境我更推荐用 logging.config.dictConfig()用一个字典描述整个日志体系。配置可以独立成文件YAML 或 JSON也可以在代码里维护一个 dict改日志结构的时候不需要动业务代码。有人问为什么不用 fileConfigfileConfig 用的是旧式 configparser 格式能配置的东西有限对 filter 和自定义 formatter 的支持很别扭。dictConfig 表达能力更强也是目前的主流写法。新手看到 dictConfig 觉得结构复杂其实它就是把 formatters、handlers、loggers 三张表组织在一起多看两眼就熟了。3.3 结构化日志让日志变成可检索的数据传统日志是给人看的纯文本比如 2025-01-01 12:00:00 ERROR xxx。但如果要把日志接入采集分析系统纯文本非常难解析。现在越来越多人直接输出 JSON 格式的结构化日志每条日志是一个 JSON 对象字段包含 timestamp、level、logger、message、module、trace_id 等。采集端拿到 JSON 直接解析字段查询、聚合、告警都很方便。自己写一个 Formatter 就能输出 JSON不需要依赖第三方库。写的时候要注意message 字段里别放用户输入、密钥、敏感信息避免日志成为数据泄露的口子。结构化日志本质上是为监控和排障铺路哪怕你现在的系统还没有采集平台也建议从一开始就按结构化格式输出后面接入时不用翻工。3.4 Handler 选型控制台、文件轮转、远程采集控制台 handler适合本地开发和容器环境。容器日志走 stdout 是主流日志采集组件会从标准输出捞日志。文件 handler适合传统部署。一定要用带轮转的别一个文件写到天荒地老。远程收集适合分布式系统把日志直接发到统一日志平台。文件轮转我会优先用 RotatingFileHandler按大小轮转保留最近 N 个备份如果业务有明显的时间特征用 TimedRotatingFileHandler 按天切分。切分逻辑不复杂但要注意多进程写同一个文件会有竞争问题日志互相覆盖、轮转失效都可能发生。这种情况建议每个进程写各自独立的文件或者直接走日志采集组件而不是多个进程抢一个文件。3.5 日志级别用对才能发挥作用很多团队把 INFO 当成“所有信息都打”的代名词一天产出几十 GB真要排查的时候大海捞针。我的阈值策略很简单级别什么时候用DEBUG开发调试本地开着线上默认关闭INFO正常的业务里程碑任务开始、完成、接口成功WARNING可能有问题但不影响主流程比如重试、降级、缓存未命中ERROR功能已经受影响必须带上异常堆栈CRITICAL程序无法继续运行必须立即告警日志如果被滥用级别就失去了意义。宁可少而精不要多而滥。我在项目里还会定期看 ERROR 日志的量如果量大到没人看说明级别定得有问题。4. 一套可以直接抄的完整配置4.1 用 dictConfig 组织日志体系假设项目叫 myapp典型结构大概是myapp/ __init__.py config.py logger_config.py services/ __init__.py order.py我的习惯是把日志配置集中在 logger_config.py入口处调用一次 dictConfig。下面这份配置可以拿去做模板# logger_config.py import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s [%(levelname)s] %(name)s: %(message)s }, detailed: { format: %(asctime)s [%(levelname)s] %(name)s:%(lineno)d %(message)s } }, handlers: { console: { class: logging.StreamHandler, level: DEBUG, formatter: standard, stream: ext://sys.stdout }, file_info: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: detailed, filename: logs/myapp.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf-8 }, file_error: { class: logging.handlers.RotatingFileHandler, level: ERROR, formatter: detailed, filename: logs/myapp_error.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf-8 } }, loggers: { myapp: { handlers: [console, file_info, file_error], level: INFO, propagate: False } }, root: { level: WARNING, handlers: [console] } } def setup_logging(): logging.config.dictConfig(LOGGING_CONFIG)这份配置有几个细节值得注意。disable_existing_loggers 设成 False。原因很现实如果你在加载配置之前已经创建了一些 loggerdictConfig 默认会把它们全部禁用掉导致日志静默丢失。设成 False 可以避免这种“配置完反而没日志了”的诡异问题。myapp 这个 logger 的 propagate 设成了 False防止日志继续传给 root造成控制台重复打印。root 只给 WARNING第三方库的日志默认不会把控制台刷屏。错误日志单独一个文件排查 ERROR 时不用在大文件里翻。RotatingFileHandler 不会自动创建 logs 目录你要先手动 mkdir logs否则首次写入会失败。4.2 业务代码里怎么用# services/order.py import logging logger logging.getLogger(__name__) def create_order(order_id, user_id): logger.info(开始创建订单, order_id%s, user_id%s, order_id, user_id) try: # 业务逻辑 pass except Exception: logger.exception(创建订单失败, order_id%s, order_id) raise这里有两个非常重要的细节。第一logger.exception 只能在 except 块里调用它会自动带上当前异常堆栈记录为 ERROR 级别。这是我最常用的排障手法比 logger.error(xxx, exc_infoTrue) 少打几个字效果一样。第二日志参数用 %s 占位符不要贪方便写 f-string。虽然 logger.info(f...) 也能跑但 f-string 在日志被过滤掉之前就已经执行了格式化纯属浪费性能。而 %s 占位符是惰性的只有日志确定要输出时才做格式化。在高并发场景下这条优化非常明显。4.3 加一个 trace_id把一次请求串起来排查分布式问题最怕的就是一个请求在多个模块、多个线程之间流转日志之间没有关联你只能靠时间和关键字去猜。我的习惯是入口处生成一个 trace_id贯穿整条调用链。最简单的实现是用 Filter 往 record 里塞字段import uuid class TraceIdFilter(logging.Filter): def filter(self, record): # 实际项目中 trace_id 通常从请求头或上下文变量取 record.trace_id getattr(record, trace_id, uuid.uuid4().hex[:12]) return True然后在 formatter 的 format 里加上 %(trace_id)s再把这个 filter 挂到对应 handler 上。之后你看到所有日志都会带着同一串 ID排查时 grep 一下 trace_id整条调用链就浮出来了。要注意Filter 默认始终返回 True也就是说它只改 record 不拦日志。如果 filter 返回 False这条日志就会被丢弃可以用来做采样比如按 trace_id 哈希取模只记录部分日志控制线上日志量。不过 filter 里生成 trace_id 的时机要小心。如果每一条 record 都生成新的 trace_id日志之间还是没有关联。实际项目应该从上下文变量里取出入口时生成的 ID取不到再生成新的。我一直用 contextvars 或者 threading.local 存这个值简单可靠。4.4 异步写日志别让磁盘 IO 拖垮主流程Python 的 logging 在 handler 里写文件是同步 IO日常量小没问题但高并发下 FileHandler 的写锁会成为瓶颈。解决方案是 QueueHandler QueueListener日志先放进内存队列后台线程统一消费写文件主线程只做入队操作几乎无阻塞。一个最小实现长这样import logging import logging.handlers from queue import Queue queue Queue(-1) queue_handler logging.handlers.QueueHandler(queue) logger logging.getLogger(myapp) logger.addHandler(queue_handler) listener logging.handlers.QueueListener(queue, file_handler, console_handler) listener.start()几点提醒QueueListener 要在程序退出时调用 stop()否则队列里还没消费的日志可能会丢。内存队列本质上是进程内的如果进程崩溃未消费的日志就丢了。我通常只在性能敏感、能容忍少量丢失的场景用异步对日志完整性要求高的场景还是同步写文件更稳。4.5 容器和云环境只输出到标准输出如果服务跑在容器里日志最佳实践是只输出到 stdout由容器运行时或日志采集组件统一收集。不要在容器里写本地文件因为容器文件系统是临时的重启就没了。所以容器项目的 dictConfig 我通常只留一个 console handler等级设 INFO格式里带上服务名和环境字段方便采集端做索引。5. 我踩过的坑和一条条排查思路5.1 日志重复输出这是最常见也最让人头疼的问题现象是同一行日志在终端出现两次甚至更多。排查步骤我固定如下检查业务 logger 的 propagate 是不是 False。如果没设日志会再传给 root logger。检查 root logger 是否也挂了同样的 handler导致一条日志被处理两遍。检查代码里有没有重复调用 dictConfig 或 addHandler导致同一个 logger 被挂了两遍相同 handler。我见过最隐蔽的情况是某个第三方库内部也往 root logger 挂 handler和你的 handler 叠加于是控制台出现重复输出。解决方法是统一在入口处配置并且明确每个 handler 归属到哪个 logger关闭不相关的传播路径。5.2 日志“神秘消失”日志没出来常见原因有几种级别不够高。logger 或 handler 的 level 高于这条日志的级别过滤掉了。被 Filter 返回 False 拦截。程序异常退出缓冲区没来得及 flush。有些 handler 带缓冲进程被强杀时缓冲区内容会丢。文件没权限写。handler 创建时如果无法写文件logging 默认会静默吞掉错误你可能只在控制台看到一条警告然后什么都没发生。我的排查习惯是先写一个最小复现脚本把配置拆掉直接用 logging.basicConfig(levellogging.DEBUG) 调一遍看日志能不能出来。如果最小脚本能出再逐步把业务配置加回来看哪一步让日志消失。5.3 堆栈信息打印不全logging.exception 确实能带出异常堆栈但前提是它必须在 except 块里调用。如果你把异常存到变量在 except 外面才记录堆栈就没了。这时候要显式传 exc_infotry: ... except Exception as err: logger.error(调用外部接口失败, exc_infoerr)我见过太多定位慢的案例日志里只有一句“请求失败”没有堆栈等于白记。任何时候记录 ERROR都要保证带堆栈这是排障的底线。5.4 时区、编码和版本问题时区Python 默认日志时间是本地时间但容器里经常是 UTC。跨时区分析时最好在 formatter 里显式转换或者统一记录 UTC 时间并带上时区后缀否则不同环境的日志在时间轴上完全对不上。编码Windows 下文件 handler 必须指定 encodingutf-8否则中文日志很容易乱码。版本如果还在用 Python 3.6 或更早一些日志特性会有坑。尽量用受支持的新版本少给自己找麻烦。5.5 性能日志也能拖垮服务日志导致的性能问题大部分不是 logging 本身而是因为在日志内容里做了太多额外操作。比如# 不推荐即使不输出也会执行函数 logger.debug(user list: %s, get_all_users())等等这个写法其实也有问题参数在调用前总是先求值get_all_users() 依然会被执行。所以更稳妥的方式是加一层保护if logger.isEnabledFor(logging.DEBUG): logger.debug(user list: %s, get_all_users())这样在 DEBUG 级别被关闭时昂贵的函数根本不会调用。这个模式在高频日志、大对象ToString、序列化操作的场景特别有用。另外日志量大的时候格式化和 IO 都会消耗 CPU异步 handler 能缓解 IO 阻塞但最好还是从源头控制量比如对 DEBUG 做采样。最后再分享一个我自己的习惯新项目启动的第一天我就会把日志配置搭好而不是等出事故再补。日志模板固定好了之后几乎不会再动它。你在真实项目里遇到日志问题回头对照这篇文章的配置和排查清单大概率能省下不少半夜排障的时间。写代码一时爽日志缺失两行泪别等到线上出了事才明白日志是程序最后的体面。