1. 从print到logging日志翻车现场与日志模块存在的意义先讲一次我亲身经历的翻车现场。有一回我帮一个业务团队排查线上接口偶发超时的问题登录服务器打开日志目录结果发现里面躺着一堆没有任何时间戳、没有模块名、没有日志级别的print输出。更崩溃的是因为多线程并发那些print内容全混在一起根本分不清哪条日志是从哪个请求打出来的排查到半夜也没定位出问题。那次之后我就养成一个习惯凡是超过几百行、可能要长期维护的Python项目直接用logging模块而不是print。因为print只能把字符串丢到标准输出它没有级别、没有来源信息、没有格式控制更不可能把日志同时写到控制台和文件里。而logging模块自带三个核心能力分级过滤、灵活的输出目的地、统一的格式规范。这三个能力在小脚本里看不出价值项目一旦上了规模、上了生产环境就是能不能快速排查故障的分水岭。有个常见的误区是等出事的时候再上logging。但日志体系和监控体系一样都得提前设计。出事那一刻再去改代码、补日志不仅动作变形还可能漏掉关键链路的信息。成熟的团队会把日志当成和代码同等级别的交付物在开发阶段就规定好什么位置打info、什么位置打warning、什么位置打error错误信息里该带哪些上下文。这套约定在Python里用logging做起来非常自然因为它本身就是标准库不需要额外引入依赖。那问题来了logging模块的写法看起来很简单网上随便一搜就是三四行代码调用basicConfig但为什么真到了生产环境还是会有各种日志不输出、重复输出、文件不轮转、中文字符乱码的诡异问题答案在于很多人只看了最浅层的用法不理解logging内部那套Logger、Handler、Formatter、Filter的分工机制。这套机制是设计得很严谨的但不过脑子直接模仿代码自然容易踩坑。2. Logger、Handler、Formatter分工logging为什么设计得这么绕2.1 四个核心角色各管一段logging模块看起来绕本质上是把日志处理链路拆成了四个独立环节Logger日志的入口负责接收代码里发来的日志事件判断这条日志的级别是否达到阈值决定要不要继续往下处理。Handler真正干活的角色负责把日志写到指定目的地比如控制台、文件、网络socket、邮件等。Formatter负责把日志事件格式化成一串字符串决定一条日志到底长什么样包含哪些字段。Filter比级别更精细的过滤器可以在Handler或Logger层面拦截日志实现更复杂的过滤逻辑。打个比方Logger像公司前台收到访客日志事件先判断有没有预约级别够不够Handler像不同的会客室有的在文件里、有的在控制台Formatter像会客室里的接待话术规定怎么介绍来客Filter则像保安可以额外拦下一批不该进来的人。多数人第一次接触logging只看到一个全局函数或配置完全没意识到背后这套流水线。一旦配置了多个Handler又没搞清楚Logger和Handler之间的传播关系很快就会出现日志重复打印这类问题。2.2 Handler的选型与典型适用场景Handler的选择直接决定日志去向。日常用得最多的是这几种Handler目的地适用场景StreamHandler标准输出/标准错误本地调试、开发环境FileHandler单个文件量小、无需轮转的内部服务RotatingFileHandler按大小轮转的文件单机服务最常用TimedRotatingFileHandler按时间轮转的文件需要按天/小时归档的业务SocketHandler / SysLogHandler网络/系统日志日志统一采集到远端如果是单机部署我一般优先选RotatingFileHandler给日志文件设一个最大体积超过就按备份数滚动。如果是多进程服务比如Gunicorn起了多个worker进程间同时写同一个日志文件时标准库的Handler表现一般需要借助concurrent-log-handler或把日志直接发到集中式采集器否则会出现日志互相覆盖、内容错乱的情况。2.3 命名规范与propagate传播logging的Logger是有父子关系的命名按点号分隔比如app是app.api的父Logger。子Logger处理完日志事件后默认会把事件继续向上传给父Logger这个行为由propagate属性控制默认是True。这套设计本身很灵活但坑也埋在这里。如果根Logger配了一个ConsoleHandler子Logger自己又配了一个FileHandler那么一条日志在子Logger打出来之后会同时进入子Logger的FileHandler和父级Logger的ConsoleHandler。结果就是控制台和文件里各出现一次看起来像日志出了问题其实只是没有理解传播链路。避免重复的标准做法很简单要么只在某个顶层Logger配置Handler子Logger只负责打日志要么明确把子Logger的propagate设成False然后各自管理Handler。命名规范也是日志治理的重要环节。最佳实践是用logging.getLogger(__name__)让Logger名自动带上模块的完整路径。这样日志里能看到是哪个模块产生的排查问题就少走很多弯路。3. 一份能直接上生产的dictConfig模板与参数取舍3.1 为什么不要用basicConfig写生产配置basicConfig适合教学和小脚本只能做最简单的一次性配置且只能在没有任何Handler的情况下生效。一旦项目代码里多个模块分别调了basicConfig后调用的一方很可能悄悄覆盖前者的配置导致日志去向不可控。生产环境推荐用logging.config.dictConfig。它用一个字典描述整个日志体系所有Logger、Handler、Formatter、Filter都集中在一处定义方便统一管理。同时也支持从YAML或JSON文件加载运维和排查时可以调整级别不用改代码。3.2 一套完整模板与字段解释先给一套我常用的模板可以直接抄进项目里用。它包含控制台输出和文件输出文件按大小轮转格式里带时间、模块、行号、级别这些基础字段import logging import logging.config from logging.handlers import RotatingFileHandler LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s, datefmt: %Y-%m-%d %H:%M:%S } }, handlers: { console: { class: logging.StreamHandler, level: DEBUG, formatter: standard, stream: ext://sys.stdout }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: standard, filename: logs/app.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf-8 } }, loggers: { : { handlers: [console, file], level: INFO, propagate: False # 根Logger不需要再向上传递 }, api: { handlers: [file], level: DEBUG, propagate: False } } } logging.config.dictConfig(LOGGING_CONFIG)这段配置里几个字段必须解释一下disable_existing_loggers默认是True会把配置之前创建的所有Logger全部停用。很多人在模块导入阶段就创建了Logger随后又调用dictConfig结果之前的Logger全变哑巴。所以我通常显式写成False。levelLogger和Handler各自有独立级别。Logger判断一条日志要不要处理Handler判断处理后的日志要不要输出到自己的目的地。一个常见组合是Logger设DEBUG控制台Handler设DEBUG文件Handler设INFO这样开发时控制台能看到一切细节文件里只留INFO以上避免把磁盘写爆。maxBytes与backupCountmaxBytes设成10MBbackupCount设成5意味着单个文件超过10MB就轮转最多保留5个备份。这里的10MB和5个备份是常见起步值具体要看服务日志量和磁盘空间不要盲目套用。encodingutf-8FileHandler在打开文件时没有默认编码Windows下容易出现编码问题。显式指定UTF-8能避免大量中文字段乱码和生产环境日志读取困难。3.3 按日轮转与多进程注意点按大小轮转适合大部分场景但某些业务要长期归档比如按天留存接口访问日志这时候更适合TimedRotatingFileHandlertimed: { class: logging.handlers.TimedRotatingFileHandler, filename: logs/business.log, when: midnight, interval: 1, backupCount: 30, encoding: utf-8, formatter: standard }whenmidnight表示每天零点轮转backupCount30保留30天。它的问题是轮转操作依赖时间和文件名后缀多进程下容易出现多个进程同时改名同一个文件的情况。所以多进程服务里要么用外部工具做日志切割要么直接让采集器读文件内容轮转由采集侧负责避免应用层自己切文件。4. 日志轮转、结构化与脱敏这三个生产刚需怎么落地4.1 日志轮转防止磁盘被日志占满日志轮转的核心目的不是好看是让磁盘永远有空间。日志文件没有一个明确的上限线上跑一两个月可能膨胀到几十GB最后系统磁盘告警服务直接写不进文件反而比业务故障更先被击垮。RotatingFileHandler的轮转逻辑是当前文件超过maxBytes时先把旧的备份文件按序号顺延比如app.log.1变成app.log.2再把当前app.log改名成app.log.1最后创建新的app.log。这里有个注意点backupCount不要设得过大。有人担心日志丢太多恨不得留100个备份结果磁盘空间先爆炸。合理估算方式是单个文件体积上限乘以备份数再留30%余量算出来的结果别超过磁盘可用空间的20%。另一个容易被忽略的地方是日志目录的清理。程序只负责轮转自己创建的文件如果日志目录被其他临时文件占满程序通常不会自动清理。所以我习惯在部署脚本里加一个定时任务专门清理超过N天的一级日志文件应用层只做轮转。4.2 结构化日志让日志能真正被检索和分析传统的纯文本日志适合人眼直接看但到了日志平台解析和检索会非常痛苦。按空格或竖线分隔的字段解析逻辑稍不严谨一条日志里如果出现特殊字符整行解析就崩了。所以现代后端服务越来越倾向输出JSON格式的结构化日志。结构化的意思是把日志拆成一个个有key的字段比如{timestamp: 2025-01-01T00:00:00, level: ERROR, service: order-api, trace_id: abc123}。这样日志平台能直接按字段索引按trace_id把一次请求的所有日志串起来排查分布式问题时价值巨大。实现方式很简单直接用一个JSONFormatter或者在配置里自定义一个Formatter类import json import logging class JsonFormatter(logging.Formatter): def format(self, record): log_data { timestamp: self.formatTime(record, %Y-%m-%d %H:%M:%S), level: record.levelname, logger: record.name, module: record.module, line: record.lineno, message: record.getMessage(), } if record.exc_info: log_data[exception] self.formatException(record.exc_info) if hasattr(record, trace_id): log_data[trace_id] record.trace_id return json.dumps(log_data, ensure_asciiFalse) LOGGING_CONFIG[formatters][json] { (): JsonFormatter }格式里最好带上trace_id这类请求标识。做法通常是在中间件里生成一个UUID放到threading.local或contextvars再通过临时绑定到record对象上。这样所有相关日志拼起来就是一个完整的请求链路。这套做法在微服务架构里几乎是标配。4.3 敏感信息脱敏别把密码和Token打进去日志里最怕的不是量大是出现敏感信息。密码、Token、身份证、手机号、银行卡号一旦落到日志文件里再同步到日志平台基本等于泄露。很多人写代码时顺手把参数整个打印出来美其名曰方便排查结果一个DEBUG日志把数据库连接串里的密码暴露了这种事故我见过不止一次。脱敏的最佳方式是设置一道底线任何情况下代码里不打印完整密码、密钥、Token。在此基础上再做一个Filter做二次拦截兜底防止漏网之鱼import re class SensitiveDataFilter(logging.Filter): def __init__(self): super().__init__() self.patterns [ re.compile(r(password[\]?\s*[:]\s*)[^\,\s}], re.IGNORECASE), re.compile(r(token[\]?\s*[:]\s*)[^\,\s}], re.IGNORECASE), re.compile(r(api_key[\]?\s*[:]\s*)[^\,\s}], re.IGNORECASE), ] def filter(self, record): msg record.getMessage() for pat in self.patterns: msg pat.sub(r\1***, msg) record.msg msg record.args () return True把Filter挂到Handler上后即使有同事不小心把敏感参数传给日志最终落盘的内容也被替换成了***。需要注意Filter做好之后要测一遍别在Filter里自己抛异常否则日志链路会直接挂掉。4.4 异常堆栈error(e)和exception()的区别排查线上问题最怕的是日志里只有一行error: division by zero没有调用栈完全不知道在哪里炸的。所以记录异常时一定要保留堆栈信息。两个等价写法logger.error(处理订单失败, exc_infoTrue) # 等价写法只能在异常处理块里用 logger.exception(处理订单失败)logger.exception本质上就是带着exc_infoTrue的error级别日志但只能在except块里用因为exc_info取的是当前正在处理的异常。有些人的坏习惯是只写logger.error(ferror: {e})只打异常对象堆栈信息全丢了。到时候查一个KeyError要猜半天下线。5. 高频问题排查实录重复日志、文件不写、控制台乱码5.1 日志重复打印的排查链路日志重复打印是最常见的问题基本十次里有八次是传播机制或Handler重复注册导致的但每次的表现形式略有不同我列几条真实排查路径场景一子Logger和根Logger各配了Handler。表现是同一行日志输出两次。解决办法是最小化Handler只在根Logger配Handler子Logger只设级别把propagate保持True让事件上抛给根Logger统一处理。或者反过来子Logger设propagateFalseHandler只挂在自己身上。场景二同一Handler对象被重复addHandler。表现是输出次数随模块导入次数增加。这种情况常见于开发阶段某个模块每被import一次就调用一次logging.basicConfig或addHandler。排查方式是打断点看Handler列表或者直接打印logger.handlers确认是否有同一个对象出现多次。场景三第三方库的Logger影响了应用日志。某些库自己建了Logger且配了Handler导致应用日志里出现它们的重复内容。这时候需要检查字典配置里的disable_existing_loggers以及是否需要单独为第三方库的Logger设置级别或禁用。排查顺序建议从简单到复杂先确认根Logger配置再看子Logger的propagate最后检查代码里有没有重复调用配置函数。不要一上来就改代码先打日志看输出。5.2 日志文件不写或写不进去日志文件一直是空的常见原因有四类路径不存在、权限不足、配置里Logger名和实际创建名不匹配、文件被其他进程占用。路径不存在是最容易被新手忽略的。FileHandler不会自动创建不存在的目录必须先os.makedirs(logs, exist_okTrue)或者确保部署脚本已经建好目录。权限方面生产环境经常用非root用户跑服务日志目录如果只有root可写服务就会在写第一行日志时静默失败。有些情况下启动脚本用sudo跑开发环境没问题切到systemd守护进程后立刻写不进日志就是因为systemd用户没有目录写权限。文件被占用在Windows上尤其明显。编辑器或者日志查看工具打开了日志文件程序轮转时发现文件被占用轮转失败之后所有日志都写不进去。如果项目部署在Windows服务器上建议日志工具不锁文件或者定期重启清一下句柄。5.3 控制台中文乱码与控制台不输出控制台中文乱码几乎都是编码问题。同一套代码在Linux服务器上正常Windows控制台就乱码多半是Windows控制台默认编码不是UTF-8。这个问题的处理方式是尽量让日志输出到文件时指定UTF-8编码控制台展示时靠终端工具调整编码。生产环境一般看日志文件不太依赖Windows控制台所以文件侧的编码正确比控制台侧更重要。控制台完全没有日志输出除了配置问题之外还有一种容易被忽略的情况代码里用了if __name__ __main__这种入口但配置函数写在入口里模块被import时没有执行配置所以普通模块里调用logger时使用的是默认的root Logger而默认root Logger没有Handler于是所有日志都被静默丢弃。结果是文件里什么都没有、控制台也什么都没有程序却正常跑着。这种问题排查起来很讨厌因为你一开始甚至分不清是没打日志还是日志被丢了。5.4 日志性能与异步日志日志I/O虽然通常是异步的但Python的logging默认是同步阻塞式写入。高并发场景下每次写日志都走一次磁盘I/O可能在高峰时拖慢业务接口几十毫秒。这个量级对低延迟服务不可忽视所以有了QueueHandler和QueueListener这种异步采集方案。import logging import logging.handlers import queue log_queue queue.Queue(-1) queue_handler logging.handlers.QueueHandler(log_queue) root_logger logging.getLogger() root_logger.addHandler(queue_handler) listener logging.handlers.QueueListener( log_queue, logging.StreamHandler(), logging.FileHandler(logs/app.log) ) listener.start()QueueHandler接收日志事件后直接放入内存队列业务线程立刻返回后台QueueListener从队列里取出事件再交给真正的Handler去写。这个设计把日志I/O从业务链路里摘了出去大幅降低日志对接口耗时的影响。代价是如果进程突然崩溃或被杀队列里还没来得及写盘的日志会丢所以消息量大的场景还需要权衡。我在实际使用中发现对于大部分中小型服务不用一上来就上异步日志够用就好。真要上异步也要做好队列容量的监控防止队列无限增长撑爆内存。把这两点做好logging这套体系才算真正在生产环境立住了。最后再分享一个我自己的习惯每次新项目启动时我会先花十分钟写好一份基础的dictConfig统一日期格式、统一字段顺序、统一日志级别。很多团队日志混乱根源不是技术不会而是没有提前做这一层统一约定。先把基础配置立好后续所有模块的开发都往里填内容就好排查问题的效率会高出一大截。
