python logging 模块配置咋不起作用了？

觉得太长？直接跳到结论部分试试！

1. 问题描述

日志可以说是所有程序都必不可少的组成部分，可是在有一天当笔者在程序入口写下如下代码时候，竟然不生效！？日志并不能如预想的一样，输出到 log_file_name 中

代码片段 1: 调用

...
01 logging.basicConfig(
02     level=logging.INFO,
03     handlers=[
04         logging.StreamHandler(),
05         TimedRotatingFileHandler(log_file_name, when='midnight', backupCount=7)
06     ],
07     format='%(asctime)s(%(process)d) %(filename)s > %(funcName)s > line %(lineno)d: %(levelname)s: %(message)s'
08  )
...

2. 问题分析

反复检查这段代码无误后，只能深入 logging.basicConfig 函数看看这个 python 自带的日志配置函数究竟做了什么（截取一部分）

代码片段 2: `logging.basicConfig` 源码，位于 `logging.__init__.py`

01  def basicConfig(**kwargs):
       ...
02     if len(root.handlers) == 0:
03         handlers = kwargs.pop("handlers", None)
           ...
04         if handlers is None:
05             filename = kwargs.pop("filename", None)
06             mode = kwargs.pop("filemode", 'a')
07             if filename:
08                 h = FileHandler(filename, mode)
09             else:
10                 stream = kwargs.pop("stream", None)
11                 h = StreamHandler(stream)
12             handlers = [h]
       ...
13          for h in handlers:
14              if h.formatter is None:
15                  h.setFormatter(fmt)
16              root.addHandler(h)

分析这段程序，02 行如果 root.handlers 为空，则会运行到 13~16 行给将每个 handler 添加到根 logger 的逻辑。所以真相只有一个，就是 root.handlers 不为空！

但是经过简单查看相关源码就会发现， root.handlers 在初始化的时候是一个空的列表，难道在我们代码的其他地方重复调用了 logging.basicConfig 方法？

经过全局搜索，确定只配置了一次日志，再次陷入僵局…

无奈，只能在 “代码片段 2” 第 02 行处打断点调试，想看看到底调用了几次该方法。神奇的事情发生了，果然调用了两次！符合猜想

那如果不是我自己代码调用的，是哪里调用的呢？利用 ide 的调用方查看功能，

诶？竟然是 logging.__init__.py 自己调用的？其中一处代码如下：

代码片段 3

...
01  def info(msg, *args, **kwargs):
02      """
03      Log a message with severity 'INFO' on the root logger. If the logger has
04      no handlers, call basicConfig() to add a console handler with a pre-defined
05      format.
06      """
07      if len(root.handlers) == 0:
08          basicConfig()
09      root.info(msg, *args, **kwargs)
...

原来是在调用 logging.info 方法时，如果还没有配置过日志，就会调用一次 logging.basicConfig 方法。

忽然想起自己在一个文件中，有一个预加载系统资源的功能，这个功能是直接在函数外面的，并且加载成功将打印日志。而我们知道，python 脚本的执行顺序是，如果你 import 了另一个文件，就会直接跳转到该文件，并将另一个文件执行完成，再跳转回来。也就是说，另一个文件中函数外的游离日志输出语句会优先于 main 的执行！造成了这次的问题。

想更直观的理解问题的原因，可以参考下图：

注：图中步骤 3 并不是真的直接返回了 main.py，而是会顺序执行下方的两个函数定义和一个类定义，这全部执行完成之后才会返回 main.py 继续执行；同理步骤 4 也是一样，会执行完中间的各种定以后，才执行 main 方法.

3. 修复

知道了问题想要修复也很简单，一种方案是只需要在 “代码片段 1” 前面加上如下语句即可

01  # 清理已有 handlers
02  root_logger = logging.getLogger()
03  for h in root_logger.handlers:
04      root_logger.removeHandler(h)

这样，在执行 “代码片段 2” 第 02 行就就进入正常的逻辑

另一种方案是，将游离于函数的语句放在一个函数中，在配置完日之后再调用该函数

结论

问题原因：游离的日志输出语句（如 logging.info）提前触发了日志配置方法，使得logging.basicConfig 函数失效

解决方法：

• 方案1：在调用 logging.basicConfig 方法前清除已有 handles
• 方案2：通过合理方式组织和调用原有游离日志输出语句，将其执行进行延迟