一直在用 print 排查问题说真的每次看到新同事在项目里四处撒 print我都替他捏把汗。Python 的 logging 模块绝对不是“换个方式打印消息”那么简单它是你在生产环境里唯一能依赖的“黑匣子”。今天这篇不是什么官方文档翻译是我在实际项目里把 logging 从头梳理到工程化落地后踩过坑、翻过车、又重新整理出来的实操总结。1. 项目概述日志系统该有的样子1.1 为什么是 logging而不是 print刚接触 Python 时我也是 print 走天下。小脚本无所谓print 甚至更快上手。可一旦程序跑在服务器上、跑在无人值守的凌晨三点print 的弊端就全暴露了你没法分级过滤、没法控制输出位置、没法做轮转切割更别说在多线程或多进程环境下保证日志不串行。说白了print 是“写给眼睛看的”logging 是“写给系统看的”两者的目标完全不同。我见过太多线上事故的复盘第一句话永远是“当时没有日志没法定位”。与其事后补日志不如一开始就把日志当成一套独立的基础设施来设计。logging 模块作为标准库自带的能力在生产环境成熟度极高你可以零依赖实现从控制台输出到文件落盘再到远程采集的全链路。1.2 工程化最佳实践的核心思路所谓“工程化最佳实践”在我理解里就三件事让日志可读、可靠、可控。可读是格式统一、上下文明确一条日志扫过去就知道发生了什么可靠是日志不能随意丢崩溃前最后一条日志一定要在可控是指级别过滤、输出目标、文件大小这些都能通过配置切换不需要改业务代码。围绕这三点logging 提供了一套组件化机制下面会逐一拆解。2. 核心细节解析搞懂 logging 的四件套2.1 Logger、Handler、Formatter、Filter 到底谁管谁我见过很多人把logging.info当全局函数用其实logging体系里有四个核心对象各司其职Logger日志记录的入口业务代码里只跟它打交道。它有层级结构名字用点号分隔比如app.module。Handler决定日志“去哪儿”。是写文件、输出控制台还是发到网络。Formatter决定日志“长什么样”也就是格式模板。Filter决定日志“要不要记”比级别更细粒度地做筛选。打个比方Logger 是前台接待Filter 是安检员Formatter 是排版员Handler 是物流车辆。业务消息从前台进来过安检、排版后交给不同的物流线送走。理解了这层关系你就知道为什么basicConfig解决不了所有问题——它只是把所有日志统一交给一个默认的 root Handler 处理想精细化管控就得自己组装。2.2 实际开发中如何创建与获取 Logger一个很常见的错误是到处logging.getLogger()然后乱配置。正确姿势是什么在每个模块里用logger logging.getLogger(__name__)让 logger 名字跟着模块路径走。这样日志里天然带着“哪个模块打了这条日志”的信息排查效率直接翻倍。我个人的习惯是只在程序入口和配置中心做 Handler 的初始化业务模块只负责获取 Logger 并打日志。这样既能统一格式又能避免重复配置导致日志重复输出。补充一个细节getLogger(__name__)传进去的__name__可能等于__main__这时候层级关系会有点特殊。如果项目有入口文件建议入口文件里显式指定一个逻辑名比如getLogger(app.main)子模块自然成为它的下级继承关系才清晰。2.3 级别体系与传播机制Python 的日志级别从低到高是 DEBUG、INFO、WARNING、ERROR、CRITICAL。设置 Logger 级别为 WARNING 后DEBUG 和 INFO 记录会被跳过。这里有个关键细节Handler 也有自己的级别两条线是叠加生效的。比如 Logger 级别是 INFOHandler 级别是 ERROR那么最终只有 ERROR 及以上才会经这个 Handler 输出。传播机制同样容易踩坑。默认情况下 Logger 的日志会向父 Logger 传播一直传到 root。如果父类有个 Handler子 Logger 又配了一个 Handler同一条日志会出现两次。解决办法是有两种要么设置logger.propagate False要么老老实实做层级隔离。3. 实操过程从小白到工程化的配置演进3.1 快速起步版一次搞定控制台加文件如果你在写一个脚本工具用basicConfig快速落盘是没问题的import logging logging.basicConfig( levellogging.INFO, format%(asctime)s | %(levelname)s | %(name)s | %(message)s, datefmt%Y-%m-%d %H:%M:%S, filenameapp.log, encodingutf-8, filemodea, ) logging.info(程序启动)这段配置做了几件事设置了全局级别、统一输出格式、指定文件路径并追加写入。注意encodingutf-8是关键Windows 下不设这个容易中文乱码。filemodea保证每次启动不清空历史日志。但basicConfig最大的问题在于它是一次性的调用之后再执行会静默失效而且无法精细控制多个输出目标。所以它更适合脚本不适合作为服务型项目的基础。3.2 工程落地版用 dictConfig 替代硬编码真正的工程项目里我推荐使用logging.config.dictConfig直接把配置写成一个字典放在logger_config.py文件里。好处是配置集中、可读性强、以后还能改成 JSON 或 YAML 文件LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: %(asctime)s [%(levelname)s] %(name)s: %(message)s }, verbose: { format: %(asctime)s [%(levelname)s] %(processName)s %(threadName)s %(name)s: %(message)s }, }, handlers: { console: { class: logging.StreamHandler, formatter: standard, level: DEBUG, }, file: { class: logging.handlers.RotatingFileHandler, filename: logs/app.log, formatter: verbose, level: INFO, maxBytes: 10485760, backupCount: 5, encoding: utf-8, }, }, root: { level: DEBUG, handlers: [console, file], }, }这段配置里有个点值得说为什么文件用RotatingFileHandler因为单文件无限增长会拖垮磁盘、影响定位。设置maxBytes10485760即 10MB、backupCount5日志就能按大小自动轮转保留最近 5 份历史文件。这是生产环境最基本的要求。调用方式很简单from logging.config import dictConfig dictConfig(LOGGING_CONFIG)disable_existing_loggers建议设成 False否则除你显式声明的 logger 外其他 logger比如第三方库自带的会被全部禁掉到时候排查第三方依赖的问题会少很多线索。3.3 模块化改造让业务代码与日志配置解耦配置集中了业务代码还要配合。我通常在项目里建一个log.py模块负责统一初始化然后每个业务模块按需获取# log.py import logging from logging.config import dictConfig def setup_logging(): dictConfig(LOGGING_CONFIG) # biz_service.py import logging logger logging.getLogger(__name__) def do_something(): logger.info(开始处理业务) try: # 业务逻辑 pass except Exception as exc: logger.exception(处理失败异常详情如下)注意到logger.exception没有它等价于logger.error(..., exc_infoTrue)会自动把当前异常栈完整打出来排查 bug 时这就是命根子。凡是except块里打日志我都强烈建议用 exception 而不是 error。3.4 参数选择的理由格式、时区与上下文格式串里我常用%(asctime)s、%(levelname)s、%(name)s、%(message)s。线上环境还会加%(processName)s和%(threadName)s因为多进程多线程环境下同一时间点可能在多个上下文里打日志没有这两个字段没法快速归因。datefmt控制时间格式不过要提醒asctime用的是本地时间。如果你的应用部署在 Docker、K8s 这种环境底层时区可能跟你想的不一样。规范做法是容器基础镜像里统一设置TZ环境变量。否则日志时间跟监控报警时间对不上定位起来特别痛苦。之前在一个项目里就吃过这个亏应用一直按 UTC 打日志运维排查问题时用自己的本地时间整整差 8 个小时一个简单问题查了快两个小时才反应过来。4. 工程化最佳实践生产环境的所有关键细节4.1 日志目录规划与权限管理日志文件不是随便往哪一扔就行。我推荐在项目目录下单独建logs/目录并通过.gitignore忽略。刚启动项目时logs/可能还不存在因此程序里要保证目录已创建from pathlib import Path Path(logs).mkdir(exist_okTrue, parentsTrue)exist_okTrue表示目录已存在时不报错parentsTrue表示递归创建父目录。这个逻辑最好放在读取日志配置前执行否则首次启动就会抛 FileNotFoundError。在服务器上还有个隐藏问题日志文件的所有者是谁如果应用通过 systemd 启动而日志目录归属 root应用进程跑在普通用户下就会普通失败。我通常会让部署脚本单独创建日志目录并chown给运行用户而不是在应用代码里尝试 mkdir 到不可写的路径。4.2 RotatingFileHandler 与 TimedRotatingFileHandler 的选择轮转策略就两类按大小轮转和按时间轮转。按大小适合日志量随业务波动的系统比如某天活动大促日志大到 1GB它一样能切割按时间适合需要跟自然日对齐做统计分析的场景比如每天一个文件运维脚本按天归档。我选择的标准很简单如果日志要做长期归档和离线分析就选TimedRotatingFileHandlerwhenmidnight加backupCount按天保留如果日志量不稳定就选RotatingFileHandler。两种 handler 还有个共性坑它们不会处理日志文件的编码和权限变更。Log rotation 生成了新文件后如果应用崩溃重启文件权限需要重新确认。自动化部署脚本里最好加一步验证。4.3 格式化与上下文信息增强线上日志里我最关注三类上下文时间、来源、业务追踪 id。单实例单线程的情况下logger name 就能定位来源。但分布式系统里一次请求跨多个服务链路时就必须在日志里注入 trace id。一个轻量做法是在请求入口生成 trace id 后放进线程局部变量或 contextvar然后在 Formatter 里读取import contextvars import logging 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 FORMAT %(asctime)s | %(levelname)s | %(request_id)s | %(name)s | %(message)s这里的逻辑不复杂Filter 本身不做筛选而是给 LogRecord 动态塞一个属性Formatter 就可以在模板里引用%(request_id)s。中间件里设置request_id_var.set(generate_trace_id())这样从请求进来到结束整个线程上下文里所有日志都会带上同一个 trace id。排查一个请求跨多个模块的调用链时一条 grep 全出来了。4.4 结构化日志面向机器可读的 JSON 输出如果日志是给人翻文件看的传统 text 格式够了。但现在主流姿势是把日志输出为 JSON 结构化格式让采集端比如 ELK 或 Loki直接解析字段。一个简单的 JSON Formatter 思路import json import logging class JsonFormatter(logging.Formatter): def format(self, record): log_entry { time: self.formatTime(record, self.datefmt), level: record.levelname, logger: record.name, message: record.getMessage(), request_id: getattr(record, request_id, -), } if record.exc_info: log_entry[exc_info] self.formatException(record.exc_info) return json.dumps(log_entry, ensure_asciiFalse)关键点在于getattr(record, request_id, -)要有个默认值因为不是每一条日志都会经过设置 request_id 的 Filter没有默认值直接 AttributeError 就整个日志系统崩了。实际运行中我还会加上module、line这类来源信息在 Formatter 里通过record.module和record.lineno就能拿到。类似source: f{record.module}:{record.lineno}查问题时可以直接定位到代码行。4.5 性能考量避免日志拖垮业务日志是 IO 操作打得太猛会拖慢接口响应。前面配置里我们加了RotatingFileHandler本质上是把 IO 限制在可预期的范围内。但还有两个性能优化技巧值得注意一是对极高频率的低级日志做采样。比如处理百万级请求每条都打 DEBUG 不现实。你可以定义采样 Filter每 1000 条只记 1 条。这个 Filter 的核心逻辑是维护一个计数器取模后决定是否放行。二是采用异步 Handler。标准库没有直接提供异步日志 handler但是QueueHandler加QueueListener的组合能实现生产消费模型业务线程把日志放进内存队列立刻返回后台线程批量写入磁盘。这套方案在 Web 服务高并发场景下很实用我自己的一个处理量比较大的服务里用上这两个类之后接口的延迟抖动明显下降。代码参考import queue from logging.handlers import QueueHandler, QueueListener log_queue queue.Queue(-1) queue_handler QueueHandler(log_queue) file_handler logging.handlers.RotatingFileHandler(logs/app.log) listener QueueListener(log_queue, file_handler) listener.start()无界队列queue.Queue(-1)在高并发下内存会持续增长。更稳的做法是给队列设置上限配合QueueHandler在队列满时丢弃日志用ERROR级别日志确保关键信息不死。这个取舍要按业务重要程度来定。4.6 多进程环境与进程安全的保障刚才提到的QueueHandler方案其实还顺带解決了多进程日志写入的混写问题。如果对RotatingFileHandler的多进程写入逻辑熟悉的话你应该知道它底层通过锁来保证同一时刻只有一个进程在写同一个文件但锁会降低效率而且进程在轮转时会产生大量竞态。我坚持的方案是每个进程使用独立文件句柄还是统一汇总如果应用本身是多进程的建议要么用 multiprocessing 的 queue 汇总日志后由单进程写入要么交给外部采集器直接读取 stdout。综合下来QueueHandlerQueueListener是最标准的多进程日志方案。从运维角度来说多进程环境里 pid 字段非常有价值。Formatter 加%(process)d一旦多进程的日志写入同一文件你还能通过 pid 区分是哪个进程干的“好事”。5. 常见问题与排查技巧实录5.1 重复日志让人头大的经典问题这是 logging 初学者遇到最多的问题控制台打印了一遍文件里又打印了一遍甚至同一个 handler 输出两条。根因不外乎两个一是同一个 logger 被反复 addHandler二是propagate没关闭子 logger 和 root logger 各输出了一次。我排查时习惯在代码里搜logging.basicConfig和getLogger()的组合调用凡是入口文件和模块代码都调用了基本配置的重复几乎不可避免。修复方案basicConfig全局只调用一次如果必须动态配置给 logger 先判空再 addHandlerif not logger.handlers: logger.addHandler(handler)还有更干净的做法项目里只保留一份 dictConfig 配置所有模块只通过getLogger(__name__)获取不主动增删 Handler。5.2 日志不输出或中文乱码问题日志一声不吭的时候优先检查三级配置Logger 级别、Handler 级别、root 级别。三者取“较严格”的交集任何一个卡住了都不会有输出。乱码问题则是平台相关的。Linux 下默认 UTF-8 基本没事Windows 下命令行再重定向文件就会出问题。处理方案是给 Handler 加encodingutf-8控制台场景如果还乱码在脚本头部加sys.stdout.reconfigure(encodingutf-8)。5.3 文件写不进去与权限问题排查有一种很隐蔽的情况代码运行时是在 Docker 容器里日志文件夹是通过 volume 挂载出来的。如果宿主机目录权限是 755 且属于 root容器内进程又是非 root 用户日志创建就会失败。此时 logging 默认会静默失败还是报错实际情况是文件日志打不开时默认会向 stderr 输出错误但很多容器里 stderr 没人关注等于丢日志了。最好在启动时主动检查log_file Path(logs/app.log) try: log_file.touch() except PermissionError: sys.stderr.write(f日志文件不可写: {log_file}) sys.exit(1)至少让问题暴露在启动阶段而不是运行几天后才发现日志断了。5.4 敏感信息脱敏与安全问题日志容易把信息带飞比如用户手机号、身份证、token、密码等。这些信息一旦进了日志文件又同步到日志平台泄密风险极大。通常做法是在项目里建一个SanitizeFilterimport re class SanitizeFilter(logging.Filter): SENSITIVE_RE re.compile(r(password[:]\\s*)(\\S), re.IGNORECASE) def filter(self, record): try: record.msg self.SENSITIVE_RE.sub(r\\1***, record.getMessage()) except Exception: pass return True但这里要说明一点record.msg直接改并不总是安全的因为 LogRecord 的getMessage()可能是拼接后的格式化内容。实际工程上我会在日志输出前先组装好脱敏后的 message。5.5 常见问题速查表现象可能原因优先排查动作控制台有日志但文件是空的FileHandler 级别设置过高检查 handler 的 level同一条日志重复打印propagate 未关闭或重复 addHandlerlogger.propagate False文件不轮转maxBytes 设置过小或 backupCount 为 0检查 RotatingFileHandler 参数时间少 8 小时容器时区默认 UTC设置 TZ 环境变量日志中断没有记录日志目录不可写或权限被回收启动时 touch 验证日志里出现二进制乱码消息包含非字符串对象日志前强制 str() 或 json.dumps同时出现 stderr 和文件重复StreamHandler 与 FileHandler 同配确认 handler 归属与 propagate5.6 我的几则排查实录与个人体会先说一个印象深刻的线上机问题某接口偶发超时大日志量下完全无头绪。后来我把日志格式加上%(threadName)s和%(processName)s才发现是某个线程池队列堆积多个线程同时持有锁导致请求等待。事后复盘那条日志在 text 格式下其实也有线程信息但没显式放到格式模板里很多人根本没注意。这种改进不复杂却直接影响排查效率。再说一个习惯上的建议打日志要打“带有可搜索上下文”的日志。比如logger.info(订单创建成功, order_id%s, user_id%s, order_id, user_id)比logger.info(f订单创建成功, {order_id}, {user_id})更好。前者使用参数化消息在 python 里就算该条日志被级别过滤掉也不会去做字符串拼接省了一笔性能开销。我自己在项目里已经强制要求后者写法。尤其高频交易或网关这类需要记录大量事件的服务参数化日志对性能提升虽不算肉眼可见但长期跑下来 GC 压力小不少。最后分享一个小技巧线上排查问题别只盯着 errorlogger.debug在关键路径上也要留然后通过配置动态调级别。线上默认 INFO需要排查时临时切到 DEBUG问题定位完再切回来。日志系统就像仪表盘平时低调关键时刻得能放大招。对 logging 这块我还有蛮多可聊的比如怎么跟 Sentry、ELK 这类外部平台集成这次先写到这里。在你自己的项目里动手配一套把格式调成自己需要的再监控一下文件轮转和性能开销跑几天回头看你就会明白日志工程化的价值了。