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设成DEBUGhandler忘了改默认是NOTSET等于0全放行结果正常但反过来logger设INFO、handler设DEBUGDEBUG日志在logger那关就被拦了根本到不了handler。两道关卡是与的关系取更严格的那个。2.3 Formatter日志长什么样Formatter决定每条日志的最终文本格式。它用%风格的占位符常用的字段我整理成表占位符含义示例输出%(asctime)s时间2024-01-15 10:30:45,123%(levelname)s级别名INFO%(name)slogger名myapp.database%(message)s日志内容连接成功%(lineno)d行号42%(funcName)s函数名connect%(process)d进程ID12345%(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默认WARNINGINFO被拦了。很多人第一次用getLogger就卡在这以为模块坏了。其实要么给logger设级别要么调basicConfig把root级别降下来。4. 从零搭建一套可用的日志配置理论讲完上实操。我按开发环境和生产环境两套配置来讲这是最实用的分法。4.1 开发环境控制台输出就够了开发时最省事的是basicConfig一行搞定import logging logging.basicConfig( levellogging.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, maxBytes10 * 1024 * 1024, # 10MB backupCount5, encodingutf-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有但propagateFalse日志也出不来。basicConfig被抢先调用别的库先调了basicConfig你的配置就不生效了。我做过一个排查清单表出问题时对着过一遍现象最可能原因快速验证完全没输出logger无handler且不传播打印logger.handlers部分级别没输出级别设置过高打印logger.getEffectiveLevel()日志重复传播导致多次处理检查propagate和各级handler格式不对Formatter没设或设错检查handler.formatter文件没内容文件handler级别过高检查handler.level5.2 多进程写同一文件的灾难RotatingFileHandler在多进程下会出大问题。多个进程同时切割文件会导致日志丢失甚至文件损坏。我吃过这个亏一个多进程任务日志文件时不时少一大段。解决方案有三个一是每个进程写自己的文件文件名带进程ID二是用QueueHandler把日志集中到一个进程写三是用支持多进程的第三方handler。最省事的是第一种import os from logging.handlers import RotatingFileHandler pid os.getpid() handler RotatingFileHandler(fapp_{pid}.log, maxBytes10485760, backupCount3)5.3 异常信息别只打str(e)捕获异常时logging.error(str(e))只拿到异常消息丢了堆栈。排查时没有堆栈等于没有线索。正确姿势是用exc_infoTruetry: risky_operation() except Exception: logging.error(操作失败, exc_infoTrue) # 或者用 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_asciiFalse)结构化日志的好处是你可以按字段过滤、聚合、统计比如统计过去一小时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严格按前面说的场景用。这样一套下来日志量可控出问题时翻起来也快。日志系统的价值不在于记录了多少而在于需要的时候能不能快速找到那一条。