Использование 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

Я думал, что вызов оберток переименует обертку с именем decor_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

Answer 3

В отличие от того, что вы подозреваете, ведение журнала. функции не используют атрибут __name__.Это подразумевает, что использование @wraps (или установка __name__ оболочки) вручную не работает!

Вместо этого показывается, что имя, рамка вызова проверяется.Он содержит список элементов code (в основном, стек).Там читается имя функции, а также имя файла и номер строки.При использовании logging-decorator имя оболочки всегда печатается , так как именно оно вызывает log.

BTW.Регистрация. level () все функции вызывают logging._log(*level*, ...), что также вызывает другие (log) функции.Которые все в конечном итоге в стеке.Чтобы предотвратить отображение этих функций журнала, в списке кадров выполняется поиск первой ( наименьшая ) функция, имя файла которой не является частью «ведения журнала».Это должна быть реальная функция для записи: один вызывающий регистратор. func ().

К сожалению, это wrapper.

Это, однако, будетМожно использовать log-decorator: когда он является частью исходного файла журнала.Но нет (пока)

Answer 4

Я подозреваю, что модуль ведения журнала использует атрибут __name__ на объекте функции. Обычно это не меняется, даже если вы присваиваете функцию другому имени ... вы увидите, что те же результаты будут выглядеть примерно так:

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

Вы получите foo - in foo, а не bar - in foo при вызове bar.

Декораторы делают что-то похожее под капотом.