Python自定义日志级别为何无法显示正确的%(filename)s文件名？

问题描述 #

已为日志模块新增VERBOSE自定义日志级别，功能正常，但日志中携带的文件名始终显示日志模块名称（如log.py），而非触发日志的业务模块名称（如test_module.py）。

当前日志输出：

Feb 4 16:54:31 VERBOSE log.py:88 : Some verbose log message

期望日志输出：

Feb 4 16:54:31 VERBOSE test_module.py:35 : Some verbose log message

原因分析 #

问题出在自定义verbose方法的实现上：

• 原代码用lambda直接调用logger.log，此时日志系统会把lambda所在的日志模块栈帧作为日志来源，而非调用verbose的业务模块栈帧。
• 标准日志方法（如logger.debug()、logger.info()）内部会自动调整栈帧深度，确保获取正确的调用方信息，但自定义方法需要手动处理。

解决方案 #

修改自定义verbose方法，调用logger.log时指定stacklevel=2（Python 3.8及以上版本支持），让日志系统跳过当前方法的栈帧，直接获取业务模块的调用信息。

修改后的完整代码 #

class _CustomRotatingFileHandler(logging.handlers.RotatingFileHandler):
    def __init__(self, *args, **kwargs):
        prev_umask = os.umask(0o000)
        super().__init__(*args, **kwargs)
        os.umask(prev_umask)

    def doRollover(self):
        prev_umask = os.umask(0o000)
        super().doRollover()
        os.umask(prev_umask)

def setup_logging():
    reference = 'my_project'
    date_fmt = '%(asctime)s %(levelname)s %(filename)s:%(lineno)d' \
               ' : %(message)s'

    # 定义VERBOSE日志级别（介于INFO和DEBUG之间）
    log_level_verbose = 15

    logging.addLevelName(log_level_verbose, 'VERBOSE')
    logger = logging.getLogger(reference)
    logger.setLevel(logging.DEBUG)

    # 替换原lambda，定义带栈帧调整的verbose方法
    def verbose(self, msg, *args, **kwargs):
        self.log(log_level_verbose, msg, *args, stacklevel=2, **kwargs)
    
    setattr(logger, 'verbose', verbose.__get__(logger, type(logger)))

    file_handler = _CustomRotatingFileHandler(
        log_file, maxBytes=10485760, backupCount=3
    )

    file_log_format = logging.Formatter(date_fmt, "%b %e %H:%M:%S")
    file_handler.setFormatter(file_log_format)
    file_handler.setLevel(log_level_verbose)

    console_handler = logging.StreamHandler(sys.stdout)
    console_log_format = logging.Formatter("%(message)s")
    console_handler.setFormatter(console_log_format)
    console_handler.setLevel(logging.INFO)

    logger.handlers = [file_handler, console_handler]
    return logger

关键修改说明 #

• 用自定义函数替换lambda实现verbose方法，添加stacklevel=2参数，让日志系统跳过当前verbose方法的栈帧，直接读取业务模块的调用信息。
• 通过__get__方法将函数绑定为logger实例的方法，保证调用时self指向正确的日志对象。

低版本Python兼容方案（Python <3.8） #

如果使用Python 3.8以下版本，stacklevel参数不可用，可通过inspect模块手动调整栈帧：

import inspect

def verbose(self, msg, *args, **kwargs):
    frame = inspect.currentframe().f_back
    try:
        # 手动传入调用方的文件名和行号
        extra = {
            'filename': inspect.getframeinfo(frame).filename.split('/')[-1],
            'lineno': frame.f_lineno
        }
        self.log(log_level_verbose, msg, *args, extra=extra, **kwargs)
    finally:
        # 手动删除帧引用，避免内存泄漏
        del frame

注意：此方案需要确保日志格式中的%(filename)s和%(lineno)d能读取到extra中的自定义字段，不如stacklevel方案简洁，建议优先升级Python版本使用官方标准方案。

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