1. 为什么你的应用需要一套正式的日志规范1.1 从print到Logging我踩过的第一个坑有一次线上业务报错我打开生产环境的日志文件5分钟刷了2万行第三方库的DEBUG输出真正的异常却被淹没在一个没带堆栈的ERROR里。那是我第一次意识到Python日志记录Logging看起来简单但从“能打印”到“能用、能救火”之间还隔着一整套工程规范。早期写项目时我也习惯用print毕竟本地调试足够直观。可一旦部署到服务器print的缺点就全暴露了没有时间戳没有日志等级不知道是哪一行代码打的更别提按文件名和行号去定位了。更要命的是print会写到标准输出跟业务打印混杂在一起如果服务还有定时任务日志基本就是一锅粥。后来我换成了logging模块但一开始只是把print改成logger.info这算迈过了第一道门槛却远远不够。网上很多教程只教了“怎么用”没教“怎么用好”。同样的logging在小型脚本和生产服务里的定位完全不同。如果只是跑一个本地小工具print完全够用但只要你的代码需要被其他人复用、需要在后台常驻运行、需要出问题后按时间线回放现场就必须引入正式日志规范。这也是我写这篇内容的核心目的把多次项目迭代中沉淀下来的日志记录Logging最佳实践完整梳理一遍从最基本的三件套到工程化配置、文件轮转、结构化日志、多进程陷阱一次讲透。无论你是刚接触Python还是已经在生产环境被日志问题折磨过都应该能从里面找到可以直接照搬的方案。1.2 日志系统到底在回答什么问题很多团队把日志当成“程序运行轨迹记录”这个想法没错但太模糊。我认为日志系统本质上只回答三个问题什么时候发生了什么When、在代码里的哪个位置发生的Where、具体内容是什么What。三个问题缺一个排障效率就会断崖式下降。比如只记录“用户登录失败”而没有时间你无法判断失败是否集中在一个时间段没有logger名称和代码行号你还要在几千行业务代码里人肉搜索没有足够的上下文参数你根本不知道这次失败和前一次失败有什么区别。所以日志的设计原则应该是“给未来排障的自己看”而不是“给我现在看”。这意味着需要做到可分级能够按严重程度过滤可配置在不同环境里能选择不同输出位置可聚合同一请求的日志能通过一个ID串起来可筛选运行时能快速查找关键词。这些需求恰恰是Python标准库logging模块被设计出来的原因。它从1994年首次推出经过多年迭代至今仍是大多数项目日志体系的地基。与其重复造轮子不如先把这套标准机制的边界摸清楚。1.3 什么项目才需要日志规范我给不出“必须超过多少行代码就要用logging”的武断结论但可以根据项目阶段判断脚本型工具一次性运行、结果简单用print问题不大。常驻服务Web服务、Worker、定时任务必须用logging。库项目只负责提供功能内部不要配置日志只创建logger并记录具体输出交给调用方。跨团队项目日志是共同语言必须提前约定统一格式否则排障时大家各自为政。很多避坑经验都来自这个判断库代码里配置了handler结果被依赖方用了之后重复日志满天飞脚本里强上logging反而增加理解成本。所以最佳实践的第一步是先想清楚你的代码处在哪个生态位。2. 基础配置Logger、Handler、Formatter三件套怎么搭2.1 logging模块的核心流程我把logging模块的运行机制总结成一句话业务代码把日志事件交给LoggerLogger根据级别判断放行还是丢弃放行的事件经过Handler路由到目的地再由Formatter决定最终外观。用生活类比来理解Logger是写日记的人Handler是决定把日记交给日记本、邮件还是碎纸机的人Formatter是排版模板。三者各司其职可以任意组合。很多人刚接触时会困惑为什么在Logger上要设置一次setLevel在Handler上又要设置一次setLevel这是两套独立的闸门。Logger.setLevel决定这条日志事件“要不要接进管道”Handler.setLevel决定“管道里的日志在出口处要不要丢弃”。为了达到某个等级才输出通常把Logger设为DEBUG把Handler设为业务需要的INFO这样调试时只需把Logger调成DEBUG就能看到完整过程。另一个核心概念是传播链。当你执行logger.info(hello)时模块会生成一条LogRecord先送给logger自身挂载的handlers然后逐级向上传递给祖先logger的handlers。默认情况下最终会传到root logger。子logger不挂handler时日志会使用root的配置子logger挂了handler且没有关闭propagate时输出内容就可能出现两份。这条传播机制引出了后面要重点讲的重复日志问题。2.2 最小可用配置与关键参数先从最朴素的一份配置开始import logging logger logging.getLogger(myapp) logger.setLevel(logging.DEBUG) handler logging.StreamHandler() handler.setLevel(logging.DEBUG) formatter logging.Formatter( %(asctime)s %(name)s %(levelname)s %(message)s, datefmt%Y-%m-%d %H:%M:%S ) handler.setFormatter(formatter) logger.addHandler(handler) logger.info(system started)这段代码看着简单实际藏着几个关键点。getLogger(myapp)创建了一个命名的logger名字会成为日志内容的一部分方便从模块名反查代码位置。setLevel(logging.DEBUG)是源头开关如果你忘了这一步logger会继承root默认的WARNING级别info日志就会无声消失。这是新手最常见的问题明明调用了logger.info控制台却什么都没打印。StreamHandler默认会输出到stderr。如果希望输出到stdout要显式指定handler logging.StreamHandler(sys.stdout)生产环境里stderr和stdout可能会被运维系统分开收集统一成stdout反而更容易处理。这一点经常被忽略等到对接日志采集平台时才暴露出来。2.3 模块内logger的命名习惯我看到很多人不管在哪个文件里都写logging.info这种写法本质上用的是root logger。小项目没问题但模块一多日志就分不清来源。最佳实践是每个模块都使用自己的命名logger# service.py import logging logger logging.getLogger(__name__) logger.info(service started)__name__会根据模块路径生成层级名称比如services.user_service。这个名称天然反映了代码结构排查问题的时候只要看logger名就能知道是哪个模块打的。层级命名也方便统一控制你可以只调整services这个logger的级别就能影响它下面所有子模块。有两个原则必须刻进脑子里。第一应用入口负责配置root logger模块内部的logger只管记录不要再addHandler。第二库代码永远不要配置日志调用方怎么配置是他们的事。遵循这两条日志配置就是单向依赖不会互相踩脚。3. 格式与级别让日志真的能帮你排查问题3.1 日志级别是语义设计不是随口标记日志级别看似简单很多人却用得很混乱。我给团队定规矩时通常用下面这套语义级别语义典型场景DEBUG开发期细节变量值、函数入参、中间状态INFO正常业务节点任务开始、请求处理完成、数据库连接建立WARNING可恢复的异常重试第2次、缓存失效、配置降级ERROR当前操作失败某次API调用500、任务执行失败CRITICAL整体不可用启动失败、数据损坏、进程退出实际项目里最常见的错误是把可恢复的异常打成INFO理由是“反正重试就成功了”把单个请求失败打成CRITICAAL理由是“用户很生气”。级别一旦失去语义告警规则就无法落地。我看到过一套相对合理的做法ERROR必须伴随告警且必须有人响应WARNING是白天会看、晚上不惊醒人的INFO是能够连成业务链路的DEBUG是为将来临时排查预留的。关于异常日志有一个黄金写法在except块内用logger.exception。它会自动附带当前异常堆栈并按照ERROR级别输出省去手动exc_infoTrue的麻烦。try: result 10 / int(user_input) except ZeroDivisionError: logger.exception(计算失败输入值: %r, user_input)%r会把值用repr展示字符串会带引号便于区分变量类型。如果你在except外调用logger.exception得到的只有一行没有任何堆栈的ERROR等于白记。这条坑我几乎每个项目都见人踩过。3.2 日志格式里该放哪些字段Formatter的格式串决定你日后排查时能拿到多少信息。一个只带message的日志基本没有排查价值。我常用的生产格式是这样的FORMAT ( %(asctime)s | %(levelname)-8s | %(name)s | %(process)d:%(thread)d | %(filename)s:%(lineno)d | %(message)s )逐项解释asctime是时间戳levelname是对齐显示级别name是logger名process和thread是多进程与多线程里定位现场用的filename和lineno能直接跳转到代码行。日志格式里带行号在Python这种动态语言里特别重要因为框架调用链很深仅靠函数名很难定位实际触发点。时间戳还要注意时区问题。默认asctime使用本地时间生产服务器如果分布在多个时区或者与日志采集平台时区不一致时间轴就会乱。我通常统一用UTC记录格式化时把converter改成UTCformatter logging.Formatter( %(asctime)s %(levelname)s %(message)s, datefmt%Y-%m-%dT%H:%M:%S%z ) formatter.converter time.gmtime%z会显示偏移量配合time.gmtime日志时间就具备了全球可读性。当然如果你们团队统一用北京时间保持一致即可但一定不要“每个服务器用自己本地时间”。消息内容同样有讲究。尽量使用参数化格式而不是提前拼接字符串# 推荐 logger.info(user %s login from %s, user.id, ip) # 不推荐 logger.info(fuser {user.id} login from {ip})原因很简单logging是懒格式化。只有当这条记录真的要被输出时%s才会被替换成实际值。如果当前级别过滤掉了INFO参数化写法可以避免构造字符串的开销。对于高频链路这个性能差异还是能感受到的。3.3 敏感信息必须脱敏日志里最容易出问题的是敏感数据。密码、令牌、身份证、支付账号任何一条出现在日志文件里都可能成为安全事故。最佳实践是能不打就不打必须打就去掉中间字段再打。最简单的做法是写一个Filter把消息里的关键模式替换掉class MaskSecretFilter(logging.Filter): def filter(self, record): if isinstance(record.msg, str): record.msg record.msg.replace(password, password***) return True这只能作兜底更稳妥的是在业务代码里少传敏感参数。等到日志已经落盘才发现脱敏问题再去清洗历史文件成本高得多。4. 工程化配置dictConfig的正确打开方式4.1 为什么我不用fileConfig项目一旦多了手写logger.addHandler这种样板代码就开始失控。尤其是多个模块都想往不同地方输出、各自还要不同级别时手工维护Handler实例的代码会非常丑陋。标准库提供了两种工程化配置方案fileConfig和dictConfig。fileConfig基于INI文件配置历史包袱重对Python对象的表达能力弱。比如你的Formatter需要传入自定义过滤器或者Handler需要调用自定义函数INI格式就很难优雅表达。dictConfig直接使用Python字典描述清晰、类型安全、支持自定义工厂函数几乎可以覆盖所有场景。它也更适合放进settings.py这类配置模块里跟项目其他配置共享一套加载逻辑。唯一需要提醒的是disable_existing_loggers这个参数。dictConfig的默认值是True意味着执行配置时会禁用所有已存在的logger。如果你的模块在配置之前就调用过getLogger()配置完成后这些logger可能集体沉默。所以工程代码里一定要显式设置disable_existing_loggers: False,4.2 一套可直接复用的dictConfig模板import logging.config LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s | %(levelname)-8s | %(name)s | %(process)d:%(thread)d | %(filename)s:%(lineno)d | %(message)s, datefmt: %Y-%m-%d %H:%M:%S } }, handlers: { console: { class: logging.StreamHandler, level: INFO, formatter: standard, stream: ext://sys.stdout }, app_file: { class: logging.handlers.RotatingFileHandler, filename: logs/app.log, maxBytes: 10485760, backupCount: 10, encoding: utf-8, formatter: standard } }, root: { handlers: [console, app_file], level: INFO }, loggers: { uvicorn: {level: WARNING}, requests: {level: WARNING} } } logging.config.dictConfig(LOGGING_CONFIG)这套配置做了四件事格式化统一、输出到控制台和文件、root级别为INFO、把两个嘈杂的第三方库调成WARNING。其中的RotatingFileHandler、encoding等细节后面会展开。如果你习惯用logging.basicConfig也可以把它看作一个只支持root配置的快捷方式。但当项目需要“control loggers”“权限控制”“全局过滤器”时basicConfig很快就不够用了还不如一开始就上dictConfig。4.3 屏蔽第三方库的噪音日志Python的日志世界有一个重要事实第三方库如果遵守规范它就不应该自己配置输出而是创建一个命名logger把决定权交给使用方。所以屏蔽噪音最优雅的方式不是去改库代码而是通过配置调整它的logger级别。上面的配置里requests: {level: WARNING}这一行关键点在于没有给它配handler也没有设propagate所以它仍然把日志传播给root由root的console和file统一输出只是这次级别过滤掉了INFO和DEBUG。如果某个库日志实在太多也可以单独把它设为ERROR。需要注意propagate的误用。有些人为了屏蔽某个logger直接写propagate: False结果这个logger内部自己挂了handler日志照样输出而它的子logger却再也到不了root其他日志反而丢了。屏蔽噪音优先用setLevel不要动不动就关传播。5. 文件轮转与清理别让日志把磁盘撑爆5.1 主流轮转Handler的选型如果日志只写到一个文件里磁盘迟早会被撑爆。我见过一台生产机器因为日志文件占满磁盘而服务挂掉的案例原因就是日志量比预想的大了几倍没配置轮转。标准库里有两个主流选择RotatingFileHandler按大小轮转TimedRotatingFileHandler按时间轮转。RotatingFileHandler的逻辑是当前文件写到maxBytes大小后把现有文件依次改名最新备份叫app.log.1旧的叫app.log.2最多保留backupCount份。配置示例from logging.handlers import RotatingFileHandler handler RotatingFileHandler( filenameapp.log, maxBytes10 * 1024 * 1024, # 10MB backupCount10, encodingutf-8 )TimedRotatingFileHandler则按时间切分最常用的是午夜切一天一个文件from logging.handlers import TimedRotatingFileHandler handler TimedRotatingFileHandler( filenameapp.log, whenmidnight, backupCount30, encodingutf-8 )选型建议磁盘敏感、日志量稳定优先按大小需要按天回看业务曲线优先按时间。我通常两个都用普通应用用大小轮转保留最近10个文件整体磁盘上限大约100MB业务需要对账、按天归档时用时间轮转并保留30天。5.2 多进程日志的安全姿势单个应用起多个进程时RotatingFileHandler并不安全。轮转过程涉及文件重命名和重新打开多个进程同时操作同一个文件轻则日志写入错乱重则把备份文件覆盖掉。生产环境里常见于gunicorn多worker、celery多worker跑同一套日志配置。处理方式有三条路。第一每个进程写不同的文件比如文件名里带上进程号第二写stdout由外部日志采集程序负责轮转归档第三进程内通过QueueHandler收集日志再由一个专门的listener进程写入文件。第三种方案用标准库就可以落地import logging.handlers import queue log_queue queue.Queue(-1) queue_handler logging.handlers.QueueHandler(log_queue) file_handler logging.handlers.RotatingFileHandler(...) queue_logger logging.getLogger(app) queue_logger.addHandler(queue_handler) listener logging.handlers.QueueListener(log_queue, file_handler) listener.start()这种方式把写文件的操作收敛到单点上多进程可以共用listener严格来说QueueListener要挂在每个进程内还是全局要结合进程模型设计。更常见的部署是容器环境应用不做文件写日志而是全部打到stdout由容器日志采集器读取。这样轮转、压缩、清理都不需要业务代码关心。5.3 日志保留与压缩轮转不等于无限保留backupCount只决定保留多少份备份不决定保留多少天。要控制保留天数最直接的是用外部脚本定期清理find logs -name *.log.* -mtime 30 -delete也可以在代码层面对旧日志做压缩避免历史文件占用太多空间。给RotatingFileHandler挂上自定义rotatorimport gzip import os def gzip_rotator(source, dest): with open(source, rb) as f_in, gzip.open(dest .gz, wb) as f_out: f_out.write(f_in.read()) os.remove(source) handler.rotator gzip_rotator这是一个小细节但对长时间运行的服务来说能显著减少磁盘占用。压缩是异步的更好但它至少能保证日志不会失控式膨胀。6. 结构化日志与Trace ID从可读走向可观测6.1 文本日志为什么难排查文本日志适合人读不适合机器分析。按行拼接的日志格式稍微不一致检索和聚合就非常痛苦。你没法直接问“过去5分钟有多少个登录失败”因为失败信息藏在几万行文本中间。而结构化日志就是让日志变成可被程序消费的数据最常用的是JSON格式。在现代后端体系里日志不再只是给人看的文件而是可观测性系统的一部分。运维平台会根据日志关键字做查询、告警、趋势统计。如果每个字段没有明确语义这些统统做不了。所以我建议新项目从第一天开始就采用结构化日志而不是等日志量大了再迁移。6.2 自己写一个JSON Formatter不引入第三方库也能实现。标准库Formatter子类把LogRecord的属性装进字典序列化成JSONimport json import logging class JsonFormatter(logging.Formatter): def format(self, record): data { time: self.formatTime(record, self.datefmt), level: record.levelname, logger: record.name, message: record.getMessage(), module: record.module, line: record.lineno, process: record.process, thread: record.thread, } for key, value in record.__dict__.items(): if key not in ( name, levelname, msg, args, exc_info, exc_text, stack_info, created, msecs, relativeCreated, module, line, process, thread ): data[key] value if record.exc_info: data[exc_info] self.formatException(record.exc_info) return json.dumps(data, ensure_asciiFalse, defaultstr)这段代码有个关键把record.__dict__里不是内置字段的自定义属性也带进JSON。这样后面我们加的request_id就会自动出现在每条日志里非常方便。当然也可以直接用python-json-logger、structlog这类库。我的建议是团队已有固定习惯就用顺手的新项目从标准库自己封装一个Formatter依赖少也更容易理解机制。6.3 给日志加上Request ID / Trace ID单次请求会经过中间件、业务函数、数据库操作、外部调用如果这些日志之间没有共同标识排查一次完整链路就像在拼图。最常见的做法是在请求入口生成一个request_id并让它自动贯穿这条链路上的所有日志。同步场景用threading.local就够异步场景要使用contextvars否则协程之间会串号。下面是一个基于ContextVar的实现import contextvars import uuid request_id_var: contextvars.ContextVar[str] contextvars.ContextVar( request_id, default- ) class RequestIdFilter(logging.Filter): def filter(self, record): record.request_id request_id_var.get() return True在FastAPI的中间件里每次请求开始时设置request_id_var.set(uuid.uuid4().hex)然后在日志格式或JSON字段中带上request_id就能把所有相关日志串起来。我曾经在一个分布式任务里用类似方案追踪一个失败的订单处理原来需要翻半小时日志后来一条request_id直接定位到8个节点的全部轨迹。7. 这些坑我几乎每个项目都会遇到7.1 重复日志与handler堆积重复日志是logging最出名的问题。症状就是某条日志在控制台出现了两次、三次排查半天发现是子logger既挂了自己的handler又没有关闭propagate于是root handler又输出了一遍。我怎么排查这类问题的先检查root上的handlers。root logging.getLogger() print(root.handlers)再看具体loggerlogger logging.getLogger(myapp.service) print(logger.handlers) print(logger.propagate)解决方向很简单二选一要么子logger不挂handler完全靠root输出要么子logger挂handler同时设置propagateFalse。如果你用的是dictConfig某个logger配置里出现了handlers: [...]且没有propagate: False就要警惕重复。另一个常见源头是配置函数被多次调用。比如在模块import时执行了一次setup_logging()函数内部又无脑addHandler导致每import一次就多一个handler。最佳实践是配置函数幂等化def setup_logging(): if logging.getLogger().handlers: return logging.config.dictConfig(LOGGING_CONFIG)7.2 basicConfig在入口之后的“失效”很多人调试时会这样写import logging logging.basicConfig(levellogging.INFO) ... logging.basicConfig(levellogging.DEBUG) # 想切到DEBUG却发现没生效原因是basicConfig只有在root还没有任何handler的时候才会执行如果已经配置过后续调用会静默忽略。这不是你写错了而是设计如此。想切换级别应该直接操作rootlogging.getLogger().setLevel(logging.DEBUG)或者重新加载完整的dictConfig。生产环境里建议把日志配置收敛到入口模块的一个函数避免散落在各处。我在项目里定了一条约定只有main.py或app.py能调用配置函数其他模块一律只创建logger。7.3 异常日志却看不到堆栈没有堆栈的ERROR只能告诉你“出错了”不能告诉你“哪里错了、为什么错”。我看到过不少代码这样写except Exception as e: logger.error(fsomething went wrong: {e})这条日志记录了错误对象但没有traceback。要拿到完整堆栈正确的姿势是except Exception: logger.exception(something went wrong)logger.exception的本质是ERROR级别加上exc_infoTrue但它必须在except块内使用因为只有那里才能拿到当前异常上下文。如果你已经捕获异常并处理完之后再用logger.exception就只能得到一条空堆栈。所以规则是捕获异常后立刻记录不要等到最后统一记。7.4 多进程和多线程并发的日志竞争日志模块本身是线程安全的多个线程写同一个handler不会导致内容交错崩溃。但多进程场景下文件handler会碰到更复杂的问题。gunicorn默认就起多个worker如果每个worker都在RotatingFileHandler里轮转同一个文件文件重命名的竞态几乎一定会出现。日志偶尔会丢轮转备份会莫名少几个。我目前的方案顺序是优先写stdout让容器或进程管理工具收集必须写文件时要么按进程PID分文件要么通过QueueHandler把日志汇聚到一个writer进程里。import multiprocessing as mp import logging.handlers queue mp.Queue(-1) def worker_main(q): h logging.handlers.QueueHandler(q) logger logging.getLogger(worker) logger.addHandler(h) logger.info(worker running) listener logging.handlers.QueueListener( queue, logging.handlers.RotatingFileHandler(app.log, maxBytes10485760, backupCount10) ) listener.start()这个方案的代价是多了一个专门消费日志的线程但换来的是多进程写安全。如果并发量不高也可以简单点每个worker进程内部独立创建一份文件文件名带PID。8. 最后分享几个我在生产环境坚持的小习惯这些经验没有写在官方文档里但确实帮我扛过了很多次线上事故。第一所有文件Handler都显式声明encodingutf-8。Windows服务器或者特殊环境里默认编码可能是GBK一旦日志里出现中文且编码不一致日志文件可能直接乱码排查起来非常闹心。第二容器应用只写stdout不写文件。Kubernetes这类环境里标准输出会被采集组件统一收集业务代码再写一份日志文件既浪费磁盘又会造成重复采集。日志的持久化、轮转、归档交给基础设施去处理应用只负责输出语义化事件。第三日志配置只加载一次并且放在入口模块的最前面。如果配置迟到早先的logger可能已经以默认级别创建后续调整会留下“部分生效”的隐患。第四预留运行时动态调整级别的通道。我现在很多项目里会暴露一个内部接口只要带上日志级别参数就能在线修改root logger的level排查问题时不用重启服务logging.getLogger().setLevel(logging.DEBUG)第五不记录核心敏感数据必须记录时先脱敏。密码、Token、Cookie值这些字段不属于日志该操心的事。最后再说一个细节如果你的日志量很大类似logger.debug(result%r, result)这种写法确实比f-string更省性能但如果格式化对象本身构造很昂贵还是需要先判断logger.isEnabledFor(logging.DEBUG)再执行。日志设计没有银弹理解机制之后每个选择都应该是可解释的。