做Python后端的时间一长你会发现一个规律很多线上事故的善后工作一半时间在修代码另一半时间在翻日志。如果日志记得好问题定位是分钟级的如果日志记成一团乱麻那就是一场灾难。我有一个很深的感触——Python日志记录Logging这个模块语法上不难但真正把它用成工程化最佳实践的人并不多。大部分项目从print开始上线后又被日志问题反复折磨。今天这篇文章我就结合自己这些年踩过的坑把logging模块从原理到工程落地完整捋一遍适合那些已经会用Python写业务但还没认真设计过日志系统的读者。我默认你熟悉Python基础语法不要求你用过logging但希望你带着一个真实问题来看这篇文章我的服务出问题时日志能不能在五分钟内告诉我哪里错了、为什么错、影响范围多大如果能你的日志体系及格了如果不能这篇文章正好帮你补上短板。1. 一次凌晨事故之后为什么我坚持用Logging而不是print先讲一段真实经历。有一年我负责的一个定时任务突然在凌晨批量失败用户第二天早上才发现数据没更新。我登录服务器一看代码里全是printNohup输出文件里塞满了无关信息真正的异常堆栈被淹没在几千行重复输出里。更麻烦的是任务是多进程跑的print出来的内容混在一起根本分不清是哪个进程、哪个任务出的错。那次事故我修到天亮问题本身只花了二十分钟定位花了好几个小时。从那之后我给自己定了一条规矩只要是长期运行的程序一律不用print做日志。print本身没有错但它只是一个输出函数不是一个日志系统。它缺的东西太多了没有级别、没有时间戳、没有模块归属、不能动态开关、不能区分输出通道。而logging模块天生就是干这个的。1.1 对比printLogging解决了哪几个核心问题我把两者的差异整理成了表格方便你直观理解维度printlogging级别控制没有全量输出DEBUG/INFO/WARNING/ERROR/CRITICAL可动态调整输出位置固定stdout可同时输出到控制台、文件、网络、消息队列格式只能拼字符串模板化格式化统一加时间戳、进程号、线程号模块归属看不出来通过logger name区分业务模块性能无条件执行有级别检查低于阈值的日志几乎零开销异常栈需要手动traceback.format_exc()logger.exception()一行带走这张表每一条都不是小事。级别控制意味着生产环境可以只看到WARNING以上排查时又能临时切到DEBUG输出位置分离意味着本地开发看控制台、线上落文件或进采集系统模块归属意味着你打开日志文件一眼就知道是哪段业务在说话。1.2 从脚本到服务日志设计的起点完全不同如果你只是写个一次性脚本五分钟后就不用了那print确实够用。但只要你这个程序要跑一天以上、要被别人调用、要在看不到控制台的环境里运行就一定要用logging。不要觉得先写起来以后再改。日志系统最难改的地方不是代码而是习惯。如果你一上来就用print后面每个模块都会延续print风格等你想换logging的时候所有输出点都要重写而且没有人会记得当时为什么在那打一行输出。所以我的建议是脚本阶段可以print但一旦代码要进入版本库、要上开发环境第一时间就把logging搭起来哪怕第一天只有一行配置。2. Logger、Handler、Formatter的对象协作从一条日志的旅程说起Logging模块刚接触时容易懵因为它的对象太多了Logger、Handler、Formatter、Filter还有个老祖宗RootLogger。我推荐用一个比喻来理解日志系统就像一家餐厅。Logger是服务员负责接单。你在代码里写logger.info(菜好了)等于把一条消息交给了服务员。Handler是传菜口决定这条消息送到哪桌——是送到控制台、写到文件、还是发给远程日志系统。Formatter是摆盘的师傅决定消息长什么样——要不要加时间要不要带级别要不要显示函数名。Filter是餐厅门口的保安有些客人不让进有些消息直接拦下来。服务员可以把同一条消息同时交给多个传菜口比如既给控制台也给他文件所以一条日志可以有多个流向。2.1 从一条日志到最终落盘发生了什么当你调用logger.info(user login)时日志的旅程大致是Logger检查自身级别如果INFO低于设定的阈值直接返回不产生日志。构造LogRecord对象记录时间、文件名、行号、消息、异常信息等元数据。Logger把LogRecord交给所有绑定的Handler同时顺着Logger的层级关系向上传递。默认会一路传到RootLogger。每个Handler收到LogRecord后先比对Handler自己的级别再让Filter决定是否放行。放行后Handler调用Formatter把LogRecord转成字符串最后输出到目标。这个链路解释了为什么很多人第一次写logging时日志会重复出现。最典型的情况是你自己给某个logger加了一个console Handler又调用了logging.basicConfig()这个函数在RootLogger上加了一个Handler。你的logger传下去给RootLoggerRootLogger又输出一次于是每条日志打印了两遍。2.2 先记住这两个底层概念Logger树和PropagateLogger之间是有父子关系的。logger logging.getLogger(app.user)的父级是logging.getLogger(app)再往上是RootLogger。这就是Logger树。子Logger默认会把LogRecord向上传递这个行为叫做Propagate。如果你不想让子Logger的日志被上层再处理一遍就把logger.propagate False关掉。实际操作中我倾向用一种更简洁的策略所有业务Logger只做命名和级别管理不直接挂Handler统一由RootLogger或某个顶层Logger挂Handler这样重复日志的问题几乎不会出现。3. 分模块、分环境、分级别日志系统落地的配置清单真正工程化的日志系统不是打开Python终端敲两行代码就完事的。你需要考虑几个问题项目分多少个模块开发、测试、生产环境分别要什么级别控制台和文件是否都要文件多久轮转一次这些问题我建议用一套集中配置来管理而不是散落在各个模块里各配各的。我的习惯是项目里建一个logging_config.py用dictConfig统一声明Logger、Handler、Formatter。业务代码里只做一件事logger logging.getLogger(__name__)。这个__name__在模块间会自动变成类似api.order、service.payment、db.session这样的名字日志里天然带模块归属非常便于过滤检索。3.1 dictConfig配置示例控制台加文件双输出下面这组配置是我比较推荐的中小型项目起步模板import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s }, detailed: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(processName)s | %(threadName)s | %(filename)s:%(lineno)d | %(message)s } }, handlers: { console: { class: logging.StreamHandler, level: DEBUG, formatter: standard, stream: ext://sys.stdout }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: detailed, filename: app.log, maxBytes: 10 * 1024 * 1024, backupCount: 5, encoding: utf-8 } }, root: { level: INFO, handlers: [console, file] }, loggers: { sqlalchemy.engine: { level: WARNING, propagate: False } } } logging.config.dictConfig(LOGGING_CONFIG)这段配置我拆开讲standard格式适合人眼快速扫读detailed格式适合文件归档带了进程名和线程名多线程排查时特别有用。consoleHandler级别设成DEBUG开发时一眼看到所有细节fileHandler级别设成INFO避免测试环境把DEBUG噪音写进磁盘。RootLogger兜底业务模块不需要额外挂Handler。把第三方库如sqlalchemy.engine单独压到WARNING防止ORM的DEBUG刷屏。propagate设成False是因为我不想让它回到RootLogger被重复格式化。3.2 环境切换用环境变量控制而不是改代码我见过不少项目日志配置写死在代码里每次上线前手动改级别改完还容易忘。我的做法是增加一个环境变量比如LOG_LEVEL通过它覆盖配置import os level os.getenv(LOG_LEVEL, INFO).upper() LOGGING_CONFIG[root][level] level这样一来开发环境export LOG_LEVELDEBUG生产环境不设或设成INFO紧急排查问题时再在部署平台临时改成DEBUG重启服务不用动一行代码。这里要强调一个原则业务Logger的setLevel最好收敛在配置里统一管理不要在代码里东一个logger.setLevel(DEBUG)西一个logger.setLevel(INFO)。一旦散落你很难判断线上到底是哪个级别在生效排查日志问题时又得先找代码。4. 轮转、多进程、异步与性能从本地脚本到集群部署的日志演进很多项目死在日志文件无限膨胀或多进程写文件互相覆盖上。这节讲的几个问题不是等你日志量大了才要考虑而是系统设计之初就该想清楚的事。4.1 RotatingFileHandler的参数怎么定我先说单机场景。文件日志一定要做轮转否则磁盘迟早被写满。RotatingFileHandler是当文件大小超过阈值时触发轮转file_handler logging.handlers.RotatingFileHandler( filenameapp.log, maxBytes50 * 1024 * 1024, backupCount7, encodingutf-8 )maxBytes建议结合单条日志的大小和业务估算比如一条日志平均1KB一天10万条是100MB那maxBytes50MB一天大概轮转两次backupCount7保留3.5天记录。还有一种方式是TimedRotatingFileHandler按时间轮转time_handler logging.handlers.TimedRotatingFileHandler( filenameapp.log, whenmidnight, backupCount30, encodingutf-8 )whenmidnight每天零点切一次文件whenD也是按天但切分时间依赖程序启动时刻不推荐容易和你预期的零点不一致。backupCount30保留一个月。如果你同时担心单文件过大和时间跨度可以自己写一个继承类同时判断大小和时间业务里够用就行。4.2 多进程写日志为什么日志会丢以及三种出路单进程写文件没问题但Web服务很多是gunicorn或uvicorn多Worker模式多个进程同时打开同一个日志文件写操作会出现交错和丢失。原因是多个进程各自持有文件描述符写入时没有锁日志行可能互相覆盖。我踩过一次很典型的坑两个Worker同时写app.log结果文件里出现整行整行地串数据一条日志被另一条截断。排查半天才反应过来是进程竞争。针对多进程场景我的经验按优先级排序用QueueHandlerQueueListener业务线程只写队列后台单线程统一落盘。使用第三方ConcurrentRotatingFileHandler底层用文件锁保证同一时间只有一个进程在写。容器和云环境里干脆输出到stdout由容器平台统一采集本地不落盘。我重点说下方案一因为它不仅在多进程下安全还能减少I/O阻塞。QueueHandler很简单import queue from logging.handlers import QueueHandler, QueueListener log_queue queue.Queue(-1) queue_handler QueueHandler(log_queue) root_logger logging.getLogger() root_logger.addHandler(queue_handler) file_handler logging.handlers.RotatingFileHandler(app.log, encodingutf-8) listener QueueListener(log_queue, file_handler) listener.start()这个组合的价值业务代码里logger.info(...)只是把日志放进了内存队列实际写文件由QueueListener线程完成而且这个线程是全进程唯一的写者。这样多条线程、多个Worker并发写文件的核心冲突就被化解了。有一点要注意QueueListener接管的是日志的最终输出所以formatter要挂在file_handler上而不是queue_handler上。这个顺序很多人搞反结果日志进了队列但格式始终不变。5. 设计日志内容结构化字段、异常栈与敏感信息脱敏日志除了写给谁看还要考虑给机器怎么读。如果你将来的日志要进ELK、Loki或者云厂商的日志服务那结构化的价值会被无限放大。用纯文本格式给人看可以给机器解析就很痛苦。我的建议是文件日志用JSON格式控制台日志保留易读的纯文本。5.1 加字段不如加结构我常用的JSON Formatter是自定义的因为标准库没直接提供JSON格式的Formatter。下面是一个极简版本import json import logging class JsonFormatter(logging.Formatter): def format(self, record): data { time: self.formatTime(record), level: record.levelname, logger: record.name, module: record.module, line: record.lineno, message: record.getMessage(), } if record.exc_info: data[exc_info] self.formatException(record.exc_info) if hasattr(record, request_id): data[request_id] record.request_id return json.dumps(data, ensure_asciiFalse)然后你可以在Handler里指定formatterJsonFormatter()。这样每条日志都是一个合法JSON对象日志平台解析时不需要正则劈字符串。这里有个小技巧如果你希望日志里带上请求ID可以用logging.Filter往LogRecord上挂附加属性。class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id get_request_id_from_context() return TrueFilter不一定要干过滤的活儿也可以当附加字段的注入器来用。日志平台按request_id一条条串联请求链路排查用户问题时非常高效。5.2 敏感信息脱敏别让日志变成安全事故日志里最容易出的安全问题就是不小心打印了用户密码、Token、身份证号。我在生产环境遇到过同事把登录请求体整个打到INFO里的事故里面包含密码明文。这个教训让我养成了一个习惯任何一个输出对象的自定义__repr__方法都要想清楚这个字符串会不会进日志。脱敏可以放在写日志之前也可以放在Formatter里统一处理。我更推荐放在Formatter因为它是一道最后防线。自定义RedactingFormatter比如对消息里形如passwordxxx或token: xxx的片段替换为***import re class RedactingFormatter(logging.Formatter): SENSITIVE_PATTERN re.compile(r(password|token|secret)\s*[:]\s*([^\s,}]), re.I) def format(self, record): record.msg self.SENSITIVE_PATTERN.sub(lambda m: f{m.group(1)}***, str(record.msg)) record.args () return super().format(record)注意一个细节record.args在格式化前会被真正替换所以如果想要在Formatter里修改消息最好先把record.msg处理成完整字符串再清空args避免原始参数被二次拼接。安全的底线是像密码、Token这种字段最好在代码入口就不记录而不是指望脱敏。脱敏只是兜底不是保险。6. 高频翻车现场日志重复、乱码与吞异常的排查链路这一节我想换成排查视角来讲。前面讲了很多应该怎么做但实际工作中更多是线上日志出问题了我怎么一步步找到根因。下面三个翻车场景都是我很高频遇到的我把完整排查链路写出来。6.1 场景A每条日志都打了两份现象代码里明明只有一行logger.info(hello)控制台却出现两行一行格式和另一行格式还长得不一样。排查链路先看是不是有人调用了两次basicConfig()。这个函数在默认情况下如果RootLogger已经有Handler不会重复添加但如果手动调用或通过框架触发可能重复。再检查业务Logger上是否单独添加了Handler比如写了logger.addHandler(console_handler)。只要这个logger.propagate没关它的日志会向下传到RootLoggerRootLogger也输出一次重复出现。用logger.handlers和logger.root.handlers打印当前Handler列表一目了然。这个问题我最推荐的解法还是回到第3节讲的统一配置业务Logger不挂Handler让所有输出都归RootLogger管。你不需要在几十个模块里逐个排查谁加了Handler只需要维护一份配置。6.2 场景B控制台输出乱码或报UnicodeEncodeError现象日志里有中文Windows控制台经常报UnicodeEncodeError: gbk codec cant encode characters或者Linux上日志文件用文本编辑器打开乱码。排查链路先区分是控制台编码问题还是文件编码问题。控制台问题基本是因为Windows默认编码是GBK而日志里包含无法映射的字符。解决办法是给StreamHandler指定编码不太靠谱更实际的方法是把PYTHONIOENCODINGutf-8环境变量加上或者在代码里设置sys.stdout.reconfigure(encodingutf-8)。文件乱码几乎都是Handler没有指定encodingutf-8。RotatingFileHandler的encoding参数在Python 3.9以后必须是合法的文本编码尽早写上。我写文件日志有个固定习惯凡是开文件Handler一律带encodingutf-8不依赖任何平台默认值。6.3 场景Cexcept里只打了error异常堆栈消失了现象程序出错日志里只有一句Something went wrong没有堆栈信息根本不知道错在哪一行。排查链路先看代码里是不是写成了logger.error(xxx %s % e)这只会打印异常对象转成的字符串。看logger.exception(xxx)才能自动带上exc_infoTrue只有它才能把完整traceback输出到日志。如果你用的是logger.error(xxx, exc_infoTrue)效果和logger.exception一样。我还见过一种隐蔽写法logger.info(fail, exc_infosys.exc_info())在except块里这么用是可行的。但日志强度不够错误场景优先级应该是ERROR不是INFO。我的经验是三个层级捕获到可预期的业务异常用logger.info或logger.warning不需要堆栈。捕获到运行期异常用logger.exception带堆栈。遇到未知异常先logger.exception再决定要不要继续向上抛。如果每个except都带堆栈日志会爆炸如果都不带就没法定位。这条分寸感靠的是对业务异常边界的理解。关于日志最后想再唠叨两句日志文件其实不是你写给机器看的东西而是你写给未来那个焦头烂额的自己看的东西。每次上线前我都会做一次日志演练模拟一个线上故障只凭日志去定位如果五分钟内找不到根因就说明日志还不够。这个方法比任何规范和文档都管用。还有一个我自己的小习惯在项目启动时把当前日志配置的开头摘要打出一条INFO日志比如logging started, levelINFO, file/data/logs/app.log。这行日志会在每次上线后的日志文件开头留下标记看到它你就能确认配置真的生效了而不是你以为生效了。日志系统的设计没有终极答案但它一定值得你花半天时间认真搭一遍。今天把配置、多进程处理、结构化、脱敏这些经验整理出来希望能帮你少走几段弯路。