Python重写第三方库logging的Info/Warn方法仅部分生效如何解决

我是Python新手（具备.Net开发背景），目前正在开发一款作为第三方库封装层的Python应用。该第三方Python库使用标准logging模块实现日志能力，我需要拦截这些日志调用并存储日志内容，相关代码如下：

第三方库主文件 — myApp.py #

# Standard Library
import logging

from options import (info, warn)
from process import (processIt)

# Module-level logger
log = logging.getLogger(__name__)
log.propagate = False

formatter = logging.Formatter("[%(name)s] [%(levelname)-7s] [%(asctime)s] %(message)s")

# Console Handler for Elevator messages
ch = logging.StreamHandler()
ch.setFormatter(formatter)
log.addHandler(ch)


def runIt():
        info("Running it.", 1)
        processIt()
        info("Running it.", 2)

第三方库日志配置 — options.py #

# Standard Library
import logging

formatter = logging.Formatter("[%(name)s] [%(ecode)d] [%(levelname)-7s] [%(asctime)s] %(message)s")

# Console Handler for Elevator messages
ch = logging.StreamHandler()
ch.setFormatter(formatter)

# Module-level logger
log = logging.getLogger(__name__)
log.level= logging.INFO
# temporary? hack to prevent multiple loggers from printing messages
log.propagate = False
log.addHandler(ch)


def info(fmt, ecode, *args):
    log.info(fmt, *args, extra={'ecode': ecode})


def warn(fmt, ecode, *args):
    log.warning(fmt, *args, extra={'ecode': ecode})


def init():    
    info("Initialized options", 100)

第三方库处理逻辑 — process.py #

from options import (info, warn)


def processIt():
  info ("Inside Process", 10)

客户端代码 — client.py #

import options
import myApp

info_msg = []
warn_msg = []


def info(fmt, ecode, *args):
    info_msg.append(dict({ecode:fmt.format(*args)}))


def warn(fmt, ecode, *args):
    warn_msg.append(dict({ecode:fmt.format(*args)}))

options.warn = warn
options.info = info


def runApp():  
  print ("Start")
  options.init()
  myApp.runIt()
  print ("End")
  print (info_msg)
  print (warn_msg)


runApp()

运行结果 #

运行代码得到如下输出：

Start
[options] [1] [INFO   ] [2022-06-09 09:28:46,380] Running it.
[options] [10] [INFO   ] [2022-06-09 09:28:46,380] Inside Process
[options] [2] [INFO   ] [2022-06-09 09:28:46,380] Running it.
End
[{100: 'Initialized options'}]
[]

问题描述 #

从运行结果可以看到，仅options.init()方法内的日志调用被成功重写拦截，其余位置调用info、warn方法产生的日志均未被自定义方法捕获，仍直接输出到控制台，请问该问题的产生原因是什么，该如何解决？

Python的from xxx import yyy属于导入时绑定机制：

• 当myApp.py、process.py执行from options import (info, warn)时，会把options模块里当时的info、warn函数引用直接绑定到自身模块的全局命名空间
• 后续修改options.info、options.warn的指向时，已经导入到其他模块的旧函数引用不会同步更新
• options.init()是在options模块内部调用自身命名空间的info，替换后它调用的是新函数，所以能被拦截
• myApp.runIt()、process.processIt()调用的是自身模块里提前绑定的旧info/warn（也就是原来写日志到控制台的函数），所以不会走自定义逻辑，日志还是直接输出到控制台

额外需要注意：第三方库的logger都设置了propagate = False，还提前绑定了StreamHandler，就算替换函数成功，原logger的handler如果不清理也可能出现重复输出日志的问题。

不要用猴子补丁替换模块函数的方式拦截日志，直接利用Python标准logging模块本身的机制实现拦截，更稳定也不需要改第三方库的导入逻辑：

• 移除替换options.info/options.warn的猴子补丁代码
• 清理第三方库所有logger提前绑定的控制台StreamHandler，避免日志直接输出到控制台
• 给对应logger添加自定义的Handler，把日志内容写入定义的info_msg/warn_msg列表即可

修正后的client.py代码示例：

import logging
import options
import myApp

info_msg = []
warn_msg = []

# 自定义日志收集处理器
class ListHandler(logging.Handler):
    def emit(self, record):
        log_entry = {record.ecode: record.getMessage()}
        if record.levelno == logging.INFO:
            info_msg.append(log_entry)
        elif record.levelno == logging.WARNING:
            warn_msg.append(log_entry)

# 统一处理所有相关logger
target_loggers = [
    logging.getLogger('options'),
    logging.getLogger('myApp'),
    logging.getLogger('process')
]
custom_handler = ListHandler()
for logger in target_loggers:
    logger.propagate = False
    # 清空原有控制台输出handler
    logger.handlers.clear()
    # 添加自定义收集handler
    logger.addHandler(custom_handler)
    logger.setLevel(logging.INFO)


def runApp():  
  print ("Start")
  options.init()
  myApp.runIt()
  print ("End")
  print (info_msg)
  print (warn_msg)


runApp()

运行后所有日志都会被正常收集，控制台不会输出第三方库的原始日志：

Start
End
[{100: 'Initialized options'}, {1: 'Running it.'}, {10: 'Inside Process'}, {2: 'Running it.'}]
[]

如果一定要用猴子补丁的方式实现，需要在导入myApp、process模块之前就替换掉options模块的info和warn函数，这样两个模块导入时拿到的就是替换后的函数引用，但这种方式侵入性强、兼容性差，不推荐使用。

内容的提问来源于stack exchange，提问作者Roger