在 Python 记录器中覆盖 lineno 的最佳方法答案

【问题标题】：Best way to override lineno in Python logger在 Python 记录器中覆盖 lineno 的最佳方法
【发布时间】：2015-12-03 07:30:29
【问题描述】：

我编写了一个装饰器，它记录用于调用特定函数或方法的参数。如下图，除了logRecord中报告的行号是装饰器的行号而不是被包装的func的行号之外，它运行良好：

from functools import wraps
import inspect
import logging

arg_log_fmt = "{name}({arg_str})"


def log_args(logger, level=logging.DEBUG):
    """Decorator to log arguments passed to func."""
    def inner_func(func):
        line_no = inspect.getsourcelines(func)[-1]

        @wraps(func)
        def return_func(*args, **kwargs):
            arg_list = list("{!r}".format(arg) for arg in args)
            arg_list.extend("{}={!r}".format(key, val)
                            for key, val in kwargs.iteritems())
            msg = arg_log_fmt.format(name=func.__name__,
                                     arg_str=", ".join(arg_list))
            logger.log(level, msg)
            return func(*args, **kwargs)
        return return_func

    return inner_func

if __name__ == "__main__":
    logger = logging.getLogger(__name__)
    handler = logging.StreamHandler()
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s"
    handler.setFormatter(logging.Formatter(fmt))
    logger.addHandler(handler)
    logger.setLevel(logging.DEBUG)


    @log_args(logger)
    def foo(x, y, z):
        pass

    class Bar(object):
        @log_args(logger)
        def baz(self, a, b, c):
            pass

    foo(1, 2, z=3)
    foo(1, 2, 3)
    foo(x=1, y=2, z=3)

    bar = Bar()
    bar.baz(1, c=3, b=2)

此示例产生以下输出

2015-09-07 12:42:47,779 DEBUG    [__main__:  25] foo(1, 2, z=3)
2015-09-07 12:42:47,779 DEBUG    [__main__:  25] foo(1, 2, 3)
2015-09-07 12:42:47,779 DEBUG    [__main__:  25] foo(y=2, x=1, z=3)
2015-09-07 12:42:47,779 DEBUG    [__main__:  25] baz(<__main__.Bar object at 0x1029094d0>, 1, c=3, b=2)

注意所有行号都指向装饰器。

使用inspect.getsourcelines(func) 我可以获得我感兴趣的行号，但尝试在logger.debug 中覆盖lineno 会导致错误。让包装函数的行号出现在日志记录语句中的最佳方法是什么？

【问题讨论】：

标签： python logging decorator

【解决方案1】：

这是一篇旧帖子，但这个答案可能对其他人仍然有用。

现有解决方案的一个问题是存在multiple parameters providing logging context，如果您想支持任意日志格式化程序，所有这些都需要修补。

原来这是raised as an issue with the Python logging library about a year ago，结果是the stacklevel keyword argument was added in Python 3.8。使用该功能，您只需修改日志调用以将堆栈级别设置为 2（在您的示例中调用 logger.log 的位置高一级）：

logger.log(level, msg, stacklevel=2)

由于 Python 3.8 尚未发布（在此回复时），您可以使用 findCaller and _log methods updated in Python 3.8 对您的记录器进行猴子补丁。

我有一个名为 logquacious 的日志记录实用程序库，我在其中执行相同类型的猴子修补程序。您可以重复使用 patch_logger class that I've defined in logquacious 并更新上面的日志示例：

from logquacious.backport_configurable_stacklevel import patch_logger

logger = logging.getLogger(__name__)
logger.__class__ = patch_logger(logger.__class__)

正如 unutbu 的回答中提到的，在使用它的范围之外撤消这个猴子补丁可能是个好主意，这就是该文件中的其他一些代码所做的。

【讨论】：

【解决方案2】：

另一种可能性是继承Logger 以覆盖Logger.makeRecord。 This is the method 如果您尝试更改 LogRecord 中的任何标准属性（如 rv.lineno），则会引发 KeyError：

for key in extra:
    if (key in ["message", "asctime"]) or (key in rv.__dict__):
        raise KeyError("Attempt to overwrite %r in LogRecord" % key)
    rv.__dict__[key] = extra[key]

通过删除这个预防措施，我们可以通过提供一个 logger.log 调用的 extra 参数：

logger.log(level, msg, extra=dict(lineno=line_no))

from functools import wraps
import inspect
import logging

arg_log_fmt = "{name}({arg_str})"


def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
    """
    A factory method which can be overridden in subclasses to create
    specialized LogRecords.
    """
    rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func)
    if extra is not None:
        rv.__dict__.update(extra)
    return rv

def log_args(logger, level=logging.DEBUG, cache=dict()):
    """Decorator to log arguments passed to func."""
    logger_class = logger.__class__
    if logger_class in cache:
        UpdateableLogger = cache[logger_class]
    else:
        cache[logger_class] = UpdateableLogger = type(
            'UpdateableLogger', (logger_class,), dict(makeRecord=makeRecord))

    def inner_func(func):
        line_no = inspect.getsourcelines(func)[-1]
        @wraps(func)
        def return_func(*args, **kwargs):
            arg_list = list("{!r}".format(arg) for arg in args)
            arg_list.extend("{}={!r}".format(key, val)
                            for key, val in kwargs.iteritems())
            msg = arg_log_fmt.format(name=func.__name__,
                                     arg_str=", ".join(arg_list))
            logger.__class__ = UpdateableLogger
            try:
                logger.log(level, msg, extra=dict(lineno=line_no))
            finally:
                logger.__class__ = logger_class
            return func(*args, **kwargs)
        return return_func

    return inner_func

if __name__ == "__main__":
    logger = logging.getLogger(__name__)
    handler = logging.StreamHandler()
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s"
    handler.setFormatter(logging.Formatter(fmt))
    logger.addHandler(handler)
    logger.setLevel(logging.DEBUG)

    @log_args(logger)
    def foo(x, y, z):
        pass

    class Bar(object):

        @log_args(logger)
        def baz(self, a, b, c):
            pass

    foo(1, 2, z=3)
    foo(1, 2, 3)
    foo(x=1, y=2, z=3)

    bar = Bar()
    bar.baz(1, c=3, b=2)

产量

2015-09-07 16:01:22,332 DEBUG    [__main__:  48] foo(1, 2, z=3)
2015-09-07 16:01:22,332 DEBUG    [__main__:  48] foo(1, 2, 3)
2015-09-07 16:01:22,332 DEBUG    [__main__:  48] foo(y=2, x=1, z=3)
2015-09-07 16:01:22,332 DEBUG    [__main__:  53] baz(<__main__.Bar object at 0x7f17f75b0490>, 1, c=3, b=2)

线

    UpdateableLogger = type('UpdateableLogger', (type(logger),), 
                            dict(makeRecord=makeRecord))

创建一个新类，它是type(logger) 的子类，它覆盖makeRecord。在return_func 内部，logger 的类更改为UpdateableLogger，因此对logger.log 的调用可以修改lineno，然后恢复原始记录器类。

通过这种方式——通过避免猴子修补Logger.makeRecord——所有loggers 在装饰函数之外的行为与以前完全相同。

为了比较，猴子修补方法是shown here。

【讨论】：

该方法可能有效，但不幸的是，当前的实现改变了其他记录器的行为（由于尝试将 None 传递给 dict.update()，它们目前会引发异常）。跨度>
@PatrickMaupin：感谢您的更正（关于例外）。现在用if extra is not None 修复。
你仍然放弃了该函数的一些原始行为——不过，如果你做一些事情，比如创建一个特殊的 dict 子类，应该不会太难找回它。
我已经修改了解决方案以避免猴子补丁logging.Logger.makeRecord。现在，所有记录器在装饰函数之外的行为都将与之前完全相同。只有在装饰函数内部才能更改 lineno。
你知道，我想如果我需要这个，我会替换这个函数，除非是永久的——IMO，以这种方式阻止程序员的意图是非常不符合 Pythonic 的。

【解决方案3】：

正如 Martijn 所指出的，事情有时会发生变化。但是，由于您使用的是 Python 2（iteritems 放弃了它），如果您不介意猴子修补日志记录，以下代码将起作用：

from functools import wraps
import logging

class ArgLogger(object):
    """
    Singleton class -- will only be instantiated once
    because of the monkey-patching of logger.
    """

    singleton = None

    def __new__(cls):
        self = cls.singleton
        if self is not None:
            return self
        self = cls.singleton = super(ArgLogger, cls).__new__(cls)
        self.code_location = None

        # Do the monkey patch exactly one time
        def findCaller(log_self):
            self.code_location, code_location = None, self.code_location
            if code_location is not None:
                return code_location
            return old_findCaller(log_self)
        old_findCaller = logging.Logger.findCaller
        logging.Logger.findCaller = findCaller

        return self

    def log_args(self, logger, level=logging.DEBUG):
        """Decorator to log arguments passed to func."""
        def inner_func(func):
            co = func.__code__
            code_loc = (co.co_filename, co.co_firstlineno, co.co_name)

            @wraps(func)
            def return_func(*args, **kwargs):
                arg_list = list("{!r}".format(arg) for arg in args)
                arg_list.extend("{}={!r}".format(key, val)
                                for key, val in kwargs.iteritems())
                msg = "{name}({arg_str})".format(name=func.__name__,
                                        arg_str=", ".join(arg_list))
                self.code_location = code_loc
                logger.log(level, msg)
                return func(*args, **kwargs)
            return return_func

        return inner_func


log_args = ArgLogger().log_args

if __name__ == "__main__":
    logger = logging.getLogger(__name__)
    handler = logging.StreamHandler()
    fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s"
    handler.setFormatter(logging.Formatter(fmt))
    logger.addHandler(handler)
    logger.setLevel(logging.DEBUG)


    @log_args(logger)
    def foo(x, y, z):
        pass

    class Bar(object):
        @log_args(logger)
        def baz(self, a, b, c):
            pass

    def test_regular_log():
        logger.debug("Logging without ArgLog still works fine")

    foo(1, 2, z=3)
    foo(1, 2, 3)
    foo(x=1, y=2, z=3)

    bar = Bar()
    bar.baz(1, c=3, b=2)
    test_regular_log()

【讨论】：

感谢您的意见。我必须将my_log_info 传递给logger.log 吗？另外，我在其他地方经常使用记录器，所以我不想永久改变它。从这个角度来看，我对猴子补丁感到不舒服。
不，这是用 2.7 编写的（试试看！）。而且这个补丁并不算太糟糕——从其他地方登录会像往常一样工作，因为如果我们不从这里登录，就会调用原始代码。
谢谢，看起来确实如此。我需要做更多的测试，然后让你的解决方案通过代码审查；-) 然后我会接受这个作为答案。
清理它并添加了一个测试，显示常规日志记录不受影响。

【解决方案4】：

您不能轻易更改行号，因为Logger.findCaller() method 通过自省提取此信息。

您可以为您生成的包装函数重新构建函数和代码对象，但这确实很麻烦（请参阅我和 Veedrac 在this post 上跳过的箍）和将当您有错误时会导致问题，因为您的回溯将显示错误的源代码行！

您最好手动将行号以及您的模块名称（因为这也可能不同）添加到您的日志输出中：

arg_log_fmt = "{name}({arg_str}) in {filename}:{lineno}"

# ...

codeobj = func.__code__
msg = arg_log_fmt.format(
    name=func.__name__, arg_str=", ".join(arg_list),
    filename=codeobj.co_filename, lineno=codeobj.co_firstlineno)

因为这里总是有一个函数，所以我使用了一些更直接的自省，通过关联的代码对象获取函数的第一行号。

【讨论】：