Использование functools.wraps с оформлением журнала

Я пытаюсь написать простой декоратор, который регистрирует задание перед вызовом декорированной функции. Записанные операторы должны отображаться как бы из той же функции, которая, как я думал, была целью 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.

Ответ 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

Ответ 2

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

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

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

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

Ответ 3

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

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

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

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

Однако было бы возможно использовать лог-декоратор: когда он является частью исходного файла журнала. Но нет (пока)

Ответ 4

Я нашел интересный lib Autologging, но пока не использовал его, может быть, он будет полезен.