原来这才是 Python logging 模块的正确使用姿势进阶高级开发必看logging 模块的核心设计配置中的 class 字段全项目一个 logger 错在哪推荐的写法配置驱动两种日志组织方式都是合理的配置驱动的写法为什么 propagate 要设为 False全项目一个 logger 的正确改法常见坑1. 重复 handler2. level 继承的坑3. 多进程写入同一个文件4. 性能问题总结最近在参与我司的一个新项目的时候让我负责配置可观测性相关的基础代码看到其他同事的第一版代码搞了个全项目一起使用的 logger 变量在所有项目代码内统一引入进行统一的打印突然感觉十分难受。# 同事的第一版代码loggerlogging.getLogger(app)# 所有模块都引用这个全局 loggerfromutilsimportlogger logger.info(xxx)这种写法让我产生了强烈的生理不适——日志真的应该是这么打的吗于是研究了一下 Python logging 的最佳实践结果发现了新大陆。logging 模块的核心设计在说最佳实践之前先聊聊 logging 模块是怎么设计的。理解了这个才能理解为什么很多常见用法其实是错误的。logging 模块有五个核心组件111*1*Loggername: strlevel: inthandlers: List[Handler]propagate: booldebug(msg)info(msg)warning(msg)error(msg)Handlerlevel: intformatter: Formatteremit(record)Formatterfmt: strdatefmt: strformat(record)Filterfilter(record)LogRecordname: strlevel: intmessage: strcreated: float日志的流转过程是这样的Handler flowLogger flow否是是否否是否是否是是否是否用户代码中的日志调用例如logger.info(...)logger 是否对本次调用 level 启用创建 LogRecord挂载在 logger 上的 filter 是否拒绝该 record将 record 传递给当前 logger 的 handlers当前 logger 的 propagate 是否为 true是否存在 parent logger将当前 logger 设为 parent logger停止层级结构中是否至少有一个 handler使用 lastResort handlerrecord 被传递给 handlerhandler 是否对该 record 的 level 启用挂载在 handler 上的 filter 是否拒绝该 recordemit包含 formatting停止关键点Logger 有层级结构root 是最顶层app.user是app的子 loggerapp.user.auth又是app.user的子 logger默认传播机制子 logger 的日志默认传播到父 loggerpropagateTrueLogger 继承父 logger 的 level如果子 logger 没有设置 level会从父 logger 继承配置中的 class 字段在 YAML 配置中class字段指定 Handler 的类参数会传给构造函数handlers:console:class:logging.StreamHandlerlevel:INFOformatter:simplestream:ext://sys.stdout# 参数传给构造函数这里的ext://sys.stdout是 logging 配置的特殊语法表示引用标准输出流。全项目一个 logger 错在哪先看看常见的全项目一个 logger是怎么写的# utils.pyimportlogging loggerlogging.getLogger(app)# user_service.pyfromutilsimportlogger logger.info(用户登录)# 来自同一个 logger# order_service.pyfromutilsimportlogger logger.info(创建订单)# 还是同一个 logger这种写法的问题是日志没有区分来源。当你想只看user_service的日志时没办法过滤。你只能看到所有模块混在一起的日志。耦合问题。所有模块都依赖utils.py模块间的依赖关系变得混乱。推荐的写法配置驱动两种日志组织方式都是合理的实际上logging 的最佳实践有两种常见的组织方式没有绝对优劣按需选择即可方式写法特点每模块独立 loggerlogger logging.getLogger(__name__)无脑方便利用默认传播机制配置简单子系统级别 loggerlogger logging.getLogger(app.user)按业务分组控制灵活但需要额外设计每模块独立 logger的好处由于 logger 默认传播和继承父 logger只要配置顶级 loggerapp就能控制所有子 logger配置并不复杂。很多项目比如 Flask、Django默认就是这么用的。子系统级别 logger的好处按业务领域分组控制很方便比如可以把app.user的日志单独输出到用户相关日志文件。但代码需要额外的设计和维护。业界现状常用库里两种用法都有。比如 uvicorn 用的是子系统级别而很多小型项目直接用每模块独立 logger。没有一定之规按需选择即可。配置驱动的写法# logging.yamlversion:1disable_existing_loggers:falseformatters:default:format:%(asctime)s - %(name)s - %(levelname)s - %(message)sdetailed:format:%(asctime)s - %(name)s - %(levelname)s - [%(filename)s:%(lineno)d] - %(message)shandlers:console:class:logging.StreamHandlerlevel:INFOformatter:defaultfile:class:logging.handlers.RotatingFileHandlerlevel:DEBUGformatter:detailedfilename:app.logmaxBytes:10485760# 10MBbackupCount:5loggers:app:# 顶级 loggerlevel:DEBUGhandlers:[console,file]propagate:false# 配置了 handler 后建议设为 Falseapp.user:level:DEBUGhandlers:[file]propagate:falseroot:level:WARNINGhandlers:[console]加载配置importlogging.configimportyamlwithopen(logging.yaml,r)asf:configyaml.safe_load(f)logging.config.dictConfig(config)为什么 propagate 要设为 False当一个 logger 配置了 handler 后建议把propagate设为False。否则会出现重复日志# 如果 propagateTrue默认app.info(msg)# 会打印两次# 第一次app 的 handler 打印# 第二次root 的 handler 打印因为传播到 root 了全项目一个 logger 的正确改法回到开头的问题正确的做法是每个模块用自己的 logger# utils.pyimportlogging loggerlogging.getLogger(__name__)logger.info(utils loaded)# user_service.pyimportlogging loggerlogging.getLogger(__name__)# user_servicelogger.info(用户登录)# order_service.pyimportlogging loggerlogging.getLogger(__name__)# order_servicelogger.info(创建订单)配置起来也很简单只要配置顶级 logger 就行root:level:INFOhandlers:[console,file]所有子 loggeruser_service、order_service的日志都会自动传播到 root logger 被处理。常见坑1. 重复 handler如果父 logger 和子 logger 都配置了 handler且propagateTrue日志会打印多次。解决要么子 logger 的propagateFalse要么子 logger 不配 handler。2. level 继承的坑子 logger 没有设置 level 时会从父 logger 继承。如果父 logger 设置了levelDEBUG子 logger 默认也是 DEBUG。解决明确设置每个 logger 的 level。3. 多进程写入同一个文件使用RotatingFileHandler或TimedRotatingFileHandler时多进程写入可能导致日志损坏。解决使用ConcurrentRotatingFileHandler或日志收集服务如 Filebeat。4. 性能问题日志字符串拼接在DEBUGlevel 时也会执行即使这条日志不会被记录logger.debug(f用户数据:{long_string})# 字符串拼接总是会执行解决使用懒加载logger.debug(用户数据: %s,long_string)# 仅在 DEBUG 开启时执行拼接总结logging 模块的设计其实很优雅层级结构 传播机制 handler 解耦。全项目一个 logger 的做法是没有理解这套设计的结果。正确做法是让每个模块用自己的 logger利用默认的传播机制配置集中在根 logger。至于选择每模块独立 logger还是子系统级别 logger取决于项目规模和个人偏好。前者简单无脑后者控制灵活。没有绝对的好坏之分。关键的一点是把日志配置抽离成配置文件YAML 或 dictConfig而不是在代码里硬编码basicConfig。这样改了配置不用改代码也方便在不同环境使用不同配置。参考文档Python Logging HOWTOPython logging 模块文档 原来这才是 Python logging 模块的正确使用姿势！进阶高级开发必看
原来这才是 Python logging 模块的正确使用姿势进阶高级开发必看logging 模块的核心设计配置中的 class 字段全项目一个 logger 错在哪推荐的写法配置驱动两种日志组织方式都是合理的配置驱动的写法为什么 propagate 要设为 False全项目一个 logger 的正确改法常见坑1. 重复 handler2. level 继承的坑3. 多进程写入同一个文件4. 性能问题总结最近在参与我司的一个新项目的时候让我负责配置可观测性相关的基础代码看到其他同事的第一版代码搞了个全项目一起使用的 logger 变量在所有项目代码内统一引入进行统一的打印突然感觉十分难受。# 同事的第一版代码loggerlogging.getLogger(app)# 所有模块都引用这个全局 loggerfromutilsimportlogger logger.info(xxx)这种写法让我产生了强烈的生理不适——日志真的应该是这么打的吗于是研究了一下 Python logging 的最佳实践结果发现了新大陆。logging 模块的核心设计在说最佳实践之前先聊聊 logging 模块是怎么设计的。理解了这个才能理解为什么很多常见用法其实是错误的。logging 模块有五个核心组件111*1*Loggername: strlevel: inthandlers: List[Handler]propagate: booldebug(msg)info(msg)warning(msg)error(msg)Handlerlevel: intformatter: Formatteremit(record)Formatterfmt: strdatefmt: strformat(record)Filterfilter(record)LogRecordname: strlevel: intmessage: strcreated: float日志的流转过程是这样的Handler flowLogger flow否是是否否是否是否是是否是否用户代码中的日志调用例如logger.info(...)logger 是否对本次调用 level 启用创建 LogRecord挂载在 logger 上的 filter 是否拒绝该 record将 record 传递给当前 logger 的 handlers当前 logger 的 propagate 是否为 true是否存在 parent logger将当前 logger 设为 parent logger停止层级结构中是否至少有一个 handler使用 lastResort handlerrecord 被传递给 handlerhandler 是否对该 record 的 level 启用挂载在 handler 上的 filter 是否拒绝该 recordemit包含 formatting停止关键点Logger 有层级结构root 是最顶层app.user是app的子 loggerapp.user.auth又是app.user的子 logger默认传播机制子 logger 的日志默认传播到父 loggerpropagateTrueLogger 继承父 logger 的 level如果子 logger 没有设置 level会从父 logger 继承配置中的 class 字段在 YAML 配置中class字段指定 Handler 的类参数会传给构造函数handlers:console:class:logging.StreamHandlerlevel:INFOformatter:simplestream:ext://sys.stdout# 参数传给构造函数这里的ext://sys.stdout是 logging 配置的特殊语法表示引用标准输出流。全项目一个 logger 错在哪先看看常见的全项目一个 logger是怎么写的# utils.pyimportlogging loggerlogging.getLogger(app)# user_service.pyfromutilsimportlogger logger.info(用户登录)# 来自同一个 logger# order_service.pyfromutilsimportlogger logger.info(创建订单)# 还是同一个 logger这种写法的问题是日志没有区分来源。当你想只看user_service的日志时没办法过滤。你只能看到所有模块混在一起的日志。耦合问题。所有模块都依赖utils.py模块间的依赖关系变得混乱。推荐的写法配置驱动两种日志组织方式都是合理的实际上logging 的最佳实践有两种常见的组织方式没有绝对优劣按需选择即可方式写法特点每模块独立 loggerlogger logging.getLogger(__name__)无脑方便利用默认传播机制配置简单子系统级别 loggerlogger logging.getLogger(app.user)按业务分组控制灵活但需要额外设计每模块独立 logger的好处由于 logger 默认传播和继承父 logger只要配置顶级 loggerapp就能控制所有子 logger配置并不复杂。很多项目比如 Flask、Django默认就是这么用的。子系统级别 logger的好处按业务领域分组控制很方便比如可以把app.user的日志单独输出到用户相关日志文件。但代码需要额外的设计和维护。业界现状常用库里两种用法都有。比如 uvicorn 用的是子系统级别而很多小型项目直接用每模块独立 logger。没有一定之规按需选择即可。配置驱动的写法# logging.yamlversion:1disable_existing_loggers:falseformatters:default:format:%(asctime)s - %(name)s - %(levelname)s - %(message)sdetailed:format:%(asctime)s - %(name)s - %(levelname)s - [%(filename)s:%(lineno)d] - %(message)shandlers:console:class:logging.StreamHandlerlevel:INFOformatter:defaultfile:class:logging.handlers.RotatingFileHandlerlevel:DEBUGformatter:detailedfilename:app.logmaxBytes:10485760# 10MBbackupCount:5loggers:app:# 顶级 loggerlevel:DEBUGhandlers:[console,file]propagate:false# 配置了 handler 后建议设为 Falseapp.user:level:DEBUGhandlers:[file]propagate:falseroot:level:WARNINGhandlers:[console]加载配置importlogging.configimportyamlwithopen(logging.yaml,r)asf:configyaml.safe_load(f)logging.config.dictConfig(config)为什么 propagate 要设为 False当一个 logger 配置了 handler 后建议把propagate设为False。否则会出现重复日志# 如果 propagateTrue默认app.info(msg)# 会打印两次# 第一次app 的 handler 打印# 第二次root 的 handler 打印因为传播到 root 了全项目一个 logger 的正确改法回到开头的问题正确的做法是每个模块用自己的 logger# utils.pyimportlogging loggerlogging.getLogger(__name__)logger.info(utils loaded)# user_service.pyimportlogging loggerlogging.getLogger(__name__)# user_servicelogger.info(用户登录)# order_service.pyimportlogging loggerlogging.getLogger(__name__)# order_servicelogger.info(创建订单)配置起来也很简单只要配置顶级 logger 就行root:level:INFOhandlers:[console,file]所有子 loggeruser_service、order_service的日志都会自动传播到 root logger 被处理。常见坑1. 重复 handler如果父 logger 和子 logger 都配置了 handler且propagateTrue日志会打印多次。解决要么子 logger 的propagateFalse要么子 logger 不配 handler。2. level 继承的坑子 logger 没有设置 level 时会从父 logger 继承。如果父 logger 设置了levelDEBUG子 logger 默认也是 DEBUG。解决明确设置每个 logger 的 level。3. 多进程写入同一个文件使用RotatingFileHandler或TimedRotatingFileHandler时多进程写入可能导致日志损坏。解决使用ConcurrentRotatingFileHandler或日志收集服务如 Filebeat。4. 性能问题日志字符串拼接在DEBUGlevel 时也会执行即使这条日志不会被记录logger.debug(f用户数据:{long_string})# 字符串拼接总是会执行解决使用懒加载logger.debug(用户数据: %s,long_string)# 仅在 DEBUG 开启时执行拼接总结logging 模块的设计其实很优雅层级结构 传播机制 handler 解耦。全项目一个 logger 的做法是没有理解这套设计的结果。正确做法是让每个模块用自己的 logger利用默认的传播机制配置集中在根 logger。至于选择每模块独立 logger还是子系统级别 logger取决于项目规模和个人偏好。前者简单无脑后者控制灵活。没有绝对的好坏之分。关键的一点是把日志配置抽离成配置文件YAML 或 dictConfig而不是在代码里硬编码basicConfig。这样改了配置不用改代码也方便在不同环境使用不同配置。参考文档Python Logging HOWTOPython logging 模块文档