Python日志实战：从基础组件到生产级日志体系搭建

我一直觉得国内做Python开发的团队十个里有八个把日志当摆设。不是说他们不记日志而是普遍停留在print大法和root logger一把梭的阶段。直到线上出事故半夜爬起来看服务器发现日志文件里全是无关痛痒的info真正有用的报错堆栈被淹没在几十MB的刷屏里那一刻才意识到logging模块不是文档里随便翻翻的入门章节而是正经的工程基础设施。今天就用一个过来人的视角把logging模块从头到尾捋一遍。这篇文章的内容足够让你从只知道logging.info的萌新进化到能在自己的项目里搭建一套清晰、好用、能扛住线上排查压力的日志体系。我会从最基础的核心组件讲起再到实际项目里怎么设计配置最后把我这些年踩过的坑一起倒给你。1. 为什么说print不是日志明确核心需求再动手很多新手甚至一些工作了两三年的开发者对日志的理解就是print。逻辑很简单我在代码里打一行print程序跑的时候屏幕上能看到输出这不算日志吗说实话开发调试的时候这确实够用。但一旦代码进了测试环境或者上了生产服务器print的局限就被无限放大。print输出的内容之后没法按级别过滤。不管是普通的状态信息、警告信息还是致命的错误print全一视同仁地扔到标准输出里。线上日志文件动辄几百MB你想只筛出error级别的记录grep半天全是刷屏的状态打印。print打出来的东西没有时间戳或者只有你用time.time()手动拼接的粗糙时间想根据日志还原一条请求的完整链路连精确到毫秒都做不到。print不支持自定义输出目标。想落盘得自己写文件操作想同时输出到控制台和文件得自己开两个流。这些代码写起来不难但改写起来特别恶心每个模块都得沾一身。logging模块存在的意义就是把这些需求都标准化了。日志级别过滤、时间格式化、多输出目标Handler、日志内容格式定制Formatter、模块化Logger体系这些在logging里全是现成的。你只需要花半小时把配置写好之后所有模块里的记录操作都是一行代码的事。这不只是省事这是在为你未来排查线上问题的时候铺路。那么问题来了logging模块到底要怎么用才算用好了我的看法是你得先把它四个核心组件搞清楚Logger、Handler、Formatter、Filter。这四个东西就像流水线上的四道工序理解了他们各自干什么你就能随心所欲地组合配置而不是乱抄网上的配置模板。1.1 组件拆解Logger不背Handler的锅先说说Logger。Logger是你代码里直接调用的入口logger.info(...) 里的logger就是它。每个Logger都有一个名字名字用点号分隔构成层级关系。比如你创建了一个名为main.module_a的Logger它和名为main的Logger之间就有父子关系。默认情况下子Logger的日志消息会向上传递给父Logger如果不加处理最终会一路传到根Logger那里。很多人刚接触logging的时候会误以为Logger就是用来写文件的所以在自己创建的Logger上找了半天怎么把日志写入文件。这是把Logger和Handler搞混了。Logger的职责只有一个决定一条日志消息要不要被处理。它维护一个级别阈值level如果你的代码里调用了logger.debug()而当前Logger的级别是INFO那么这条debug消息会被直接丢弃连Handler都不会触发。这个机制被称为Logging Flow的入口过滤是最容易被人忽视但影响最大的配置项。Handler则负责把符合条件的日志消息分发出去。同一个Logger可以挂多个Handler比如一个StreamHandler输出到控制台一个FileHandler写入文件两者可以同时工作互不干扰。Handler也有自己的级别这意味着你可以做到所有INFO及以上级别的日志写进文件但只有ERROR及以上级别的日志在控制台显示。这种设计在开发时尤其有用——终端输出别太吵但文件里尽量保留完整轨迹。Formatter做的是把LogRecord格式化成字符串。常见的格式包括时间、Logger名字、级别、文件名、行号、消息正文等。你甚至可以自定义输出JSON格式的日志方便后续接入日志采集系统做检索。最后是Filter这玩意儿用得不多但用好了能救命。它可以基于更精细的规则过滤日志。举个实际场景你某个模块里有个函数会被高频调用里面的debug日志噪音太大但你不想全局关闭DEBUG你可以写一个Filter按函数名或Logger名过滤掉这部分噪音。Handler和Logger上都可以挂Filter执行顺序是先Logger上的Filter再Handler上的Filter。这四个组件之间的关系用一句话概括Logger决定一条消息是否够资格出发Handler决定出发后去哪儿Formatter决定去了之后长什么样Filter则负责在任何一个环节干精细化拦截的活儿。理解到这个层次你才能读懂各种logging配置里那些奇奇怪怪的参数而不是对着网上的配置文件望洋兴叹。1.2 三分钟理解LogRecord的诞生与被丢弃上面提到Logger会先做个级别判断不够级别的消息直接丢弃。这里涉及一个所有logging使用者都必须透彻理解的概念LogRecord的生成成本。很多人好奇为什么logging模块不推荐在运行时用字符串拼接去构造日志消息而是推荐用logger.info(message %s, arg)这种带格式占位符的方式。原因就在级别过滤这里。如果你写了logger.info(this is %s % expensive_str)哪怕当前级别是WARNING这行代码也会先执行字符串格式化和str(expensive_str)的调用白白浪费CPU。如果你写成logger.info(this is %s, expensive_str)logging模块在判断级别不够时根本不会做格式化那个expensive_str的转换也被推迟到真正要输出的时候。这叫惰性格式化。日志的级别过滤机制让这条优化策略变得极其有价值。另一个需要理解的点是异常堆栈。logging模块提供了一个叫exc_info的参数。你写logger.error(something went wrong, exc_infoTrue)时日志里会附带当前的异常堆栈信息。更简洁的写法是在except块里直接调logger.exception()它默认就是级别为ERROR且exc_infoTrue的效果会自动帮你捕获堆栈。这里要提醒一句exception方法只能在异常处理里调用。如果代码没在except块中你调logger.exception()日志里会打出一个“NoneType: None”的堆栈对排查屁用没有反而会误导人。2. 从零搭建一套靠谱的日志配置聊完了组件接下来进入实操。我不会直接甩一段配置代码让你抄那样你跟不了几行就懵了。我带你从最简单的配置开始一步一步演变到生产可用级别。每个演进背后的理由才是这篇文章真正的干货。2.1 起步配置别急着上JSON先用basicConfigPython的logging模块提供了一个极其简单的入门函数logging.basicConfig()。它能在根Logger上自动配置一个默认的StreamHandler和Formatter。很多教程会让你第一行就写这个然后告诉你“这就够用了”。import logging logging.basicConfig( levellogging.INFO, format%(asctime)s - %(name)s - %(levelname)s - %(message)s, )我自己不反对在脚本里用basicConfig但反对无脑在项目启动文件里用一次就完事。basicConfig有个特点它在第一次调用时生效如果根Logger上已经配置了Handler后续再调用就无效了。这一点在你调试多模块项目时特别容易踩坑。不过作为第一步理解basicConfig里的level参数和format参数的含义是很有价值的它们会直接映射到后面“正经配置”里的同名概念。level指定根Logger的阈值format指定日志记录里显示哪些字段。2.2 从脚本走向项目dictConfig的正确姿势当你开始正经做一个项目而不是写一次性脚本的时候我强烈推荐你使用fileConfig或者dictConfig。这两个函数可以从配置文件中加载完整的日志配置包括Logger、Handler、Formatter、Filter的定义。相比直接在代码里new几个Handler然后addHandler配置文件的好处是改日志级别、改输出路径、改格式都不用动业务代码。我个人偏向dictConfig因为它是纯Python字典可以灵活地合并环境变量也可以在字典里塞一些动态参数比如按当前时间戳生成日志文件名。你也可以用JSON文件来承载这个字典这样运维同学看到了也能改。来看一个我常用的基础生产配置模板import logging.config import os LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { default: { format: %(asctime)s - %(name)s - %(levelname)s - %(message)s, datefmt: %Y-%m-%d %H:%M:%S }, detailed: { format: %(asctime)s - %(name)s - %(levelname)s - %(pathname)s:%(lineno)d - %(message)s, datefmt: %Y-%m-%d %H:%M:%S }, }, handlers: { console: { class: logging.StreamHandler, level: DEBUG, formatter: default, }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: detailed, filename: app.log, maxBytes: 10485760, backupCount: 5, encoding: utf-8 }, }, loggers: { app: { handlers: [console, file], level: DEBUG, propagate: False, }, }, root: { level: WARNING, }, } logging.config.dictConfig(LOGGING_CONFIG) logger logging.getLogger(app)这个配置有几个关键设计disable_existing_loggers设为False。这个参数在dictConfig里特别坑默认是True意味着加载配置时会禁用之前创建的所有Logger。如果你在导入某些第三方库后重建配置那些库内部创建的Logger会被静默禁用导致它们的日志消息彻底消失。设成False是最保险的选择。分Formatter。控制台只需要简单格式文件用详细格式带文件路径和行号两种Formatter各安其职。开发时看控制台不想要一堆噪音排查问题时翻文件需要足够信息。RotatingFileHandler替代FileHandler。前者支持日志文件按大小滚动比如单文件超过10MB就自动重命名为app.log.1并新建一个app.log继续写同时保留最多5个备份文件。这个机制可以有效防止日志文件无限膨胀把磁盘塞满。生产环境下这是最基本的自我保护。专门的app Logger关闭propagate。关闭传播是为了避免日志消息向上传到root Logger再被处理一次导致日志重复输出。这一点下面会展开讲。2.3 模块化获取Logger每个模块用独立的namespace配置搞定之后代码里怎么拿Logger就很有讲究了。很多人图省事直接在模块顶部写logger logging.getLogger(__name__)这是最标准的写法。__name__在这个模块里就是模块的完整导入路径比如main.package.module。这样一来你的Logger天然构成了层级结构。你可以只查看某个包的日志也可以根据Logger名字快速判断一条日志代码在哪个模块里。但要注意层级Logger的传播问题。假设你在main.mod_a和main.mod_b里分别用了getLogger(name)也就是分别生成了main.mod_a和main.mod_b两个Logger它们的父Logger是main。如果你在main这个Logger上挂了一个Handler默认情况下main.mod_a产生的日志会交给main的Handler处理同时如果main.mod_a自己没有Handler日志就顺着传播链往上找。这个机制大多数时候很好用但也很容易出现重复输出的问题。重复输出的根源在于你挂Handler的位置。如果你在每个子Logger上手动addHandler同时它们又通过传播把消息传给了父Logger的Handler那么同一条日志消息就被打印了两次甚至更多。解决方式就两条路要么手动给每个Logger设propagateFalse断掉上传路径要么只在父级Logger上挂Handler子Logger完全依托传播机制。我上面配置里用的是一个独立命名空间app并且显式关了propagate这是为了避免该Logger的日志传入root Logger后被root上可能配置的默认Handler再打一遍。3. 生产环境里的日志策略跟教科书不一样配置好模块化Logger只是第一步真正到了生产环境你会遇到更多教科书上不会写的东西。这部分我结合自己实际趟过的坑聊聊日志级别怎么设、日志文件怎么切分、要不要发邮件告警。3.1 日志级别规划开发环境与生产环境标准要不同日志级别看起来是最没有技术含量的话题但实际上大部分团队的级别设置都是乱的。要么把INFO当成默认级别疯狂输出要么为了减少日志量全局设置为WARNING导致真正想看的上下文信息全没了。我给一个比较务实的方案。开发环境里你的控制台级别可以设到DEBUG文件级别也可以开DEBUG你需要在调试时看到尽可能多的信息。生产环境里控制台那一侧可以关掉或者只保留WARNING及以上级别而文件里保留INFO以上的全部日志。这样文件里留有完整业务轨迹终端只报真正的异常。但这里有一个重要的补充关键业务路径要用INFO记录而不是你以为的DEBUG。举个例子用户下单、支付回调、定时任务执行这些核心动作必须用INFO级别打日志。只有那些纯粹用于开发排查的临时变量、算法中间状态才应该用DEBUG或甚至不打。因为生产环境的日志是要留证据的等到线上出了问题你得能根据INFO级别的记录还原出业务链路光有异常堆栈很多时候不够用。还有一种声音认为日志级别越低越好干脆全部打DEBUG反正有RotatingFileHandler挡着。我强烈反对。首先大量的DEBUG日志会显著增加I/O开销高QPS的服务尤其明显性能会肉眼可见地往下掉。其次日志量上去之后真正要排查问题时在亿级日志里找一条有效记录那个检索成本太高了。日志的本质是噪音控制你要做的是用最小的噪音保留最完整的高价值信息。3.2 文件切割与保留策略避免磁盘写满的惨剧再展开说说RotatingFileHandler。前面提到maxBytes和backupCount这是文件按大小切割的经典参数。具体实现逻辑是当当前日志文件大小达到maxBytes时Handler会把现有文件重命名为app.log.1然后再新建一个app.log继续写入。旧的app.log.1会变成app.log.2以此类推。backupCount决定最多保留多少个滚动文件超过最老的那个会被删除。要考虑的一点是maxBytes和backupCount怎么配合。如果你设置maxBytes10MBbackupCount5那么理论上日志总大小不会超过约60MB5个备份加上当前文件。对大多数应用来说足够。但如果你的应用特别爱打日志一天就能产生上GB数据那就得算一下磁盘空间和保留天数反过来决定这两个参数。另外还有两个Handler值得知道TimedRotatingFileHandler和ConcurrentRotatingFileHandler。前者按照时间切割比如按天、按小时生成日志文件这个在你有日志归档需求时特别好用。后者则解决多进程同时写一个日志文件的冲突问题。多进程写日志是个大坑。标准库的FileHandler在多进程环境下是不安全的两个进程同时写入同一个文件互相覆盖是常态日志内容直接串联交错。如果非要多个进程共用一个日志文件我建议用一个额外的服务进程统一收集日志比如通过SocketHandler把日志发到logstash之类的采集端或者使用multiprocessing的Queue配合QueueHandler做日志中转。否则就用按进程名或按PID区分日志文件的方式简单粗暴。3.3 第三方库日志的降噪与桥接项目里不可避免会用到第三方库比如requests、urllib、boto3这些。这些库内部通常会用logging记录自己的调试信息其中有些还很吵。比如requests库会在DEBUG级别把完整的HTTP请求和响应头都打出来urllib3也一样这在调试时确实有用但生产环境里就是灾难。解决方案不复杂在dictConfig配置里给对应的Logger单独设置级别。loggers: { urllib3: { level: WARNING, }, requests: { level: WARNING, }, app: { handlers: [console, file], level: DEBUG, propagate: False, }, },这种做法非常推荐等于给第三方库的日志立规矩。它们的日志级别可以比你的业务Logger高这样既不影响库里错误信息的输出又能把没用的调试噪音挡在门外。还有个常被忽略的点如果你的项目用了多个日志框架比如同时存在Python的logging和loguru或者你引入了用了java.util.logging风格的库就需要考虑桥接问题。Python标准库原生没有统一桥接机制但你可以让自定义Formatter把所有LogRecord转换成统一格式来实现一定程度的对齐。我见过有人把loguru的日志也路由到标准库logging里来做法是在loguru里自定义一个sink把每条日志包装成logging的LogRecord再交给标准库处理。这种做法在团队规范一致时还挺管用。4. 疑难杂症与经典排查技巧写到这里你已经有了一套能跑的日志体系。但光能跑还不够日志模块在实践中的坑实在太多。我把这些年高频遇到的几个问题整理成了排查索引谁踩到谁拿走。4.1 日志重复输出先查传播链“我的日志打印了两遍有时候甚至三遍怎么回事”这是一个被问烂了的问题十有八九是propagate在作怪。回顾一下日志消息从Logger产生后经过该Logger的处理器处理完后如果propagate为True默认还会把消息传给父Logger父Logger的Handler再处理一次。如果你的父Logger和子Logger都挂了同样的Handler同一个事件被处理了两次自然就出现重复输出。排查思路打印出你的Logger链logging.getLogger(__name__)然后看它的logger.parent是谁。检查每个Logger上挂了哪些Handler用logger.handlers打印。检查每个Handler的formatter看重复输出的格式是否来自不同Handler。最有效的解法就是统一设计Handler层级要么全部Handler挂在根Logger上子Logger全部propagate True要么每个子Logger自理Handlerpropagate一律False。千万不要混着来。我自己习惯的做法是业务Logger统一挂一个文件Handlerpropagate设False根Logger挂一个控制台Handler负责兜底比如某些第三方库的日志两者各管一段互不干扰。这样既不会重复也不会漏日志。4.2 日志文件找不到或者没有写入权限在Linux服务器上这个问题太常见了。你明明配置了FileHandler往某个路径写文件但程序跑起来后日志文件就是不存在。大概率是路径目录不存在。FileHandler默认不会帮你递归创建目录如果路径中有任何一级目录不存在写入直接失败而且失败很容易被静默吞掉。我的建议import os log_dir os.path.dirname(log_file_path) os.makedirs(log_dir, exist_okTrue)在创建FileHandler之前先确保目录存在。不要依赖logging的默认行为它在目录缺失时只会默默地不写文件你排查起来会一头雾水。还有一个权限问题。如果你的应用是以某个低权限用户运行的比如容器里默认的非root用户而日志路径指向了root才能写的目录那同样写不进去。这类问题要提前在部署脚本里处理或者让应用启动时检查日志目录的可写性。4.3 日志时区与时间格式化很多人在查看日志时间时发现日志时间和服务器本地时间差了8小时或者没有毫秒。这源于datefmt和Formatter里的%(asctime)s字段。默认的%(asctime)s格式是2025-03-16 12:00:00,123但如果你在dictConfig里通过datefmt自定义过格式要记得把毫秒放进去%Y-%m-%d %H:%M:%S,%f。如果不加日志时间精度只能到秒高并发环境下同一秒内的多条日志无法用时间精确排序。至于时区问题logging模块是读取系统本地时间。如果你的服务器时区没设置对日志时间就是错的。排查时先确认一下系统的date命令输出和/etc/localtime是否匹配。还有一点容易忽略日志时间建议统一用UTC存储或者统一用东八区不要一会儿本地一会儿UTC否则排查跨时区问题时会疯掉。我自己在项目里统一用本地时间并写明时区因为公司服务器都在同一时区运维也习惯这么看。4.4 日志丢失被静默吞掉有一种情况特别膈应人代码确实调用了logger.error但日志文件里什么都没有。排查了一圈发现可能有两个原因。第一Logger的级别设置错误。最常见的是你把Logger的level设成了ERROR后面却发现代码里写的是logger.warning那这条warning自然就被过滤了。很多人天真地以为它一定会输出不看级别就是不走心。第二Handler的level设置正确了但Formatter报错了。这个比较隐蔽。如果你在Formatter里用了一个不存在的字段比如%(lineno)d写成了%(lineno)s或者把某个字段名字拼错日志会在格式化阶段抛异常。默认情况下Handler会捕获这个异常并调用logging.Handler.handleError而默认的handleError只打印traceback到stderr不一定会中断程序于是你只能看到控制台上飘过一段报错文件里却什么都没有。排查这类问题可以临时开启logging.raiseExceptions True让格式化异常直接暴露出来。当然生产环境慎用这个值在生产上建议设为False避免日志模块自身的问题拖垮业务主流程。4.5 性能问题频繁打日志导致接口变慢日志I/O是同步阻塞的每一条日志都涉及到文件的写入。如果你的接口每次请求打几十条日志那么日志写入时间就会叠加到接口耗时里。吞吐量一高磁盘I/O就成了瓶颈。优化思路有几种。最简单的是降低日志量把大量低价值DEBUG日志关掉或者只在需要排查时临时开放某个模块的DEBUG级别。稍微进阶一点的做法是引入内存缓冲使用MemoryHandler它可以在内存里攒够一定量的日志记录再一次性写入磁盘。这样做的好处是大幅降低I/O次数代价是一旦程序崩溃缓冲区内未落盘的日志会丢失。日志本身就是给排查用的在崩溃场景丢日志有点讽刺所以MemoryHandler只在极端性能要求下用。另一个方向是日志异步化。用QueueHandler配合一个后台线程把日志写入操作异步化。Python官方文档里推荐了这个方案主线程把LogRecord放进Queue后台线程从Queue取出来交给真正的Handler处理。这样业务线程不会被磁盘I/O阻塞。这个方案实现起来不复杂但要处理好后台线程的生命周期确保进程退出前把队列里的日志都写完。import logging import logging.handlers import queue import threading log_queue queue.Queue(-1) queue_handler logging.handlers.QueueHandler(log_queue) logger logging.getLogger(async_logger) logger.addHandler(queue_handler) logger.setLevel(logging.INFO) def consumer(): while True: try: record log_queue.get(timeout1) if record is None: break logging.getLogger(record.name).handle(record) except queue.Empty: continue thread threading.Thread(targetconsumer) thread.daemon True thread.start()这段代码里有个细节值得注意consumer里重新用record.name拿到对应的Logger然后用它的handle方法处理这条LogRecord。这样的话消息还是按照Logger的层级和Handler配置去分发不会因为用了QueueHandler就丢掉原有的格式化和Handler逻辑。这个方案我在高吞吐的服务里实测用得很稳。5. 日志风格建议一些长期主义的做事思路写到最后聊点更宏观的。日志这个东西很多人不重视觉得能看就行。但我个人的体会是日志体系建设得好不好直接决定了一个团队处理线上故障的速度和心情。我的建议是把日志当成产品来做。每个关键流程的日志记录点都像埋点一样尽量做到“一条日志就是一张事实表”谁哪个用户/哪个请求、做了什么哪个动作、什么时间精确到毫秒、结果如何成功/失败/耗时多少。如果这些信息都通过结构化的方式比如JSON格式落到日志里未来不管是排查问题还是做一些简单的数据分析都会非常顺手。另外一个建议是别过度设计。日志配置的终极目标是在合理成本内保留最多的有效信息。如果你的服务是内部工具日请求量几百次那没必要上复杂的异步方案一把FileHandler加Rotating就绰绰有余。反过来如果服务是面向高并发的核心链路那从第一行代码开始就要规划异步队列和日志采集。最后再分享一个小技巧。如果你在调试一个线上问题临时想调高某模块的日志级别但不想重启服务。标准库logging没有直接的动态调整API但你可以通过外部的信号处理或者定期读取配置的方式来实现。比如用signal模块监听某个自定义信号收到后重新加载日志配置。我在某个项目里就是这么干的排查问题的时候不用频繁重启体验好很多。logging模块的学习曲线并不陡峭但它的价值会在你真正遇到线上问题时体现出来。希望这篇长文能帮你在这个主题上少走几步弯路。