Python多模块调用logging模块导致日志重复输出的原因与解决

Python多模块日志配置问题背景

Python内置的logging模块提供了通用的日志记录功能，其基本用法相对直观，此处不再赘述。本文将重点探讨在涉及多个Python文件相互调用的场景中，若各模块配置了不同的logging策略，可能会引发令人困惑的日志行为。

以下结合开发过程中遇到的实际案例进行说明：

假设存在三个Python模块A、B和C。主模块A导入并调用模块B和C，且A自身配置了特定的logging机制。

模块A配置logging的方式如下：

import logging
import logging.handlers
def CreateLogger(logFile = 'batch'):
  handler = logging.handlers.RotatingFileHandler(str(logFile) + '.LOG', maxBytes = 1024 * 1024 * 500, backupCount = 5)
  fmt = '%(asctime)s - %(filename)s:%(lineno)s - %(name)s - %(message)s'
  formatter = logging.Formatter(fmt)
  handler.setFormatter(formatter)
  logger = logging.getLogger(str(logFile))
  logger.addHandler(handler)
  logger.setLevel(logging.INFO)
  return logger
sLogger = CreateLogger()

模块A采用标准的logging配置方法：创建一个RotatingFileHandler实例，通过该处理器控制日志文件的轮转策略，包括保留的日志文件数量及单个日志文件的最大大小限制。同时，创建一个Formatter对象以定义日志输出的格式。使用该配置生成的logger对象记录日志时，所有日志均会正确写入指定的日志文件中。

模块B配置logging的方式如下：

def GetLogger(testName):
  logger = logging.getLogger(testName)
  logger.setLevel(logging.INFO)
  hdlr = logging.FileHandler(testName + '.LOG')
  hdlr.setLevel(logging.INFO)
  formatter = logging.Formatter("[%(asctime)s]\t[%(levelname)s]\t[%(thread)d]\t[%(pathname)s:%(lineno)d]\t%(message)s")
  hdlr.setFormatter(formatter)
  logger.addHandler(hdlr)
  return logger
logger = GetLogger('OK')
 
def SetLogger(log):
  global logger
  logger = log

模块B默认的logging配置与A类似，区别在于B倾向于将日志写入独立的日志文件。在实际调用B模块的函数或类时，A并未直接使用B内置的logging方式，而是通过SetLogger函数对B的日志记录器进行了重定向。具体而言，A将自身已配置好的logger对象传递给B，使B与A共享同一个logger实例，从而将日志统一输出到A指定的文件中。这种在主模块调用多个子模块且各子模块拥有独立logging逻辑的场景下，有助于统一控制总日志文件的大小和数量。

日志重复输出的现象与排查

然而，当引入模块C后，发现A程序运行过程中，A和B模块的日志信息不仅写入文件，还直接打印到了屏幕上，且日志文件中同样存在对应记录。这一现象令人困惑：即使注释掉对B模块的调用，A的日志依然会输出到屏幕；但若仅保留A中配置logging对象的代码而移除其他部分，系统运行则完全正常。

基于上述现象，初步推测模块C中存在某种设置，改变了A和B模块的日志输出行为。进一步排查发现，模块C并未配置特定的logger对象，而是直接调用了logging.info()记录日志。注释掉这部分逻辑后，A和B的日志输出恢复正常，不再向屏幕打印日志。

Logger树形结构与Root Logger机制

通过查阅Python logging模块的源码，发现了一些关键机制：

1. Logger对象构成树形结构，每个创建的logger都是root logger的子节点。调用getLogger(name=None)时，若name为None，则创建root logger；若name包含点号（如'a.b.c'），则会创建c、b、a三个logger对象，层级关系为c->b->a->root。其中root为根节点，a、b、c依次为其子节点，依此类推。

2. root节点是全局共享的。尽管涉及多个模块，它们共同使用同一个root logger实例。

3. 日志消息会向上传递至父级logger。在c->b->a->root的结构中，一条日志会被记录4次，依次经过c、b、a和root处理。

有人可能会质疑：若按A或B的方式初始化logger，该logger也是root的子节点，而root默认会将日志输出到屏幕，那么正常情况下日志应同时出现在文件和屏幕中。为何实际仅见文件日志，屏幕无输出？

若对这一过程保持好奇并深入探究，将有助于获得更深刻的理解。

Root Logger失效原因分析

因此，核心困惑在于：为何调用A模块产生的sLogger.info()输出的日志仅存在于文件中，而root logger未向屏幕输出？即root logger为何失效？查看logging __init__.py源码可知，root logger的info方法实现如下：

def info(msg, *args, **kwargs):
  """
  Log a message with severity 'INFO' on the root logger.
  """
  if len(root.handlers) == 0:
    basicConfig()
  root.info(msg, *args, **kwargs)

上述代码涉及root.handlers属性，怀疑其与日志输出方式相关。执行print len(root.handlers)结果为0。这意味着默认情况下root logger的handlers列表为空，导致sLogger记录日志时，root logger不会执行任何输出操作。在__main__中添加以下代码进行验证：

if __name__ == '__main__':
 
  sLogger.info('OK')
 
  print len(logging.root.handlers), logging.root.handlers
 
  logging.info('Bad')
 
  print len(logging.root.handlers), logging.root.handlers

运行程序，得到如下结果：

0 []

1 [<logging.StreamHandler instance at 0x7f066e3eef80>]

第一行输出'0 []'解释了为何正常情况下root logger未输出日志。

调用logging.info('Bad')后，root.handlers变为StreamHandler对象。该程序展示了调用logging.info前后root logger对象状态的变化。

还需验证调用logging前后正常模块的日志行为。

在__main__中编写如下代码：

if __name__ == '__main__':
 
  for i in xrange(0, 2):
 
    sLogger.info('OK')
 
    logging.info('Bad')

根据前述分析，首次调用sLogger.info('OK')不会输出日志，而logging.info因未达WARNING级别也未输出；第二次调用则会向屏幕输出日志。因此，预期结果为日志文件中包含三条日志，屏幕上显示一条'INFO:batch:OK'。这与之前的推测一致。

basicConfig触发机制与解决方案

为何调用logging.info后会发生这种转变？

继续查看上述root logger的info方法，并对照basicConfig代码。注意到当len(root.handlers) == 0时会调用basicConfig，此时需关注basicConfig的具体实现。

def basicConfig(**kwargs): 
 
  if len(root.handlers) == 0:
 
    filename = kwargs.get("filename")
 
    if filename:
 
      mode = kwargs.get("filemode", 'a')
 
      hdlr = FileHandler(filename, mode)
 
    else:
 
      stream = kwargs.get("stream")
 
      hdlr = StreamHandler(stream)
 
    fs = kwargs.get("format", BASIC_FORMAT)
 
    dfs = kwargs.get("datefmt", None)
 
    fmt = Formatter(fs, dfs)
 
    hdlr.setFormatter(fmt)
 
    root.addHandler(hdlr)
 
    level = kwargs.get("level")
 
    if level is not None:
 
      root.setLevel(level)

可以看出，当root.handlers长度为0时，会创建一个默认的StreamHandler对象，该处理器的配置导致日志输出至屏幕。这与之前打印logging.root.handlers的结果相符。由此可明白，为何C文件中直接调用logging.info会影响上层模块及其子模块的日志行为。

基于上述问题及logging相关部分的分析，对logging模块的理解应更为深入。最关键的一点是，若需精确控制日志输出方式，务必注意主模块及子模块中不要直接调用logging基础函数（如logging.info）。

关于多个Python文件调用logging模块产生错误的更多问题，请查看相关链接