Python导入库中Logger设置顺序导致trace_id缺失问题咨询

问题现象 #

自定义了自动注入trace_id字段的CustomLogger类，当先执行logging.setLoggerClass(CustomLogger)再导入日志模块时，日志能正常输出带trace_id的内容；但先导入日志模块再设置Logger类，就会触发KeyError: 'trace_id'错误。

代码结构 #

my_library/
  __init__.py
  folder1/
    __init__.py
    helper.py

helper.py代码 #

import logging

logger = logging.getLogger(__name__)
def helper():
    logger.info('LOG IN HELPER')

主程序program.py代码 #

import logging

trace_id = 1

class CustomLogger(logging.Logger):

    def _log(self, level, msg, args, exc_info=None, extra=None):
        extra = {'trace_id': trace_id}
        super(CustomLogger, self)._log(level, msg, args, exc_info, extra)


logger = logging.getLogger(__name__)

def config_logger():
    helper_logger = logging.getLogger("folder1")

    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s - %(trace_id)s')

    handler = logging.StreamHandler()
    handler.setFormatter(formatter)
    handler.setLevel(logging.INFO)
    helper_logger.addHandler(handler)
    helper_logger.setLevel(logging.INFO)

def program():
    logger.info('main start')

    # <--- 先导入再设置Logger类的错误写法 ---> #
    from folder1.helper import helper
    logging.setLoggerClass(CustomLogger)

    config_logger()
    helper()
    global trace_id
    trace_id += 1
    helper()
    logging.setLoggerClass(logging.Logger)
    logger.info('main end')

test_program.py代码 #

import logging
import program

logger = logging.getLogger(__name__)

class TestProgram:

    def test_helper(self):
        logger.info('LOG IN TEST')
        program.program()

错误输出详情 #

-------------------------------- live log call ---------------------------------
INFO     test_program:test_program.py:9 LOG IN TEST
INFO     program:program.py:30 main start
--- Logging error ---
Traceback (most recent call last):
  File "/opt/bb/lib/python3.8/logging/__init__.py", line 435, in format
    return self._format(record)
  File "/opt/bb/lib/python3.8/logging/__init__.py", line 431, in _format
    return self._fmt % record.__dict__
KeyError: 'trace_id'
...（后续错误栈省略）

原因分析 #

问题根源在于Python logging模块的Logger实例创建机制：

• logging.getLogger(__name__)会返回已存在的Logger实例，若不存在则用当前全局设置的Logger类创建新实例。
• 先导入helper.py时，模块内的logger = logging.getLogger(__name__)会立刻创建一个默认logging.Logger类的实例，后续调用logging.setLoggerClass(CustomLogger)只会影响新创建的Logger实例，不会修改已存在的实例类型。
• 这个默认Logger实例的_log方法不会自动注入trace_id字段，但配置的Formatter强制要求输出%(trace_id)s，因此格式化日志时会触发KeyError。

解决方案 #

方案1：调整导入顺序（最简单） #

确保在导入任何会创建Logger实例的模块之前，先设置自定义Logger类：

def program():
    logger.info('main start')

    # 先设置Logger类，再导入模块
    logging.setLoggerClass(CustomLogger)
    from folder1.helper import helper

    config_logger()
    helper()
    global trace_id
    trace_id += 1
    helper()
    logging.setLoggerClass(logging.Logger)
    logger.info('main end')

方案2：动态替换已存在的Logger实例类型 #

如果无法调整导入顺序，可以手动修改已创建的Logger实例的类属性：

def program():
    logger.info('main start')

    from folder1.helper import helper
    logging.setLoggerClass(CustomLogger)
    
    # 替换已存在的folder1模块Logger实例的类
    helper_logger = logging.getLogger("folder1")
    helper_logger.__class__ = CustomLogger

    config_logger()
    helper()
    global trace_id
    trace_id += 1
    helper()
    logging.setLoggerClass(logging.Logger)
    logger.info('main end')

方案3：使用日志过滤器注入trace_id（更优雅） #

不修改Logger类，通过过滤器自动给日志Record添加trace_id字段，不受Logger实例创建时机影响：

import logging

trace_id = 1

class TraceIdFilter(logging.Filter):
    def filter(self, record):
        record.trace_id = trace_id
        return True

logger = logging.getLogger(__name__)

def config_logger():
    helper_logger = logging.getLogger("folder1")
    
    # 添加trace_id过滤器
    helper_logger.addFilter(TraceIdFilter())

    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s - %(trace_id)s')
    handler = logging.StreamHandler()
    handler.setFormatter(formatter)
    handler.setLevel(logging.INFO)
    helper_logger.addHandler(handler)
    helper_logger.setLevel(logging.INFO)

# 后续program函数无需修改Logger类，直接导入模块即可

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