1. 日志系统到底在解决什么问题
刚入行那会儿,我对日志的理解就是"print大法好"。代码跑不通了,到处插print,调试完再一行行删掉。直到有一次线上服务半夜挂了,第二天翻遍控制台输出,发现关键信息早被滚屏冲没了,才意识到:日志不是调试的附属品,它是一套独立的、需要认真设计的系统。
logging模块就是Python标准库给这套系统提供的官方答案。它要解决的核心问题有三个:第一,信息分级,不是所有输出都同等重要,调试信息不该出现在生产环境的告警里;第二,输出分流,同一件事可能需要写到文件、打到控制台、同时发给监控系统,格式还各不相同;第三,性能与可控性,日志写多了拖慢程序,写少了出问题查不到,得能动态调整。
这套东西适合谁?我的判断是:只要你的代码超过两百行,或者需要交给别人维护,或者要跑在你看不到的地方(服务器、定时任务、后台进程),就该用logging。新手常觉得它比print麻烦,但等你经历过一次"线上出问题但没有任何线索"的绝望,就会明白这点麻烦有多值。
logging模块的设计哲学是职责分离:产生日志的地方只管产生,怎么处理、写到哪、什么格式,全部交给另一套配置体系。这个分离思想是理解整个模块的钥匙,后面讲的所有组件,都是围绕这个分离展开的。
2. logging模块的四大核心组件拆解
很多人用logging就是抄一段basicConfig,能跑就行。但一旦需求变复杂——比如想让不同模块的日志写到不同文件——就抓瞎了。根子在于没搞清这四个组件各自管什么。
2.1 Logger:日志的入口和层级管理者
Logger是你代码里直接调用的对象,logging.getLogger(__name__)拿到的就是它。它干两件事:一是提供debug/info/warning/error/critical这些方法让你产生日志;二是维护一个树状的层级结构。
这个层级结构是很多人忽略的重点。Logger的名字用点号分隔,a.b.c的父级是a.b,再往上是a,最顶端是root。当你调用a.b.c这个logger时,日志会沿着这条链往上传播(propagate),父级logger的handler也会处理这条日志。我见过有人纳闷"为什么我的日志打了两遍",八成就是子logger和父logger都挂了handler,日志传播上去被重复处理了。
import logging # 这两个logger存在父子关系 parent = logging.getLogger("myapp") child = logging.getLogger("myapp.database") # child的日志默认会传播给parent处理控制传播用logger.propagate = False,这是避免重复输出的标准手段。
2.2 Handler:决定日志去哪儿
Handler负责"输出目的地"。一个logger可以挂多个handler,实现一份日志多处输出。常用的有:
| Handler类型 | 输出目标 | 典型场景 |
|---|---|---|
| StreamHandler | 控制台/流 | 开发调试 |
| FileHandler | 单个文件 | 简单持久化 |
| RotatingFileHandler | 按大小切割的文件 | 生产环境防爆盘 |
| TimedRotatingFileHandler | 按时间切割的文件 | 按天归档 |
| NullHandler | 丢弃 | 库开发占位 |
这里有个关键点:handler自己也有日志级别。一条日志要真正被写出来,得同时通过logger的级别和handler的级别两道关。我踩过的坑是:logger设成DEBUG,handler忘了改,默认是NOTSET(等于0,全放行),结果正常;但反过来logger设INFO、handler设DEBUG,DEBUG日志在logger那关就被拦了,根本到不了handler。两道关卡是"与"的关系,取更严格的那个。
2.3 Formatter:日志长什么样
Formatter决定每条日志的最终文本格式。它用%风格的占位符,常用的字段我整理成表:
| 占位符 | 含义 | 示例输出 |
|---|---|---|
| %(asctime)s | 时间 | 2024-01-15 10:30:45,123 |
| %(levelname)s | 级别名 | INFO |
| %(name)s | logger名 | myapp.database |
| %(message)s | 日志内容 | 连接成功 |
| %(lineno)d | 行号 | 42 |
| %(funcName)s | 函数名 | connect |
| %(process)d | 进程ID | 12345 |
| %(threadName)s | 线程名 | MainThread |
时间格式可以自定义,datefmt="%Y-%m-%d %H:%M:%S"。我强烈建议生产环境带上%(process)d和%(threadName)s,多进程多线程出问题时,没有这两个字段你根本分不清是哪条线出的错。
2.4 Filter:精细的过滤器
Filter是最容易被忽视的组件,但它能解决一些刁钻需求。它挂在logger或handler上,filter()方法返回True才放行。比如你想过滤掉某个特定模块的日志,或者只保留包含特定关键词的日志,都可以用Filter实现。
class NoHealthCheckFilter(logging.Filter): def filter(self, record): # 过滤掉健康检查产生的噪音日志 return "healthcheck" not in record.getMessage() handler.addFilter(NoHealthCheckFilter())这四个组件的关系可以这样理解:Logger是水龙头,Handler是水管通向的容器,Formatter是容器的标签格式,Filter是管道上的筛网。水(日志)从龙头出来,经过筛网过滤,通过水管流进容器,按标签格式呈现。
3. 日志级别与传播机制的门道
级别这东西看着简单,用起来全是细节。
3.1 五个级别的真实使用场景
标准库定义了五个级别,数值从低到高:DEBUG(10)、INFO(20)、WARNING(30)、ERROR(40)、CRITICAL(50)。但光记数值没用,关键是什么场景该用哪个。我的经验划分:
- DEBUG:只有开发时关心的细节。变量值、循环进度、函数进出。生产环境一律关掉。
- INFO:正常业务流程的关键节点。服务启动、配置加载、任务开始结束。这是生产环境的主力级别。
- WARNING:不正常但程序还能跑。磁盘快满了、接口响应慢、用了废弃的参数。需要关注但不紧急。
- ERROR:功能出错了。请求处理失败、数据库连接断了。需要立即排查。
- CRITICAL:整个程序要挂了。关键依赖不可用、内存耗尽。通常伴随告警。
我见过太多项目把什么都打成INFO,结果日志文件一天几个G,真正的问题淹没在噪音里。级别不是随便选的,它决定了这条日志值不值得被人在半夜叫起来看。
3.2 传播机制与重复输出陷阱
前面提过传播,这里展开说。当你在myapp.database这个logger上打日志,如果它自己没有handler,日志会往上找myapp的handler,再往上找root的handler。只要某一层有handler处理了,日志就输出了。
问题出在:如果myapp和root都配了handler,一条日志会被输出两次。这是新手最常见的"日志重复"原因。解决办法有两个:要么只在root配handler,子logger靠传播;要么给子logger配handler的同时设propagate = False。
logger = logging.getLogger("myapp.database") logger.addHandler(file_handler) logger.propagate = False # 切断向上传播,避免重复注意:
propagate = False只影响传播,不影响当前logger自己的handler。设了它,日志就只在当前logger的handler里处理。
3.3 级别继承的坑
子logger如果没有显式设级别,会继承父级的有效级别。这个"有效级别"的计算方式是:从当前logger往上找,找到第一个显式设置了级别的logger,用它的级别。如果一路找到root都没设,root默认是WARNING。
这意味着:你新建一个logger,啥都不配,直接打INFO,是打不出来的——因为root默认WARNING,INFO被拦了。很多人第一次用getLogger就卡在这,以为模块坏了。其实要么给logger设级别,要么调basicConfig把root级别降下来。
4. 从零搭建一套可用的日志配置
理论讲完,上实操。我按"开发环境"和"生产环境"两套配置来讲,这是最实用的分法。
4.1 开发环境:控制台输出就够了
开发时最省事的是basicConfig,一行搞定:
import logging logging.basicConfig( level=logging.DEBUG, format="%(asctime)s [%(levelname)s] %(name)s:%(lineno)d - %(message)s", datefmt="%H:%M:%S" ) logging.debug("调试信息") logging.info("普通信息")basicConfig的本质是给root logger配一个StreamHandler。它有个坑:只能生效一次。第二次调用如果root已经有handler了,它什么都不做。所以别指望在多个模块里反复调它来改配置,改不动的。要动态改,得手动操作root的handler。
开发环境我建议格式里带上%(name)s和%(lineno)d,这样一眼能看出日志从哪个模块哪一行来的,比print强太多。
4.2 生产环境:文件切割加多目标输出
生产环境的核心诉求是:别爆盘、别丢关键信息、方便排查。我的标准配置是这样的:
import logging from logging.handlers import RotatingFileHandler def setup_logging(): logger = logging.getLogger("myapp") logger.setLevel(logging.INFO) logger.propagate = False # 控制台handler,只放WARNING以上 console = logging.StreamHandler() console.setLevel(logging.WARNING) console.setFormatter(logging.Formatter( "%(asctime)s [%(levelname)s] %(message)s" )) # 文件handler,按大小切割,保留5个备份 file_handler = RotatingFileHandler( "app.log", maxBytes=10 * 1024 * 1024, # 10MB backupCount=5, encoding="utf-8" ) file_handler.setLevel(logging.INFO) file_handler.setFormatter(logging.Formatter( "%(asctime)s [%(levelname)s] %(name)s:%(lineno)d " "[%(process)d:%(threadName)s] - %(message)s" )) logger.addHandler(console) logger.addHandler(file_handler) return logger这套配置的考量:控制台只放WARNING以上,避免刷屏;文件放INFO以上,保留完整业务轨迹;按10MB切割保留5份,最多占50MB,不会爆盘;格式里带进程和线程,多并发时能定位。
maxBytes和backupCount怎么定?我的经验是:先估算单条日志平均大小(大概200字节),再乘以每天的日志条数,得出日增量。比如一天10万条,约20MB,那maxBytes设10MB就是一天切两次,backupCount设5就是保留两天半。想保留更久就调大backupCount,或者改用TimedRotatingFileHandler按天切。
4.3 用字典配置实现配置与代码分离
硬编码配置有个问题:改日志级别得改代码重新部署。更好的做法是用dictConfig,把配置抽成字典甚至独立的配置文件。
import logging.config LOGGING_CONFIG = { "version": 1, "disable_existing_loggers": False, "formatters": { "standard": { "format": "%(asctime)s [%(levelname)s] %(name)s - %(message)s" } }, "handlers": { "console": { "class": "logging.StreamHandler", "level": "INFO", "formatter": "standard", "stream": "ext://sys.stdout" }, "file": { "class": "logging.handlers.RotatingFileHandler", "level": "INFO", "formatter": "standard", "filename": "app.log", "maxBytes": 10485760, "backupCount": 5, "encoding": "utf-8" } }, "loggers": { "myapp": { "level": "INFO", "handlers": ["console", "file"], "propagate": False } }, "root": { "level": "WARNING", "handlers": ["console"] } } logging.config.dictConfig(LOGGING_CONFIG)disable_existing_loggers这个参数要特别注意,默认是True,会把已经存在的logger全禁用掉,容易出诡异问题。我一般显式设成False。这套配置可以存成JSON或YAML文件,用环境变量控制加载哪份,实现"开发用DEBUG、生产用INFO"的切换,不用改一行代码。
5. 实战中踩过的坑与排查技巧
这部分是我这些年攒下的血泪经验,文档里基本不会写。
5.1 日志不输出的排查顺序
日志打不出来,按这个顺序查,基本能定位:
- 级别够不够:logger级别、handler级别、root级别,三道关都得过。先确认你要打的级别数值大于等于所有关卡的级别。
- handler挂没挂:logger没handler且propagate被关了,日志就凭空消失。用
logger.handlers看一眼。 - 传播断没断:子logger没handler,父logger有,但propagate=False,日志也出不来。
- basicConfig被抢先调用:别的库先调了basicConfig,你的配置就不生效了。
我做过一个排查清单表,出问题时对着过一遍:
| 现象 | 最可能原因 | 快速验证 |
|---|---|---|
| 完全没输出 | logger无handler且不传播 | 打印logger.handlers |
| 部分级别没输出 | 级别设置过高 | 打印logger.getEffectiveLevel() |
| 日志重复 | 传播导致多次处理 | 检查propagate和各级handler |
| 格式不对 | Formatter没设或设错 | 检查handler.formatter |
| 文件没内容 | 文件handler级别过高 | 检查handler.level |
5.2 多进程写同一文件的灾难
RotatingFileHandler在多进程下会出大问题。多个进程同时切割文件,会导致日志丢失甚至文件损坏。我吃过这个亏:一个多进程任务,日志文件时不时少一大段。
解决方案有三个:一是每个进程写自己的文件,文件名带进程ID;二是用QueueHandler把日志集中到一个进程写;三是用支持多进程的第三方handler。最省事的是第一种:
import os from logging.handlers import RotatingFileHandler pid = os.getpid() handler = RotatingFileHandler(f"app_{pid}.log", maxBytes=10485760, backupCount=3)5.3 异常信息别只打str(e)
捕获异常时,logging.error(str(e))只拿到异常消息,丢了堆栈。排查时没有堆栈等于没有线索。正确姿势是用exc_info=True:
try: risky_operation() except Exception: logging.error("操作失败", exc_info=True) # 或者用 logging.exception("操作失败"),等价于 error + exc_infologging.exception只能在except块里用,它会自动带上当前异常信息。这个细节能帮你省下大量排查时间。
5.4 性能敏感场景的懒加载
日志内容拼接是有开销的。logging.debug("结果:" + str(expensive_call()))这种写法,即使DEBUG级别被关掉,expensive_call()照样执行,白白浪费性能。正确做法是用占位符,让logging在确定要输出时才格式化:
# 不好:无论级别如何都会执行expensive_call logging.debug("结果:" + str(expensive_call())) # 好:只有DEBUG开启时才执行 logging.debug("结果:%s", expensive_call())这个差别在高频循环里非常明显。我实测过一个每秒调用上万次的函数,改成占位符后,关闭DEBUG时性能提升了将近三成。
6. 让日志真正产生价值的几个进阶思路
配置对了只是及格,让日志真正帮到你才是目标。
6.1 结构化日志便于检索
纯文本日志人看还行,机器分析就费劲。可以考虑输出JSON格式,方便日志系统采集和检索:
import json import logging class JsonFormatter(logging.Formatter): def format(self, record): log_obj = { "time": self.formatTime(record), "level": record.levelname, "logger": record.name, "message": record.getMessage(), "line": record.lineno } if record.exc_info: log_obj["exception"] = self.formatException(record.exc_info) return json.dumps(log_obj, ensure_ascii=False)结构化日志的好处是,你可以按字段过滤、聚合、统计,比如"统计过去一小时ERROR级别的日志按模块分布",纯文本得写正则,JSON直接查字段。
6.2 用上下文补充关键信息
排查问题时,光有消息不够,还得知道是哪个用户、哪个请求出的问题。可以用LoggerAdapter或者extra参数往日志里塞上下文:
logger = logging.getLogger("myapp") logger.info("处理订单", extra={"order_id": "A123", "user_id": "U456"})配合带%(order_id)s的Formatter,这些字段就会出现在日志里。这样一条日志就能还原出完整的业务上下文,比干巴巴一句"处理失败"有用得多。
6.3 别让日志成为负担
最后说个反向的经验:日志不是越多越好。我接手过一个项目,每个函数进出都打日志,一个请求产生几百条日志,查问题时翻得眼花。好的日志应该像好的注释——只在关键决策点、状态变化点、异常点出现。判断标准很简单:这条日志在出问题时,能不能帮你缩小排查范围?不能的话,删掉。
我在实际项目里形成的习惯是:INFO级别只记录"业务里程碑",比如任务开始、任务完成、关键分支选择;DEBUG级别记录"过程细节",开发时开着,生产关掉;WARNING和ERROR严格按前面说的场景用。这样一套下来,日志量可控,出问题时翻起来也快。日志系统的价值不在于记录了多少,而在于需要的时候能不能快速找到那一条。