在日志装饰器中使用functools.wraps

Question

我正在尝试写一个简单的装饰器，它会在调用被装饰的函数之前记录一条给定的语句。我希望记录的语句看起来都是来自同一个函数，我以为这就是functools.wraps()的目的。

为什么下面的代码：

import logging
logging.basicConfig(
    level=logging.DEBUG,
    format='%(funcName)20s - %(message)s')

from functools import wraps

def log_and_call(statement):
    def decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            logging.info(statement)            
            return func(*args, **kwargs)
        return wrapper
    return decorator


@log_and_call("This should be logged by 'decorated_function'")
def decorated_function():
    logging.info('I ran')

decorated_function()

会导致日志语句像这样：

             wrapper - This should be logged by 'decorated_function'
  decorated_function - I ran

我以为调用wraps会把包装函数的名字改成被装饰函数的名字。

我使用的是python 2.7.1。

Answer 1

你可能会觉得，logging.functions 其实并没有使用 __name__ 这个属性。这意味着使用 @wraps（或者手动设置包装函数的 __name__）是没用的！

实际上，要显示的名字是通过检查调用的上下文来获取的。这个上下文包含了一系列的 code 项目（基本上就是调用栈）。在这里，可以读取到函数名、文件名和行号。当使用一个日志装饰器时，包装函数的名字总是会被 打印 出来，因为它是调用日志的那个。

顺便说一下，logging.level() 这些函数都会调用 logging._log(*level*, ...)，而这个又会调用其他的（日志）函数。这些函数最终都会出现在调用栈上。为了防止这些日志函数被显示，系统会在调用栈中查找第一个（最底层的）函数，其文件名不包含 'logging'。这个函数应该就是我们真正想记录的函数：也就是调用 logger.func() 的那个。

可惜的是，这个函数是 wrapper。

不过，如果使用一个日志装饰器的话，是可以做到的：前提是它在日志源文件中。但目前还没有这样的装饰器（还没出现）。

Answer 2

我在文档中找到了怎么做的方法，只需要把这段代码加到你的装饰器里：

def log_and_call(statement):        
    def decorator(func):
        old_factory = logging.getLogRecordFactory()

        def record_factory(*args, **kwargs):
            record = old_factory(*args, **kwargs)
            record.funcName = func.__name__
            return record

        def wrapper(*args, **kwargs):
            logging.setLogRecordFactory(record_factory)
            logging.info(statement)
            logging.setLogRecordFactory(old_factory)
            return func(*args, **kwargs)
        return wrapper
    return decorator

或者，你也可以用这个装饰器，替代functools.wrap：

def log_wrapper(func_overrider):
    old_factory = logging.getLogRecordFactory()

    def new_factory(*args, **kwargs):
        record = old_factory(*args, **kwargs)
        record.funcName = func_overrider.__name__
        return record

    def decorator(func):
        def wrapper(*args, **kwargs):
            logging.setLogRecordFactory(new_factory)
            result = func(*args, **kwargs)
            logging.setLogRecordFactory(old_factory)
            return result

        return wrapper

    return decorator

Answer 3

不幸的是，logging模块是通过函数的代码对象来推断名称的。你可以通过使用extra这个关键字参数来指定一些额外的属性，这样在格式化的时候就可以使用这些属性。你可以这样做：

logging.basicConfig(
    level=logging.DEBUG,
    format='%(real_func_name)20s - %(message)s',
)

...

logging.info(statement, extra={'real_func_name': func.__name__})

这种方法唯一的缺点是每次都需要传入extra字典。为了避免这样，你可以使用一个自定义的格式化器，并让它重写funcName：

import logging
from functools import wraps

class CustomFormatter(logging.Formatter):
    """Custom formatter, overrides funcName with value of name_override if it exists"""
    def format(self, record):
        if hasattr(record, 'name_override'):
            record.funcName = record.name_override
        return super(CustomFormatter, self).format(record)

# setup logger and handler
logger = logging.getLogger(__file__)
handler = logging.StreamHandler()
logger.setLevel(logging.DEBUG)
handler.setLevel(logging.DEBUG)
handler.setFormatter(CustomFormatter('%(funcName)20s - %(message)s'))
logger.addHandler(handler)

def log_and_call(statement):
    def decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            # set name_override to func.__name__
            logger.info(statement, extra={'name_override': func.__name__})
            return func(*args, **kwargs)
        return wrapper
    return decorator

@log_and_call("This should be logged by 'decorated_function'")
def decorated_function():
    logger.info('I ran')

decorated_function()

这样就能实现你想要的效果：

% python logging_test.py
  decorated_function - This should be logged by 'decorated_function'
  decorated_function - I ran