今天分享一个Python logging模块“小陷阱”，问题在Python2和3中都存在，先看“问题”代码：
文件main.py, 它希望日志都写入my.log, 且只写到my.log，不期望日志打印到控制台（stderr）
#main.py#coding: utf-8import logging.configimport foo# 配置日志，只输出到 my.log 文件logging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': True, 'handlers': { 'default': { 'class': 'logging.handlers.RotatingFileHandler', 'filename': 'my.log', }, }, 'loggers': { 'my': { 'level': 'INFO', 'handlers': ['default'], }, },})logger = logging.getLogger('my')logger.info('message 01 (预期只在 my.log 中)')# 调用一个外部模块的函数foo.bar()logger.info('message 02 (预期只在 my.log 中)')
foo.py是被main.py调用的库
#foo.pyimport loggingdef bar(): logging.debug('bar')
运行main.py的结果是：message 01 和 message 02 都按预期记录到my.log，但 message 02 还打印到控制台了，这一点不符合预期。
“罪魁祸首”是foo.py中的那行logging.debug。
在Python的logging模块中，如果直接调用 logging.info、logging.debug 等函数，它实际上是在根日志记录器（Root Logger）上进行操作。该模块有一个“贴心”但有时会带来麻烦的设计：当它发现根日志记录器没有任何配置好的处理器（Handler）时，它会自动调用 logging.basicConfig()来进行一次默认配置。
def debug(msg, *args, **kwargs): """ Log a message with severity 'DEBUG' on the root logger. """ if len(root.handlers) == 0: basicConfig() root.debug(msg, *args, **kwargs)
上面就是logging.debug的源代码。basicConfig()的默认行为就是添加一个 StreamHandler，也就是将日志输出到控制台。
梳理以下完整流程：
1. main.py启动，配置了名为 my 的 logger，但没有配置根 logger
2. logger.info('message 01')被调用，日志通过my logger 的处理器写入文件
3. foo.bar() 函数被调用，执行 logging.debug()。logging模块检查根 logger，发现它没有日志处理器
4. logging自动调用 basicConfig()，为根 logger 添加了一个控制台处理器
5. logger.info('message 02') 再次被调用。日志首先被写入文件。然后，因为所有 logger 默认都有一个 propagate = True 的属性，这条日志消息会向上传播到它的父级——也就是根 logger
6. 此时根 logger 已经有了一个控制台处理器，于是它愉快地把这条消息也打印到了屏幕上
以上是原因分析，以下是改进方案：
方案1，设置 my logger的propagate属性为False
'loggers': { 'my': { 'level': 'INFO', 'handlers': ['default'], 'propagate': False, }, },
这个方案不够完美，因为foo.bar函数万一是写的warning及以上级别日志时会打到stderr
方案2，设置root logger, 所有root logger都不显示
logging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': True, 'handlers': { 'default': { 'class': 'logging.handlers.RotatingFileHandler', 'filename': 'my.log', }, 'null': { 'class': 'logging.NullHandler', }, }, 'loggers': { '': { 'handlers': ['null'], }, 'my': { 'level': 'INFO', 'handlers': ['default'], }, },})
方案3，期待root logger的错误也出现在my.log中
'loggers': { '': { 'level': 'ERROR', 'handlers': ['default'], }, 'my': { 'level': 'INFO', 'handlers': ['default'], 'propagate': False, }, },
方案4，修改foo.py将logging换成logger
import loggingmodule_logger = logging.getLogger(__name__)def bar(): module_logger.debug('bar')
同时main.py中这里也需要修改一下，
logging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': False, 'handlers': { 'default': { 'class': 'logging.handlers.RotatingFileHandler', 'filename': 'my.log', }, }, 'loggers': { '': { 'level': 'INFO', 'handlers': ['default'], }, }})
注意disable_existing_loggers设置为False了，因为：import foo时module_logger = logging.getLogger(__name__)会被执行。这会创建一个名为 foo 的 logger。这个动作发生在你的日志配置代码logging.config.dictConfig 执行之前。dictConfig 函数有一个默认行为：它会禁用掉所有在配置执行前已经存在的logger。所以设置 disable_existing_loggers: False，以防止它禁用掉已经存在的 logger。
