聊一个看起来不起眼、真出问题的时候能把人逼疯的话题Python日志记录Logging。我接手过不少半途项目十个里有七八个的日志系统处于“能用但没法用”的状态——print和Logger混用、级别全乱、时间没有时区、同一个错误能打三遍。更难受的是这些问题往往在线上出故障之后才被认真对待那时候再重构日志成本和风险都很大。这篇文章把Python logging从原理到落地梳理成一套可以照着做的实践方案先讲清楚Logger、Handler、Formatter、Filter怎么配合再对比三种配置方式的适用场景然后落到切割、上下文、结构化、异步这些生产关键点最后把几个高频日志故障的排查链路完整走一遍。适合所有写Python的人花二十分钟把自己的日志体系捋清楚。1. 为什么很多项目的日志形同虚设print、warning与Logger的本职区别1.1 print打天下欠下的三笔“债”先说我见过的最常见开局一个项目从第一行代码开始就用print()调试一路写到上线。开发者不是不知道有logging模块而是觉得“print够用了等需要再说”。这个“等需要再说”通常要等到线上故障那天才兑现。print的第一笔债是输出不可控。print只能打到标准输出你没有办法说“只要警告级别以上的内容”也没有办法说“开发环境打印到控制台、生产环境落盘”。第二笔债是上下文失真。print打出的字符串过三周再回来看你根本不知道是哪个模块、哪一行触发的、当时的变量值是什么。第三笔债是格式混乱。每个人print的风格都不一样有人加时间戳有人不加有人喜欢用横线分隔最后日志就是一团乱麻别说grep人眼都扫不下去。也有人会说“我可以用print加个开关函数啊”听起来可行实际上你很快会发现单线程小脚本还能凑合一旦涉及多模块、多线程、框架回调print的输出顺序会乱、会被缓冲区吞掉、会跟框架自己的输出混在一起。这不是print的错它本身就不是为日志设计的硬拿来打日志属于超纲使用。1.2 Logging模块的分工设计隔离、分级、可路由标准库logging模块把日志这件事拆成了四个职责Logger负责采集接收代码里的日志调用判断这条消息够不够级别被记录。Handler负责输出把消息送到控制台、文件、Socket或消息队列。Formatter负责排版把原始消息加上时间、级别、位置、线程等信息变成一行可读文本。Filter负责过滤在级别之外再按自定义规则决定放行还是拦截。四个角色各管一段互不越权。这样设计最大的好处是改日志输出位置、调格式、关某个模块的日志都不用动业务代码。print想做这些事得自己封装、自己管理文件句柄、自己处理切割最后封装出来的东西又往往比标准库难用。所以我一直的观点是logging不是print的“高级替代”而是“可观测性基础设施”。print的受众是当时的你日志的受众是未来排查问题的你以及你的同事。这个认知建立起来后面所有折腾都值得。1.3 级别与继承两个最容易误解的点logging的级别从低到高依次是DEBUG、INFO、WARNING、ERROR、CRITICAL。第一件容易踩的事是根Logger的默认级别是WARNING。很多人写了logging.debug(...)却什么都没看到就是因为默认级别把DEBUG和INFO都拦了。想让调试信息出来必须先显式设置级别。第二件容易踩的事是Logger的层级继承。Logger的名字用点号分隔比如myapp.module.sub的父Logger是myapp.module再往上myapp最后到根Logger。一条日志在子Logger里产生后会逐级向上传递术语叫propagation直到某个Handler处理它或者到达根Logger。这个机制很好用你只需要在根Logger配一个Handler整个项目的日志就都串起来了。但它也是大量“日志重复打印”事故的根源后面专门讲。2. 拆解日志流水线Logger、Handler、Formatter、Filter各管哪一段2.1 Logger与__name__先想清楚“谁在说话”Logger是日志记录的入口代码里所有日志调用都是logger.info(...)、logger.error(...)这种形式。创建Logger最简单也最推荐的方式是import logging logger logging.getLogger(__name__)__name__在模块里就是模块的完整导入路径比如myapp.services.order。带点号的层级天然对应Logger的父子关系后面想单独调某个模块的日志级别、关掉某个模块的日志直接按名字定位就行。我见过有人喜欢用自定义名字比如getLogger(log)、getLogger(main)短期看没区别一旦项目重构、模块改名这些名字就变成了一堆无法定位的孤儿标签。Logger本身不直接写日志它只负责接收调用、做级别判断。真正的输出动作由Handler完成这也是为什么Logger可以配多个Handler——同一个事件可以同时打到控制台和文件互不干扰。2.2 Handler选型与输出目标Handler决定了日志往哪走。标准库内置了几种常用的Handler输出目标适合场景StreamHandler标准输出/标准错误开发时看控制台FileHandler单个文件最简单落盘RotatingFileHandler按大小切割的多个文件日志量不稳定TimedRotatingFileHandler按时间切割的多个文件按天/小时归档QueueHandler内存队列配合异步消费SysLogHandler系统日志集中日志服务实际项目中最常见的组合是“控制台Handler 文件Handler”双路输出开发时控制台看实时输出生产时文件保留完整记录。两个Handler可以用不同的Formatter、不同的级别比如文件记录完整INFO以上控制台只打WARNING以上。这里有一个很关键的细节Handler的级别和Logger的级别是两套门槛两个都过了才会真正写出日志。Logger级别是总闸门Handler级别是分路闸门别搞混。2.3 Formatter格式化字段与时间戳Formatter把一条日志记录变成最终落盘的字符串。控制字段用字符串模板比如formatter logging.Formatter( %(asctime)s | %(levelname)-8s | %(name)s:%(lineno)d | %(message)s )常用字段有这些字段含义asctime记录时间可配datefmt控制格式levelname级别名如INFO、ERRORnameLogger名字通常是模块路径lineno日志调用所在行号module / filename模块名 / 文件名funcName函数名process / thread进程ID / 线程IDmessage日志正文我强烈建议把%(name)s和%(lineno)d放进格式。之前排查过一个报错日志里只有一句话“操作失败”没有模块、没有行号找了大半天。如果从一开始就把这两列加进去五分钟就能定位。2.4 Filter在什么时候派上用场Filter的价值体现在级别搞不定的场景。举两个实际的例子一是健康检查的噪声。某个服务每几秒打一次INFO心跳日志量不大但很吵你想在保持其他INFO不变的前提下单独屏蔽它级别做不到Filter可以class HealthCheckFilter(logging.Filter): def filter(self, record): return record.getMessage() ! heartbeat二是给日志追加上下文。Filter不仅能否决记录还能往record上挂属性后面的Formatter和Handler都能读到。比如给每条日志注入请求IDimport contextvars request_id_var contextvars.ContextVar(request_id, default-) class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id request_id_var.get() return True然后在Formatter模板里加一个%(request_id)s整条链路就串起了。这种方法我后面讲上下文信息时还会展开。3. 三套配置方案怎么选basicConfig、dictConfig、手工装配3.1 轻量脚本用basicConfig就够了对于脚本、批处理、一次性任务basicConfig是最快的方案import logging logging.basicConfig( levellogging.INFO, format%(asctime)s | %(levelname)s | %(message)s, filenameapp.log, filemodea, encodingutf-8, )两行代码解决90%的脚本需求。但有三个坑要知道basicConfig只在根Logger没有任何Handler时生效。如果你或者某个依赖库提前给根Logger加过Handler这次调用会静默失效。重复调用basicConfig不会刷新配置很多人以为可以“再调一次改级别”结果什么都不变。脚本里不建议同时配filename和控制台输出basicConfig指定了filename后默认就不往控制台打了想看实时输出只能二选一或者自己手动加两个Handler。3.2 独立应用推荐dictConfig到了Web服务、后台任务、长驻进程这个规模我建议直接用dictConfig把配置写成一份独立的数据结构import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s | %(levelname)-8s | %(name)s:%(lineno)d | %(message)s, }, }, handlers: { console: { class: logging.StreamHandler, level: INFO, formatter: standard, }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: standard, filename: app.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf-8, }, }, root: { level: INFO, handlers: [console, file], }, loggers: { requests: {level: WARNING}, myapp.boring_module: {level: WARNING}, }, } logging.config.dictConfig(LOGGING_CONFIG)dictConfig的好处是“声明式”的整个日志体系长什么样一眼看全。给某个模块单独降噪、给某个Handler单独调级别都只是改一行配置不用碰代码。而且生产环境经常要快速调整日志级别dictConfig这种集中配置是唯一让我觉得“可控”的方式。一个容易犯的错disable_existing_loggers默认是True在大型应用里会把其他库已经创建的Logger全部禁用导致日志静默消失。除非你确定自己在做什么否则统一设成False。3.3 库的日志策略只管留名不抢Handler如果你在写一个会被别人import的库日志策略完全是另一套逻辑不要在库里配置任何Handler。标准库的约定是库代码里只管logger logging.getLogger(__name__)然后正常打日志。即使宿主应用没有配置日志你的日志也不会报错——前提是库的顶层模块里加一个NullHandlerimport logging logging.getLogger(__name__).addHandler(logging.NullHandler())NullHandler会“接住”日志事件然后什么都不做避免Python 3.2之前那种“No handlers could be found”的报错。宿主应用配好自己的根Logger后你库里的日志会自动通过propagation流过去。这既不给宿主添乱又保留了日志链路。如果你在库代码里调用了basicConfig或者给根Logger加了FileHandler很可能直接把宿主应用的日志配置搞乱这种“越俎代庖”的行为在开源生态里是非常不受欢迎的。3.4 方案对比与迁移建议简单总结一下三种方式的定位方式适用规模优点缺点basicConfig脚本、单文件快零学习成本只能配根Logger灵活性极低dictConfig应用、服务集中、可声明、易调整需要维护配置结构手工装配特殊需求最灵活运行时可控代码量大容易重复加Handler我给过不少项目做日志改造通常的路径是脚本阶段用basicConfig等业务逻辑开始分模块、出现多Handler需求时一次性迁到dictConfig顺手把各模块的级别梳理一遍。迁移本身不痛苦真正的痛苦在于迁移前那些没级别的print流浪在代码各处。所以我的建议是任何一个预期运行超过一个月的脚本直接上basicConfig加格式别用print裸奔。4. 生产环境日志落地的四件事切割、上下文、结构化、异步4.1 文件切割轮转别让单文件无限膨胀生产环境日志写进单个文件是不行的。你想象一下一个每天几十万请求的服务日志文件一周就能涨到几个GB到时候打开、grep、备份都是灾难。标准库提供了两个轮转HandlerRotatingFileHandler按大小切TimedRotatingFileHandler按时间切。按时间的配置一般是这样from logging.handlers import TimedRotatingFileHandler handler TimedRotatingFileHandler( app.log, whenmidnight, backupCount14, encodingutf-8, atTimeNone, )whenmidnight表示每天零点切换文件旧文件会带上日期后缀backupCount14保留最近14份更早的自动删除。这个组合在绝大多数场景下够用了。按大小切则适合日志量不可预期、早晨晚上峰谷明显的场景from logging.handlers import RotatingFileHandler handler RotatingFileHandler( app.log, maxBytes10 * 1024 * 1024, # 10MB backupCount5, encodingutf-8, )这里有两个容易被忽略的点。第一轮转不是自动就万无一失的它只在每次写日志时检查是否超过阈值如果你的应用长时间不打日志轮转就不会发生。第二多进程同时写入同一个日志文件会互相踩踏RotatingFileHandler本身不是多进程安全的慎用。对了编码一定要设encodingutf-8。Windows环境下不指定的话默认可能是GBK日志里一旦有中文字符就会乱码或者直接抛UnicodeEncodeError。4.2 上下文信息把“你是谁”写进每行日志生产日志光有“时间级别消息”是不够的。出问题的时候你真正需要知道的是这是哪个请求触发的、哪个用户、哪次调用的参数是什么。最简单的方式是Logger的extra参数logger.info(用户操作成功, extra{user_id: user.id, action: purchase})但extra有个陷阱如果Formatter模板里声明了某个字段而extra没提供会直接抛KeyError。反过来extra里多传了字段则没事。更推荐的方案是Filter往record上挂上下文因为Filter是全局的不需要每个调用点都写一遍。配合contextvars可以在Web框架里实现“每个请求一个request_id日志全程自动携带”import contextvars import logging request_id_var contextvars.ContextVar(request_id, default-) class ContextFilter(logging.Filter): def filter(self, record): record.request_id request_id_var.get() return True接入点通常是框架中间件收到请求时request_id_var.set(new_id)响应结束后reset。之后所有本线程异步框架下是本任务产生的日志Formatter里加%(request_id)s就能自动带上请求ID。跨服务排查时这个ID就是你拼接完整调用链的锚点。4.3 结构化输出让日志能被程序消费文本日志适合人读不适合机器读。当日志量上来之后想要按字段过滤、聚合、关联告警都得靠日志系统去解析文本而解析文本是出了名的脆弱——多一个空格、少一个引号解析就废了。所以很多团队选择结构化日志最常用的是JSON格式。实现也不难继承logging.Formatter重写format方法import json import logging class JsonFormatter(logging.Formatter): def format(self, record): payload { time: self.formatTime(record, self.datefmt), level: record.levelname, logger: record.name, module: record.module, lineno: record.lineno, message: record.getMessage(), } if getattr(record, request_id, None): payload[request_id] record.request_id if record.exc_info: payload[exc_info] self.formatException(record.exc_info) return json.dumps(payload, ensure_asciiFalse)然后Formatter指定成这个类formatters: { json: {class: myutils.JsonFormatter}, }选JSON的第一受益方其实是联调排查。文本日志里搜索一次完整请求涉及的几十行日志靠肉眼拼接是折磨结构化之后日志系统按request_id一键拉出整条链路那才叫可观测性。4.4 异步写日志别让日志变成性能瓶颈日志IO看似不起眼但在高QPS场景下同步写文件会成为链路里的隐性瓶颈。每次logger.info都同步刷一次磁盘会增加请求耗时极端情况下日志拖垮业务的事我都遇到过。标准库提供了QueueHandlerQueueListener的组合把日志事件先放进内存队列后台线程批量消费写盘import queue import logging from logging.handlers import QueueHandler, QueueListener log_queue queue.Queue(-1) queue_handler QueueHandler(log_queue) file_handler logging.FileHandler(app.log, encodingutf-8) formatter logging.Formatter(%(asctime)s | %(levelname)s | %(message)s) file_handler.setFormatter(formatter) listener QueueListener(log_queue, file_handler) logger logging.getLogger(__name__) logger.addHandler(queue_handler) listener.start()业务代码调logger.info(...)只负责把事件放进队列瞬间返回实际落盘由listener的线程完成。这样日志IO就不阻塞业务线程了。使用这套方案有两个注意点一是listener.start()要跟进程序生命周期一起管理程序退出前记得listener.stop()否则队列里的日志可能丢二是队列本身占内存极端情况下队列积压会带来内存压力需要监控队列长度。对于日百万级以下日志量的服务我通常的建议是“先同步出问题再异步”异步不是银弹它只是在日志IO成为瓶颈时的解法。5. 高频日志故障排查从现象到根因的完整链路5.1 日志重复打印现象、定位与修复“同样的日志打了两遍、三遍”这是我在代码评审里遇到最多的问题。先说结论几乎都是propagation与Handler重复注册共同作用的结果。排查链路我是这样走的第一步看重复的规律。每条日志打两遍大概率是当前Logger上和根Logger上都挂了Handler打三遍往往是Logger、父Logger、根Logger三级都有Handler。第二步验证propagation。给异常Logger加一行logger.propagate False如果重复消失说明父链路的Handler在重复处理。修复方式不是盲目关闭propagation而是确认你确实需要当前Logger有自己的Handler——大部分情况下业务模块不需要独立Handler所有日志统一走根Logger就行。第三步查代码里是否重复addHandler。常见写法是每次调用某个初始化函数都logger.addHandler(handler)函数被调用多次Handler就挂多个。这种在热更新、重加载配置的App里尤其隐蔽。第四步排查dictConfig重复生效。有些框架会加载多次配置或者你同时用了basicConfig和dictConfig两套配置叠加根Logger上就有了两组Handler。建议应用启动时打印一次当前配置的Handler列表root_logger logging.getLogger() print(root_logger.handlers)眼见为实这种自查五分钟就能定位问题。5.2 只有错误级别没有堆栈exc_info与logger.exception另一个高发问题是日志里只有一句“操作失败”没有异常堆栈。排查线上错误的时候没有堆栈等于没有线索。根因在于很多人是这么写的try: do_something() except ValueError as e: logger.error(f操作失败: {e})logger.error默认不记录堆栈。要让堆栈进日志有两种写法。推荐在异常处理块里用logger.exceptiontry: do_something() except ValueError as e: logger.exception(操作失败: %s, e)logger.exception等价于logger.error(..., exc_infoTrue)它会把当前异常堆栈完整记下来而且级别是ERROR。如果你不希望堆栈只出现在except块里也可以用显式的exc_infoTruelogger.error(操作失败: %s, e, exc_infoTrue)我自己的习惯是异常场景一律用logger.exception无异常但需要记录错误信息时用logger.error(..., exc_infoTrue)比如检查到状态不合法但并没有真正抛出异常的场合。日志里带不带堆栈排查效率是天壤之别。5.3 日志时间不对asctime的格式与时区日志时间有问题通常表现为时间用本地时区打但服务部署在多个时区的机器上几台机器的日志合在一起事件顺序完全对不上或者容器内时区没设置打出来的时间和现实相差八小时。asctime默认使用进程的本地时间要想统一最简单的是改Formatter的converter统一成UTCimport time class UTCFormatter(logging.Formatter): converter time.gmtimeHandler建好后指定这个Formatter所有时间就都以UTC记录了。如果团队更习惯本地时间也要在格式串里显式带上时区避免看到时间还要猜机器时区。更规范的方案是把时间写成带时区的ISO 8601格式如2025-01-01T12:00:0008:00这样不管日志被收集到哪语义都是明确的。还有一个细节asctime默认精确到毫秒但如果你用的datefmt包含空格日志系统解析时间戳时容易出错。调日志平台的时候优先选ISO 8601紧凑格式能少踩很多坑。5.4 中文乱码与文件编码问题中文乱码是本土项目特有的高频问题。日志里出现锟斤拷之类的内容通常是文件编码与写入内容编码不匹配。标准库的FileHandler默认编码跟随系统区域设置在中文Windows上是GBK在Linux上通常是UTF-8。同一段代码换台机器日志就乱码了。解决办法很简单所有FileHandler类实例化时显式传encodingutf-8。字典配置里在handler字典中加上encoding: utf-8手工装配时handler logging.FileHandler(app.log, encodingutf-8)还有另一种乱码来源是日志消息本身携带了无法编码的字符。可以把errorsreplace传给FileHandler遇到无法编码的字符时替换成?而不是抛异常保证日志进程不因为编码问题崩溃。6. 这些年总结的几条日志习惯不太会写进文档的那种6.1 用模块名做Logger名比名字空间更稳全项目强制执行“模块内只用logging.getLogger(__name__)”。好处前面说过这里想补充一个反例有个项目喜欢用getLogger(app)这种统一点结果微服务拆开之后所有模块共用同一个Logger名想按模块关日志完全没办法区分。__name__是Python天然的信息载体顺着模块路径就能定位到代码位置可靠又省心。6.2 禁止把敏感信息写进日志这是血泪教训必须单列一条。密码、Token、密钥、身份证号这类东西一律不允许出现在日志里。一个常见但反面的做法是logger.debug(登录请求 token%s, token)一旦日志文件泄露这就是安全事件。我的建议是两条第一代码评审时把“日志是否包含敏感字段”当成固定检查项第二实在需要记录参数调试先做脱敏再输出。可以写一个简单工具函数把手机号、邮箱、银行卡号中间几位替换成星号。如果日志平台支持字段过滤在接入层也配一道双保险。6.3 测试里怎么配合日志断言日志也是接口的一部分。业务逻辑触发了告警、记录了错误完全可以用测试来保证。标准库的unittest从3.4开始内置了assertLogs用起来很简单import logging import unittest def process_order(order_id): logging.getLogger(order).warning(订单%s处理超时, order_id) class OrderTest(unittest.TestCase): def test_timeout_log(self): with self.assertLogs(order, levelWARNING) as captured: process_order(1234) self.assertIn(订单1234处理超时, captured.output[0])assertLogs会自动往目标Logger挂临时Handler断言结束后自动移除不会污染正常日志配置。这是一个很实用的模式当某个异常分支需要日志告警兜底时测试能把这条日志锁住防止后续重构把告警弄丢。6.4 关于惰性格式化的最后提醒日志调用点有一个容易忽视的性能细节# 不推荐即使日志级别是INFOf-string也已执行 logger.debug(f当前状态: {build_debug_string()}) # 推荐字符串延后到真正要输出时才格式化 logger.debug(当前状态: %s, build_debug_string())logging模块在接收日志调用后会先比较级别如果够不到阈值就直接丢弃第二种写法传入的是待格式化的参数字符串拼接被延后到确定要输出的时候才发生。在高频路径上这个差别可能省下大量无用的字符串构建开销。最后分享一个我自己的小习惯日志改造不要一次推全量。先从一个最小闭环开始——根Logger加Handler、统一格式、控制台文件双路输出、所有模块用__name__跑通之后再逐步加Filter、结构化、异步这些进阶能力。日志这个事最大的成本不是配置难而是不自知——你觉得它简单结果线上抓瞎你把基础打牢之后会发现排查问题的时间比过去少了一半还多这个回报是实打实的。