Python日志配置实战：从print到logging工程化落地

日志这玩意说起来简单写起来头疼。大部分Python项目跑着跑着就变成print(123)print(到这里了)满天飞然后线上出问题的时候对着控制台那一堆毫无时间戳、毫无上下文的输出干瞪眼。我这些年看过太多项目的日志代码说实话能把logging用明白的项目真的不多大多数是能跑但离好用差了十万八千里。这篇博文我就直接把我平时在项目里怎么配置Python日志记录的整套思路拿出来讲透。从最基本的配置讲起到Logger、Handler、Formatter的分工再到多模块项目、日志轮转、多环境切换、结构化日志、敏感信息脱敏这些工程化实战中躲不开的问题。适合谁看如果你正在写Python脚本、维护一个长期迭代的Web服务或者刚接手一个别人写的项目被混乱的日志折磨得不行那这篇就是冲着你来的。我尽量把话说得直白把配置代码直接给你抄。1. 为什么你的日志写了等于没写1.1 先搞清楚print和logging的根本区别很多人觉得日志嘛不就是把程序运行的信息打印出来。print确实能打印但它干不了日志的活。区别在哪我打个比方print是你在马路上扯着嗓子喊了一句话喊完就完了谁听见谁没听见你不知道想找回来也找不回来。logging是你把这句话写进了一个带目录索引的档案柜里什么时间说的、什么场合说的、说的什么重要级别的信息、归档在哪个分类下全都清清楚楚回头随时能查档。具体到技术层面print只能输出到控制台它无法控制输出级别、无法写入文件、无法自定义格式、无法按模块区分。而logging天然支持这四件事而且都是内置在标准库里不需要装任何第三方包。你说你项目里想加个调试信息用print就得手动删用logging只需要把日志级别调成DEBUG就能看到发布的时候调成WARNING就自动隐藏了。这就是根本区别。1.2 日志的五个级别到底什么时候用哪个logging内置了五个日志级别从小到大依次是DEBUG调试信息开发阶段用。数据库查询、变量中间值、函数调用参数这类细颗粒度的信息都放这里。INFO关键节点信息。程序启动、服务监听端口、任务完成、用户登录这种正常流程里值得记录的事。WARNING不影响当前运行但需要关注的情况。比如磁盘空间不足、接口响应变慢、配置项用了默认值。ERROR发生错误但程序还能继续跑。比如某个请求处理失败、某次外部API调用异常。CRITICAL致命错误程序可能无法继续运行。数据库连接彻底断了、程序即将崩溃。我见过不少项目的日志代码把所有信息全打在INFO甚至DEBUG级别结果生产环境重启一下服务日志文件瞬间多出几百兆。还有的干脆什么都不区分出了事全在ERROR里捞捞完才发现一半是无效噪音。正确的做法是在写日志之前先问自己一句这条信息如果真的打出来了未来我翻日志的时候会看吗如果不会就别打。1.3 日志应该有的三种状态一套能用的日志方案至少要能覆盖三种运行场景。开发时你希望看到完整的DEBUG细节控制台输出花花绿绿的密密麻麻都不嫌多。测试时你希望看到INFO级别的流程信息方便确认测试用例走到了哪个分支。生产时你只想看到WARNING和ERROR并且全部落盘方便事后回溯。这三种状态的切换不能靠改代码必须靠配置文件或者环境变量。这是工程化的底线也是我这篇文章后面要重点展开的内容。别慌这几种状态其实很好切核心思路就是一套代码、一个配置函数、多个运行参数。2. 一套能直接抄作业的基础配置2.1 basicConfig到底做了什么又做错了什么新手接触logging最容易看到的就是logging.basicConfig。一行代码日志能跑了但也就仅仅能跑了。看下面这个例子import logging logging.basicConfig( levellogging.INFO, format%(asctime)s - %(name)s - %(levelname)s - %(message)s ) logging.info(服务启动完成)这行配置运行起来能正常工作它做的是在根Logger上创建一个默认的StreamHandler输出到控制台设置日志级别为INFO然后指定一行输出格式。就这么点事。它的局限性也很明显如果你想同时输出到控制台和文件basicConfig天生就不太支持多Handler如果你想给不同模块设置不同级别它也做不了如果你的项目引入了第三方库那些库自己也用logging输出信息你会发现你的控制台被别家的日志刷屏了。所以我的建议是basicConfig适合写一次性脚本、快速验证某个想法的时候用。但凡你的项目需要长期维护、需要跑多个模块、需要留档复盘就别图省事用basicConfig一杆子捅到底。2.2 日志格式是一门手艺活日志格式不只是写个%(message)s就完事了不同场景对格式的需求完全不同。我自己在项目里常用的一个标准格式是%(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s拆开讲讲这么写的原因。%(asctime)s是时间必须放在最前面因为排查问题第一件事就是看时间线。%(levelname)-8s里的-8s是左对齐占8个字符这样日志输出后级别那一列会非常整齐肉眼扫过去很舒服。%(name)s是Logger名字告诉你是哪个模块打的日志。%(filename)s:%(lineno)d是文件名和行号这一项特别重要没有行号你定位问题时就只能靠猜。再补充一个高级的细节默认的asctime格式长这样2024-01-15 10:23:45,123后面带毫秒。但如果你希望日志里能显示当前请求的ID或者用户名就需要用到filter或者自定义Formatter这个我后面专门讲。曾经有个运维同事找我排查一个线上问题日志打了一堆但看不到任何时间戳以外的上下文信息压根不知道是哪个用户的那个请求触发的排查过程极其痛苦。从那以后我再写日志格式一定会加上业务上下文信息。2.3 完整的基础配置文件写法直接看一个实际的配置这个示例基本是生产环境最小可用集import logging import sys LOG_FORMAT %(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s LOG_DATE_FORMAT %Y-%m-%d %H:%M:%S logging.basicConfig( levellogging.INFO, formatLOG_FORMAT, datefmtLOG_DATE_FORMAT, handlers[ logging.StreamHandler(sys.stdout), logging.FileHandler(app.log, encodingutf-8), ] )注意我这次用了handlers参数这是Python 3.3以后才支持的写法可以在basicConfig里传入多个Handler同时输出到控制台和文件。FileHandler我特意加上了encodingutf-8这行代码能救你的命。Windows环境下如果不指定编码默认可能是GBK一旦日志里出现中文或者特殊字符程序会直接抛异常。这个坑我踩过一次当时线上服务跑着跑着突然不写日志了查了半天发现是FileHandler写入时报错就是因为编码问题。3. 真正理解Logger Handler Formatter这套组合拳3.1 三个角色各自管什么很多人看到Logger、Handler、Formatter这三个名词就晕实际上它们的职责非常清晰。我用一家公司的组织架构来类比Logger是部门的负责人你向它提交一条日志请求它根据级别决定这个事该不该管Handler是具体干活的员工有的员工负责把消息贴到公告栏输出到控制台有的负责登记入档案写入文件Formatter是文员负责把消息按公司标准格式排版让记下来的内容整齐规范。在代码里它们的协作流程是这样的你的代码调用logger.info(msg)Logger接收信息后先看这条信息的级别是否高于自己配置的级别阈值如果低于阈值就直接丢弃如果高于阈值就把这条信息交给所有挂在它下面的Handler每个Handler拿到信息后又需要检查自己的级别阈值再交给Formatter排版最后输出到目标位置。这就是为什么你可以给同一个Logger挂两个Handler——一个Handler设置级别为WARNING只输出错误到独立文件另一个Handler设置为DEBUG全量输出到控制台。这种灵活组合是print完全做不到的。3.2 一个手写的控制台 文件黄金组合我平时在项目里经常这么写控制台只显示INFO级别以上的日志文件里则分两个一个记录所有INFO以上日志一个只记录WARNING和ERROR。这样既能保证开发时看控制台不闹心又能让线上错误日志单独归档、单独统计。代码长这样import logging logger logging.getLogger(my_app) # 定义一个模块级Logger logger.setLevel(logging.DEBUG) # Logger级别设为最低让所有日志都流下来 console_handler logging.StreamHandler() # 控制台Handler console_handler.setLevel(logging.INFO) # 控制台只看INFO及以上 console_handler.setFormatter(logging.Formatter( %(asctime)s | %(levelname)-8s | %(message)s )) file_handler logging.FileHandler(app.log, encodingutf-8) file_handler.setLevel(logging.DEBUG) # 文件记录所有DEBUG及以上 error_handler logging.FileHandler(error.log, encodingutf-8) error_handler.setLevel(logging.WARNING) # 错误文件只看WARNING及以上 logger.addHandler(console_handler) logger.addHandler(file_handler) logger.addHandler(error_handler)这里有个新手极容易踩的坑设置了Logger的级别是DEBUG但是Handler的级别是INFO最终输出到文件的会有DEBUG日志文件却不会记录。因为两条链上任何一个级别挡住日志都出不去。有一次我排查一个客户项目对方说我把DEBUG打开了为什么文件里还是看不到DEBUG信息一看代码Logger级别是DEBUG没错但FileHandler的级别写死了INFO。级别是双重过滤Logger一层Handler一层明白了这个原理这类问题基本就不会再出错。3.3 dictConfig才是工程化的正确姿势手动创建Handler的写法在小项目里够用但项目一旦大起来十几二十个模块你总不能每个模块都复制粘贴一遍Handler配置。而且手动配置的方案无法通过修改外部配置来切换环境硬编码在代码里换个环境就得改代码重新发布。工程化做法是用logging.config.dictConfig把配置独立成一个字典甚至存成YAML或JSON文件。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, datefmt: %Y-%m-%d %H:%M:%S, }, simple: { format: %(levelname)s | %(message)s, }, }, handlers: { console: { class: logging.StreamHandler, level: INFO, formatter: simple, stream: ext://sys.stdout, }, file: { class: logging.FileHandler, level: DEBUG, formatter: standard, filename: logs/app.log, encoding: utf-8, }, error_file: { class: logging.FileHandler, level: WARNING, formatter: standard, filename: logs/error.log, encoding: utf-8, }, }, loggers: { my_app: { handlers: [console, file, error_file], level: DEBUG, propagate: False, }, third_party_lib: { handlers: [console], level: WARNING, propagate: False, }, }, root: { handlers: [console], level: WARNING, }, } logging.config.dictConfig(LOGGING_CONFIG)讲一下这里的设计思路。formatters定义了两种格式standard带完整信息用于落盘存档simple只保留关键信息用于控制台实时显示避免终端被刷得密密麻麻。handlers定义了三个输出目标各自绑定不同的级别。loggers里my_app是我们自己的应用Loggerthird_party_lib是示意用的第三方库Logger给它单独设了WARNING级别这样第三方库的INFO日志就不容易污染主日志文件。最后还有个root兜底所有没配的Logger都走根Logger输出到控制台且只显示WARNING以上。disable_existing_loggers: False这行很关键。dictConfig执行时如果不写这一项默认会把之前已经创建的所有Logger全部禁用导致你其他模块里早先创建的Logger全部哑火。这个坑我也踩过加了一行配置以后其他模块的日志全没了排查半天才反应过来是dictConfig的锅。4. 工程化落地绕不开的几件事4.1 按模块划分Logger别再用root logger到处打模块化设计听起来虚但在日志上落地其实非常具体每个模块创建属于自己的Logger。方法很简单# utils/db.py import logging logger logging.getLogger(__name__) def connect(): logger.info(尝试连接数据库)这里__name__会自动变成类似utils.db的字符串这样日志里就能清楚看到是哪条链路打出来的。如果项目用了create_app一类的工厂模式建议在应用入口处预先写好Logger命名规范比如app.api.user、app.service.order、app.infra.kafka团队内部统一命名风格线上排查的时候一眼就能根据%(name)s字段定位到模块。为什么不建议都用根Logger因为一旦第三方库也往根Logger里塞日志你的日志文件会混进海量无关信息。而如果你在dictConfig里给第三方库单独开一个命名空间设置成WARNING级别它们就只会输出真正的问题。这是一种文明也是工程效率。4.2 日志轮转别让磁盘成为事故的起点日志文件无限增长是生产环境最常见的隐形杀手。服务刚上线没感觉跑一个月日志文件动辄几十GB磁盘告警服务莫名其妙变慢最后一看是日志把磁盘占满了。解决办法是日志轮转。Python标准库提供了两个现成的HandlerRotatingFileHandler按文件大小轮转TimedRotatingFileHandler按时间轮转。from logging.handlers import RotatingFileHandler rotating_handler RotatingFileHandler( logs/app.log, maxBytes10 * 1024 * 1024, # 每个日志文件最大10MB backupCount5, # 保留最近5个备份文件 encodingutf-8 )maxBytes满了以后当前文件自动改名为app.log.1并新建一个app.log继续写依次类推最多保留backupCount个备份最老的自动删除。这个设计非常实用磁盘占用变成有界大小单文件10MB × 6个文件 60MB服务器跑多久都不用担心磁盘被日志塞爆。按时间轮转更适合业务有明显峰谷的场景比如每天晚上定时任务跑批可以设置每天凌晨轮转一次whenmidnight再配合backupCount30保留30天的日志历史方便回溯一个月内的问题。我个人习惯是通用业务日志用大小轮转错误日志单独走时间轮转。这样既控制了膨胀速度又保证了错误信息有足够长的保留期。提示日志轮转不是配了就万事大吉。FileHandler不支持多进程同时写同一个文件如果服务用了gunicorn多Worker或者gevent协程多个进程同时写一个日志文件会互相覆盖内容。解决方案要么用ConcurrentRotatingFileHandler这种第三方扩展要么让日志通过网络发往统一的日志收集服务。这个问题在并发量大的时候几乎是必然踩到。4.3 多环境切换开发想看DEBUG生产只看ERROR我常用的做法是把日志配置做成一个函数接收debug参数或者读取环境变量。项目启动时根据环境决定配置细节。看代码import os import logging.config def setup_logging(): env os.getenv(APP_ENV, development) config LOGGING_CONFIG.copy() if env development: config[handlers][console][level] DEBUG config[loggers][my_app][level] DEBUG elif env production: config[handlers][console][level] WARNING config[handlers][file][level] INFO config[handlers][error_file][level] ERROR logging.config.dictConfig(config)这里不只是切换级别更关键的是生产环境把控制台Handler级别抬高到WARNING避免在线上的标准输出里刷一堆调试信息。而文件Handler保持INFO级别保证核心运行信息落盘。如果你的项目用的是pydantic-settings或python-dotenv只要在setup_logging里读配置值就行核心逻辑都一样。4.4 结构化日志线上排查的作弊码纯文本日志排查看多了会发现一个蛋疼的问题你想按某个业务ID去过滤日志只能靠grep硬搜搜出来还得自己用正则去抠字段。如果字段嵌套多层、值里有特殊字符那排查效率会非常低。这个时候就需要考虑结构化日志最常用的格式就是JSON。Python内置的logging不直接支持JSON输出但实现起来并不复杂——自定义一个JsonFormatter继承logging.Formatter即可import json import logging class JsonFormatter(logging.Formatter): def format(self, record): log_entry { timestamp: self.formatTime(record, self.datefmt), level: record.levelname, logger: record.name, message: record.getMessage(), module: record.module, line: record.lineno, } # 把extra字段并入日志 if hasattr(record, extra_fields): log_entry.update(record.extra_fields) return json.dumps(log_entry, ensure_asciiFalse) # 使用方式 logger logging.getLogger(my_app) logger.info(用户登录成功, extra{ extra_fields: {user_id: 12345, ip: 192.168.1.1} })这样一来每行日志就是一个JSON对象直接把日志接入ELK、Loki或者ClickHouse这类日志平台就能自动解析字段按用户ID、请求ID建索引点击即可筛选。在微服务架构里配合trace_id串联整个调用链定位问题的时间能从小时级压缩到分钟级。我强烈建议如果你的项目以后有接入日志平台的打算从一开始就用JSON格式不要等到日志量大了再迁移那会是一场噩梦。4.5 敏感信息脱敏这条是红线日志里经常出现用户信息、Token、数据库连接串这些敏感数据。一旦日志文件被拉取、被泄露事故级别直接飙升。我的原则很简单默认就是不落盘敏感信息。要打用户ID可以但不要连密码、手机号、身份证号、鉴权Token一起打出来。如果确实需要必须做脱敏处理。脱敏最简单的方式是写一个Filter在日志输出前替换敏感字段。一个脱敏Filter代码大概长这样import re import logging class MaskFilter(logging.Filter): def filter(self, record): record.msg re.sub( rpassword[:]\s*\S, password***, str(record.msg) ) return True logger logging.getLogger(my_app) logger.addFilter(MaskFilter())别小看这个环节。有些公司上线了敏感信息扫描工具日志里出现password明文直接报警。如果你在写日志时就把脱敏埋点做好这些事就不会发生。还有一个相关的细节异常堆栈里也可能泄漏信息。Python的traceback会把变量值带出来如果你觉得变量值过于敏感可以使用raise ... from None切断异常链或者自定义filter把异常信息里的敏感关键字也干掉。5. 一个从开发到上线的完整案例5.1 项目结构和配置位置结合前面讲的内容给一个完整参考。假设项目结构长这样my_project/ ├── app.py ├── configs/ │ └── logging_config.py ├── core/ │ ├── __init__.py │ ├── db.py │ └── cache.py └── services/ ├── __init__.py └── order_service.pyconfigs/logging_config.py里放的就是LOGGING_CONFIG字典以及setup_logging()函数。app.py是程序入口在启动最早的位置调用setup_logging()。各个模块里只负责getLogger(__name__)不创建Handler不设格式这样所有日志行为全部由入口统一控制。5.2 配置代码逐行拆解把前面的要点集中在一个配置里加上环境切换逻辑# configs/logging_config.py import os import logging.config BASE_FORMAT %(asctime)s | %(levelname)-8s | %(name)s | %(filename)s:%(lineno)d | %(message)s LOGGING_CONFIG { version: 1, disable_existing_loggers: False, formatters: { standard: { format: BASE_FORMAT, datefmt: %Y-%m-%d %H:%M:%S, }, json: { format: BASE_FORMAT, }, }, handlers: { console: { class: logging.StreamHandler, level: INFO, formatter: standard, stream: ext://sys.stdout, }, file: { class: logging.handlers.RotatingFileHandler, level: INFO, formatter: standard, filename: os.getenv(LOG_FILE, logs/app.log), maxBytes: 10485760, backupCount: 5, encoding: utf-8, }, error_file: { class: logging.handlers.RotatingFileHandler, level: ERROR, formatter: standard, filename: os.getenv(ERROR_LOG_FILE, logs/error.log), maxBytes: 10485760, backupCount: 5, encoding: utf-8, }, }, loggers: { : { handlers: [console, file, error_file], level: INFO, }, }, } def setup_logging(debug: bool False) - None: config LOGGING_CONFIG if debug: config[handlers][console][level] DEBUG config[loggers][][level] DEBUG os.makedirs(os.path.dirname(config[handlers][file][filename]), exist_okTrue) os.makedirs(os.path.dirname(config[handlers][error_file][filename]), exist_okTrue) logging.config.dictConfig(config)注意这里的Logger其实是根Logger所有没配独立Logger的模块都会归到这里统一输出到三个Handler。setup_logging(debugdebug)里把目录先建好避免日志文件路径不存在时报错。用RotatingFileHandler替换了前面示例里的FileHandler这个是生产必备日志文件到一定大小自动切割不会无边界膨胀。5.3 实际效果长什么样跑起来以后控制台会输出类似这样的内容2024-06-18 10:22:33 | INFO | app | app.py:12 | 服务启动监听端口: 8000 2024-06-18 10:22:34 | DEBUG | core.db | core/db.py:25 | 连接池创建成功初始连接数: 5错误日志文件error.log里只记录ERROR级别以上的信息配合前面的MaskFilter敏感信息全部被遮掉。这些配置一旦落地你未来排查任何问题时只需要一条命令grep order_id10086 logs/app.log就能把所有相关的链路信息一次性捞出来。6. 我踩过的坑和排查技巧实录6.1 经典疑难问题速查表这一节把我的实操经验直接表格化方便你遇到问题的时候对照参考。症状原因解决方案日志完全不输出Logger级别挡住了或者Handler没挂到Logger上检查Logger级别和Handler级别确认调用了addHandler或配置里绑定正确日志重复输出同一个Logger被多次addHandler或者propagate与根Logger同时输出给自定义Logger设置propagateFalse确保入口只调用一次配置函数文件中没有DEBUG信息Logger级别是DEBUG但FileHandler级别不是DEBUG双重级别都要放行Logger和Handler都要检查多进程写同一个日志文件相互覆盖FileHandler不支持多进程并发写用ConcurrentRotatingFileHandler或统一发送到日志服务日志中文乱码Windows默认编码或未指定encoding创建Handler时指定encodingutf-8第三方库日志刷屏第三方库用了根Logger或自己的Logger且级别低在dictConfig中单独设置该库的Logger级别dictConfig执行后其他模块日志消失disable_existing_loggers默认值是True显式设置为False日志文件被占满磁盘未做日志轮转换用RotatingFileHandler或TimedRotatingFileHandler6.2 追求性能别让日志拖垮你的程序日志写入磁盘看起来不费事但如果代码里的日志调用非常频繁比如循环内部每跑一次都打一条DEBUG日志系统的I/O开销会明显影响吞吐。Python的logging是同步的一个info调用要经历格式化、级联过滤、多个Handler逐个写入这些步骤串行执行。如果你的程序是性能敏感型有几个技巧可以优化循环体外打日志循环内只打关键的中间结果不要每轮迭代都打。懒构建消息日志用的是logger.info(result: %s, expensive_func())这种格式化方式而不是logger.info(result: %s % expensive_func())。前者只有当这条日志真会输出时才执行格式化后者则会无条件调用expensive_func()。这个隐藏的性能差异在华为OD面试里都出现过可见它有多容易被忽略。异步日志如果日志量确实大可以把日志写入放到后台线程。标准库没有异步Handler但可以通过继承Handler重写emit方法把日志放入队列再开一个线程统一写文件。简单实现如下import queue import logging import threading class AsyncHandler(logging.Handler): def __init__(self, target_handler): super().__init__() self.target_handler target_handler self.queue queue.Queue() self.thread threading.Thread(targetself._consume, daemonTrue) self.thread.start() def emit(self, record): self.queue.put(record) def _consume(self): while True: record self.queue.get() self.target_handler.emit(record)用了异步Handler主流程完全不需要等待磁盘I/O写入操作全在后台线程完成。不过要注意程序崩溃时队列里可能还有日志没写进去关键日志建议还是同步写。6.3 异常日志最容易写错的一个细节捕获异常的时候打日志很多新手写成这样try: result risky_func() except Exception as e: logger.error(出错了: %s, e)这个写法有个致命缺陷它只记录了异常的消息字符串完全丢失了异常堆栈。堆栈才是你定位问题的最重要线索如果真的发生异常光看一句division by zero你根本不知道是哪个文件哪一行除零了。正确写法是try: result risky_func() except Exception: logger.error(出错了, exc_infoTrue)exc_infoTrue会把完整堆栈打进日志。如果你的项目中这个函数是Python 3.10还可以用except Exception as e: logger.error(..., exc_infoe)效果相同但更明确。我见过太多项目因为这里少了一个参数导致线上排查困难重重。注意这个细节你的日志价值至少翻一倍。写在最后的一点体会日志这个东西你写的时候总会觉得是在浪费时间出了问题的时候才会庆幸当初多写了一句。我是一个日志洁癖非常重的人项目里宁可代码写慢一点也要保证每次提交都有清晰的日志记录。因为线上问题往往不会给你留出打日志、重新发布、再复现的机会这时候唯一能依靠的就是你之前埋下的那些看似不起眼的日志条目。如果你看完这篇文章准备重构现有项目的日志配置我的建议是不要一次推翻先把基础配置改成dictConfig把生产环境级别设为INFO每次排查问题后顺手补充缺失的关键日志点日志系统就会在一个个迭代中越来越顺手。还有一点日志不只是写给别人看更是写给三小时、三天、三个月后的自己看的所以请务必保持结构清晰、格式统一、信息有效。