使用functools.wraps和logging d

Question

我试图编写一个简单的decorator，在调用decorated函数之前记录一个给定的语句。记录的语句应该都来自同一个函数，我认为这是functools.wrapps（）的目的。

为什么会出现以下代码：

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

我以为对wrapps的调用会用修饰的函数名重命名wrapper。

我使用的是Python2.7.1。

Answer 1

不幸的是，logging使用函数代码对象来推断名称。可以通过使用^{}关键字参数为记录指定一些附加属性来解决此问题，然后可以在格式化期间使用这些属性。你可以这样做：

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

Answer 2

我在docs中找到了实现方法，只需将此代码添加到您的decorator：

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

我怀疑日志模块在函数对象上使用了“name”属性。即使将函数赋给另一个名称，这种情况通常也不会改变……您会看到相同的结果，例如：

def foo()
  logging.info("in foo")
bar = foo
bar()

当您调用bar时，您将得到foo - in foo，而不是bar - in foo。

装潢师也在做类似的事情。