将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的调用将使用decorated_function的名称重命名wrapper。

我正在使用python 2.7.1。

Answer 1

不幸的是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