使用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

我认为对换行的调用会用wrapped_function的名称重命名包装器.

我正在使用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

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