聊日志这个事乍一听没什么技术含量既不像算法那样性感也不像新框架那样时髦。但恰恰是这种“不起眼”的基础能力决定了线上出故障时你是十分钟精准定位还是通宵翻服务器干瞪眼。Python 日志记录Logging最正统的方案就是标准库里的 logging 模块我见过太多项目从第一天就用 print 裸奔等日志量上来、事故多起来才知道这套内置体系有多值钱。这篇文章我会从日志体系的整体设计讲起逐个拆解 Logger、Handler、Formatter、Filter 四大核心组件再给出从开发到生产环境都能直接抄的配置方案最后把高频踩坑点集中列清楚。适合想把日志从“能跑”做到“可靠”的开发者也适合正准备给团队搭建统一日志规范的负责人参考。1. 先想清楚再动手日志体系的设计思路1.1 为什么 print 救不了生产事故先讲一个我自己经历过的场景。某天凌晨线上接口突然大面积超时数据对账对不上我登录服务器想复盘结果发现服务日志全是一堆 print 打到 stdout 的零散输出既没有时间戳也没有级别区分更倒霉的是进程一重启之前的输出全被冲没了。那一刻你会深刻理解print 用来调试 100 行的小脚本没问题但放在生产环境里它连“事后复盘”的基本条件都满足不了。print 和 logging 的本质区别在于print 是面向“人看控制台”设计的输出方向固定、格式固定、没有分级而 logging 是一套面向“程序化处理日志”的完整管线它把日志的产生、加工、路由、输出拆成了相互独立的部分你可以让调试信息只在开发环境出现让错误信息同时进文件和控制台让日志按大小自动轮转还能在毫秒级的高频路径上把性能损耗压到最低。换个更直白的说法print 是把所有话都喊给现场所有人听logging 则是给每句话贴上重要级别标签再按你的规则分派给不同的人——重要的送进档案室永久保存普通的写在白板上废话直接丢进垃圾桶。生产事故复盘的时候你需要的绝不是现场碎片而是一份完整、有序、可追溯的档案。1.2 日志级别不是摆设每个级别怎么用logging 内置了五个标准级别从低到高分别是 DEBUG、INFO、WARNING、ERROR、CRITICAL。级别本质是一个整数阈值logger 只会输出大于等于自身阈值的记录。这个机制看起来简单但我观察到一个普遍现象很多人从头到尾只用 INFO或者反过来不管什么内容都往 ERROR 里塞级别体系形同虚设。我自己的用法是DEBUG 记开发期排查所需的一切细节比如每次请求的参数、中间变量的取值这些内容量最大、噪音最多绝不能在生产环境全量打开INFO 记关键业务节点的状态流转比如服务启动完成、订单创建成功、任务调度触发目标是让运维和业务方扫一眼就知道系统在干什么WARNING 记可以继续运行但需要关注的异常状况比如接口响应时间超过阈值、重试了第三次才成功这类“还没挂但值得警惕”的事件ERROR 记导致当前操作失败的异常通常要带上完整堆栈CRITICAL 留给服务起不来、数据库连不上、核心功能整体瘫痪这类必须立刻喊醒人的场景。这里有一条实操建议不要把日志级别硬编码死在代码里而是通过环境变量动态指定。开发环境默认 DEBUG生产环境默认 INFO出问题时临时调到 DEBUG 再恢复不需要改代码重新发布。标准写法是用 os.getenv(LOG_LEVEL, INFO).upper() 来设定根日志级别这符合“配置与代码分离”的基本思路。1.3 一条合格日志应该包含什么很多人以为日志就是“把要看的字符串打出来”其实一条能支撑事后分析的日志至少应该包含四类信息时间、来源、级别、内容。时间要精确到秒甚至毫秒来源要能定位到模块和行号级别要便于批量过滤内容要描述清楚发生了什么。错误日志还应该包含异常类型、堆栈信息和当时的上下文参数。举个例子同样是记录“用户登录失败”一种写法是logger.error(login failed)这种日志除了告诉你登录挂了什么线索都没有另一种写法是logger.warning(user%s login failed, reason%s, ip%s, user_id, err_msg, ip)排查的人一眼就能看到是谁、为什么、从哪里来。参数化的写法也符合 logging 的最佳实践把占位符留给 logging 内部去格式化而不是提前用 f-string 拼好字符串——这一点后面讲性能的时候还会再提到。2. 四大核心组件拆开看Logger、Handler、Formatter、Filter2.1 Logger入口与层级传播Logger 是你调用 logging 的入口对象平时写的logging.getLogger(xxx)拿到的就是这个东西。它本身并不直接输出日志而是把日志记录向下传递给 Handler 处理。Logger 之间按照名字的层级关系组织比如名字叫a.b的 logger 是a的子级a又是根 logger 的子级。这个层级关系引出了 logging 体系里最容易踩的第一个大坑传播propagation。默认情况下一个日志记录不仅会被当前 logger 的 handler 处理还会沿着层级向上被所有祖先 logger 的 handler 再处理一遍。如果根 logger 配了一个控制台 handler你自己又给子 logger 配了一个文件 handler结果就是同一条日志既出现在控制台又出现在文件里看着没问题但如果你在子 logger 和根 logger 上都加了同样的 handler日志就会被打两遍甚至更多遍这就是“日志重复”最常见的来源。我推荐一个通用铁律在应用代码里统一使用logger logging.getLogger(__name__)获取 logger因为__name__天然反映了模块的包路径日志里带出的名字能直接定位到模块。然后在配置阶段明确决定传播策略——要么只在根 logger 上挂 handler所有子 logger 靠传播要么每个模块 logger 自配 handler 并设置propagate False两者取其一不要混着来。2.2 Handler日志去向和轮转策略Handler 决定日志的最终去向。标准库最常用的有 StreamHandler输出到控制台或任意流、FileHandler输出到文件、RotatingFileHandler按文件大小轮转、TimedRotatingFileHandler按时间周期轮转。选择 Handler 的核心逻辑只有一个你想让日志去哪里、以及怎么防止日志无限膨胀。开发环境通常只需要 StreamHandler把日志打到标准输出配合容器平台自带的日志收集能力生产环境必须落盘但单纯用 FileHandler 会踩一个很实在的问题——单个文件会无限增长几周下来就是一个几十 GB 的巨型文件编辑器打不开日志切片也困难。RotaingFileHandler 会在文件达到 maxBytes 时自动改名并新建文件配合 backupCount 参数保留最近几个备份文件这样磁盘占用就能控制在一个可预期的范围内。我自己的生产配置习惯是TimedRotatingFileHandler 适合业务日志按天归档、后续要做定时分析的项目RotatingFileHandler 按大小轮转更适合单文件超大、需要立即可读的场景。另外要注意如果你用的是 Python 3logging.handlers 这个子模块经常不会被自动导入手动配置时务必显式import logging.handlers不然访问 RotatingFileHandler 会直接报 AttributeError。2.3 Formatter格式化的细节Formatter 决定日志记录最终渲染成什么样子标准格式串里常用字段有 asctime时间、levelname级别名、namelogger 名、module模块名、lineno行号、message日志正文。我推荐的通用格式是%(asctime)s | %(levelname)-8s | %(name)s | %(module)s:%(lineno)d | %(message)s这里%(levelname)-8s的意思是左对齐并补足到 8 个字符宽度视觉效果上每一行的级别列都是对齐的用文本工具或者直接在终端里看可读性会明显好很多。时间字段有几种容易忽略的处理技巧。默认情况下 asctime 显示的是本地时间但生产服务器经常跨时区部署日志集中收集之后时间线会非常混乱。我习惯统一用 UTC 时间落盘做法是拿到 Formatter 之后手动把它的 converter 属性指到time.gmtime这样时间戳就变成 UTC。显示上我还习惯把 datefmt 设成%Y-%m-%dT%H:%M:%S%z这类 ISO 风格后续无论对接日志平台还是人工阅读都很友好。2.4 Filter精细过滤Handler、Formatter 解决的是“往哪打”和“打成什么样”Filter 解决的是“到底哪些能打”。日志级别只能做粗粒度筛选Filter 则允许你写任意规则在日志记录被 handler 处理之前拦截或放行。最常见的需求是过滤健康检查类的噪声。很多服务每一秒都会被探活请求打一次这些请求通常不需要进日志我在实践中写过这样一个 Filter检查 record.getMessage() 里是否包含 /healthz 路径包含就直接返回 False日志记录被丢弃。用 Filter 的好处是不用改业务代码统一加在 handler 上所有经过该 handler 的日志都会被过滤。还有一个场景是给日志附加上下文。Filter 的另一个合法操作是在日志记录对象上动态挂额外字段比如给每条日志带上当前请求的 request_id后面做链路检索时非常有用。到这里你已经看到了一个完整事实一条日志从业务代码里调用到最终写到磁盘依次经过 Logger 的级别检查、Filter 的规则过滤、Formatter 的格式渲染、Handler 的实际输出每一层都可以独立定制这也正是 logging 比 print 高一个维度的根本原因。3. 从入门到生产三种配置方案实操3.1 快速起步basicConfig 够用但别贪如果只是脚本项目或者临时排查任务直接用 basicConfig 是最快的入口。它一行就能同时设置级别、格式、输出目标import logging logging.basicConfig( levellogging.INFO, format%(asctime)s | %(levelname)-8s | %(name)s | %(message)s, datefmt%Y-%m-%d %H:%M:%S, handlers[ logging.StreamHandler(), logging.FileHandler(app.log, encodingutf8), ], ) logger logging.getLogger(__name__) logger.info(服务启动完成)这里有一个细节值得强调basicConfig 只有在根 logger 没有配置任何 handler 的时候才会生效如果你之前已经手动添加过 handler再调用 basicConfig 是无效的。而且 basicConfig 的粒度比较粗没法对不同 logger 设置不同级别也无法优雅地处理复杂的轮转策略。我的建议是basicConfig 适合作为个人脚本和小工具的默认方案但只要是会长期运行的服务就别在这里将就。不要等到日志文件 8 GB 了才去后悔当初没有做轮转日志配置从一开始就应该按生产标准来搭。3.2 手动装配 Handler 链当项目复杂度上来需要不同模块输出到不同目标时手动装配 Handler 是很直观的做法。它比 basicConfig 清晰也比后面讲的 dictConfig 更贴近常规代码思维。import logging import logging.handlers logger logging.getLogger(myapp) logger.setLevel(logging.DEBUG) console_handler logging.StreamHandler() console_handler.setLevel(logging.INFO) console_handler.setFormatter( logging.Formatter(%(asctime)s | %(levelname)-8s | %(message)s) ) file_handler logging.handlers.RotatingFileHandler( app.log, maxBytes10 * 1024 * 1024, backupCount5, encodingutf8, ) file_handler.setLevel(logging.DEBUG) file_handler.setFormatter( logging.Formatter(%(asctime)s | %(levelname)-8s | %(name)s | %(lineno)d | %(message)s) ) logger.addHandler(console_handler) logger.addHandler(file_handler) logger.propagate False这个方法的核心是“一个 logger多个 handler各自独立级别和格式”。控制台只保留 INFO 以上文件保留 DEBUG 以上两者互不干扰。需要特别注意的是logger.propagate False这一行这是防止日志上抛到根 logger 被二次输出的关键。手动装配适合模块数量不多的项目它的缺点在于配置逻辑散落在业务代码里想统一调整格式、级别就需要改多处代码。当规模再往上走我强烈建议把配置从代码里抽离成一份独立的字典也就是 dictConfig 方案。3.3 生产标准dictConfig 一份配置管全家dictConfig 是 Python 官方推荐的生产级配置方式。它用一份字典描述所有 logger、handler、formatter 和 filter代码里只需要调用一次logging.config.dictConfig(config)之后所有模块的 logger 都自动生效。import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { verbose: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(module)s:%(lineno)d | %(message)s, datefmt: %Y-%m-%dT%H:%M:%S%z, }, simple: { format: %(levelname)-8s | %(message)s, }, }, handlers: { console: { class: logging.StreamHandler, level: DEBUG, formatter: verbose, stream: ext://sys.stdout, }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: verbose, filename: logs/app.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf8, }, }, loggers: { : { handlers: [console, file], level: INFO, propagate: False, }, }, } logging.config.dictConfig(LOGGING_CONFIG)这份配置里有几个容易被忽视的关键点。disable_existing_loggers默认是 True如果设置成默认值dictConfig 执行时会把之前已经创建好的 logger 全部禁用导致一些模块日志神秘消失所以生产配置务必显式设为 False。: {...}这一项配置的是根 logger根 logger 上挂好 handler 之后所有子 logger 通过传播机制共用同一套输出业务代码里只需getLogger(__name__)就能获得一个格式统一、输出一致的 logger。dictConfig 还支持通过ext://前缀引用外部对象比如ext://sys.stdout这种方式在配置里直接引用 Python 对象比硬编码文件名和流更方便。等你需要把这份配置交给运维团队统一管理时还可以把它改写成 JSON 或 YAML 文件加载真正做到配置与应用代码分离。3.4 异步日志与性能调优日志写入本质是 I/O 操作在每条请求都要输出若干条日志的高并发服务里同步写盘会成为隐藏的性能瓶颈。logging 标准库从 3.2 版本开始提供了 QueueHandler 和 QueueListener 组合原理非常朴素主线程把日志记录塞进内存队列就立即返回后台单独起一个线程负责从队列取出并写盘把同步 I/O 变成异步。import logging import queue from logging.handlers import QueueHandler, QueueListener record_queue queue.Queue(-1) queue_handler QueueHandler(record_queue) file_handler logging.FileHandler(app.log, encodingutf8) file_handler.setFormatter( logging.Formatter(%(asctime)s | %(levelname)-8s | %(message)s) ) listener QueueListener(record_queue, file_handler) listener.start() logger logging.getLogger(app) logger.setLevel(logging.INFO) logger.addHandler(queue_handler) logger.propagate False使用异步日志有一个必须记住的规矩程序退出前要调用listener.stop()否则队列里可能还有日志没来得及落盘进程一退出就直接丢了。另外异步方案本质上是用丢日志的极小概率换取吞吐量对于必须保证不丢失的核心审计日志还是建议同步写入数据库或专用日志通道。还有一个小到不值得单独开节的性能细节调用logger.debug(fvalue{x})时即便 DEBUG 级别被关闭f-string 也会在函数调用前被完整求值白耗 CPU。而logger.debug(value%s, x)是惰性求值只有日志真正启用时才会格式化。高频路径上积少成多还是养成用 %-占位符的习惯更稳妥。4. 高频问题与排查实录4.1 日志重复输出的真相日志重复是排查频率最高的问题症状是控制台里每一条日志都出现两次甚至三次。核心原因几乎都指向同一个机制propagate 传播。假设根 logger 加了控制台 handler模块 logger 也加了控制台 handler模块里产生的日志先被模块 handler 输出一次再传给根 logger 被输出第二次于是重复。解决思路两条一是如果所有 handler 都挂在根 logger 上子 logger 就不应该再挂 handler让日志靠传播机制统一输出二是如果子 logger 确实需要独立配置必须在子 logger 上设置propagate False。尤其在使用第三方库时第三方库往往会自己创建 logger 并挂 handler它们的日志传播到你的根 logger 之后重复问题会变得特别隐蔽排查时可以用logger.handlers和logger.propagate两个属性逐个检查各级 logger 的状态。4.2 异常到底怎么记才能还原现场这是我在 code review 里重复讲得最多的问题。很多人在 except 分支里写logger.error(fsomething failed: {e})只把异常信息拼进字符串结果日志里只有一句话没有堆栈根本看不出调用链。正确做法是使用logger.exception或者显式传exc_infoTruetry: result risky_operation() except Exception: logger.exception(业务操作失败关键参数: %s, params)logger.exception等价于在 ERROR 级别上自动附带当前异常堆栈日志里会同时出现异常类型、错误信息、完整 traceback排查的人能顺着堆栈直接找到出事的那一行。另一个容易忽略的点是exc_infoTrue放在 except 分支内才有意义如果你把异常对象当作普通参数传入但没设置 exc_info它是不会自动带堆栈的。还有一个相关坑有人习惯raise之后再logger.error结果日志打了一遍异常又往外抛被上层再次记录DB 里相同错误出现两三条。我建议在一个进程内的异常链路上要么记录日志要么抛出异常只在最顶层统一记录一次避免重复刷屏。4.3 敏感信息混进日志的防范日志里最容易出事故的不是日志功能本身而是把不该出现的内容打进去了。我见过真实案例有人把完整的数据库连接串直接打印到日志有人为了排查方便把用户密码、身份证号、支付信息加进了 DEBUG 输出最后日志文件泄露导致数据安全事故。最靠谱的防御是源头控制日志输出前人工确认不包含敏感字段打印用户相关内容时一律脱敏比如邮箱显示a***domain.com手机号显示138****1234。我在团队里还维护了一个工具类专门负责对日志参数做脱敏替换。如果项目里已经有历史日志可以加一层 Filter 做兜底拦截包含常见敏感关键词的记录并替换内容但这终究只是亡羊补牢不能替代源头治理。日志平台侧的权限管理和定期审计同样不能省。4.4 多进程场景下的轮转与写入多进程服务里日志表现得最怪的两个问题日志内容互相覆盖以及轮转时文件被错误切换。标准库的 RotatingFileHandler 在设计上没有承诺跨进程安全两个进程同时开启一个文件写入会互相覆盖和错乱到轮转的时候进程 A 把 log 改名为 log.1进程 B 还在往旧的句柄写内容就丢了。三种常见解法第一每个进程自己写独立的日志文件文件名里带上进程号或实例编号再交给日志采集系统统一归集第二所有进程把日志通过 UDP/TCP 发给一个专用的日志进程去写盘这种集中式方案和 QueueListener 的原理一脉相承第三如果外部有成熟的日志轮转工具接管轮转Python 侧改用 WatchedFileHandler它只负责按当前文件名重开文件轮转由外部工具完成。具体选择取决于你的部署架构但核心判断标准只有一个日志文件的写入和轮转必须由唯一一个控制方负责。4.5 日志问题速查表把上面的实战经验整理成一张速查表遇到问题直接对照定位。症状根因解决方案日志重复输出子 logger 和根 logger 都挂了 handler且未关闭传播只在一层挂 handler或设置 propagateFalse有 ERROR 但没堆栈拼接异常信息时未传 exc_info用 logger.exception 或 logger.error(..., exc_infoTrue)中文日志乱码FileHandler 使用系统默认编码创建时显式指定 encodingutf8日志时间与服务器不一致Formatter 默认用本地时间设置 formatter.converter time.gmtime统一 UTC多进程日志丢失或轮转错乱多个进程同时写同一文件按进程拆文件或集中到日志进程统一写配置后某些模块日志消失disable_existing_loggers 未设 FalsedictConfig 中显式设置 disable_existing_loggersFalse这张表背后其实是一个更通用的排查方法论日志出了问题先分清是“产生”环节的问题还是“输出”环节的问题。产生环节多和 Logger 层级、级别设置有关输出环节多和 Handler 配置、编码、多进程有关分清楚之后至少能少走一半弯路。5. 进阶一点结构化日志与链路追踪5.1 让日志变成机器可读的结构化数据传统文本日志最大的问题是字面意思只有人能看懂程序很难直接按字段解析。当你需要把日志接入日志平台按级别统计错误量、按请求 ID 过滤整条调用链、做告警聚合时文本日志就得付出大量解析成本。结构化日志的思路是把每条日志变成 JSON 对象每个字段独立成键值对。标准 logging 就能实现简单的结构化输出只需要自定义一个 Formatterimport json import logging class JsonFormatter(logging.Formatter): def format(self, record): payload { time: self.formatTime(record), level: record.levelname, logger: record.name, module: record.module, line: record.lineno, message: record.getMessage(), } if record.exc_info: payload[exception] self.formatException(record.exc_info) return json.dumps(payload, ensure_asciiFalse)把JsonFormatter挂到生产 Handler 上每一行日志就变成一个 JSON 对象。日志平台收集后可以直接按level字段过滤错误按logger字段聚合模块耗时按moduleline定位代码位置分析效率比文本日志高一个量级。代价是日志文件肉眼可读性下降但那是可以通过终端工具的同学现场调研时 jq 格式化一行命令就解决了不值得因此放弃结构化。5.2 用请求 ID 把散落日志串成一条线单个请求在系统里会穿过多个模块网关进来业务逻辑处理缓存读取数据库查询最后返回结果。每个模块各打各的日志日志本身互不关联出问题时想还原一趟完整的调用链路就得靠人工按时间戳拼图效率极低。请求 ID 就是为了解决这个问题。思路很简单请求入口处生成一个 UUID 作为请求 ID通过协程上下文传递日志 Filter 在渲染前把请求 ID 附加到日志记录上最终每一行日志都带上这个 ID。import logging import uuid from contextvars import ContextVar request_id ContextVar(request_id, default-) class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id request_id.get() return True formatter logging.Formatter( %(request_id)s | %(asctime)s | %(levelname)-8s | %(message)s )请求进入时设置一次结束整个生命周期后恢复token request_id.set(str(uuid.uuid4())) try: # 处理请求的业务逻辑 pass finally: request_id.reset(token)用了 ContextVar 之后异步场景下每个协程都持有独立的请求 ID不会互相串。排查问题时只需要拿着出问题的那条请求 ID 一搜整条链路的所有日志就都出来了。这个方案虽然只有几十行代码但在微服务架构里属于性价比极高的免费午餐比引入重量级全链路追踪系统轻量得多。如果团队还处在“日志能打出来但查起来靠猜”的阶段我建议你先把请求 ID 这个能力补上。日志这件事的本质是你在为未来的自己铺路。代码里每多打一条结构化、含上下文、有级别的日志线上事故的定位时间就缩短一分。我自己的体会是配置日志不要追求一步到位先把“级别合理、落盘可靠、格式统一、能跟请求 ID”这几条底线守住等日志平台接入、告警规则、全链路追踪这些需求真正冒出来时再按需扩展也不迟。最后再分享一个小经验日志配置值得成为团队的 Code Review 检查项每次提交代码时顺手看一眼改到的地方有没有敏感信息、有没有把异常吞掉时间久了整个团队的日志质量会肉眼可见地变好。