Verwendung von functools.wraps mit einem Logging-Dekorator

Question

Ich versuche, einen einfachen Dekorator zu schreiben, der eine bestimmte Anweisung protokolliert, bevor er die dekorierte Funktion aufruft. Die protokollierten Anweisungen sollten beide von der gleichen Funktion zu kommen scheinen, was ich dachte, war der Zweck von functools.wraps().

Warum funktioniert der folgende Code:

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()

führen zu Protokollerklärungen wie:

             wrapper - This should be logged by 'decorated_function'
  decorated_function - I ran

Ich dachte, der Aufruf von wraps würde wrapper mit dem Namen von decorated_function umbenennen.

Ich verwende Python 2.7.1.

Answer 1

Leider logging verwendet das Funktionscode-Objekt, um den Namen abzuleiten. Sie können dies umgehen, indem Sie das extra Schlüsselwortargument, um einige zusätzliche Attribute für den Datensatz anzugeben, die Sie dann bei der Formatierung verwenden können. Sie könnten etwa so vorgehen:

logging.basicConfig(
    level=logging.DEBUG,
    format='%(real_func_name)20s - %(message)s',
)

...

logging.info(statement, extra={'real_func_name': func.__name__})

Der einzige Nachteil dieses Ansatzes ist, dass Sie die extra jedes Mal ein Wörterbuch. Um das zu vermeiden, könnten Sie einen benutzerdefinierten Formatierer verwenden und ihn die folgenden Funktionen überschreiben lassen 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()

Das macht, was Sie wollen:

% python logging_test.py
  decorated_function - This should be logged by 'decorated_function'
  decorated_function - I ran

Answer 2

Ich habe gefunden in docs wie es gemacht werden kann, fügen Sie einfach diesen Code zu Ihrem Dekorator hinzu:

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

oder anstelle von functools.wrap diesen Dekorator verwenden:

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

Anders als Sie vielleicht vermuten, ist die Protokollierung. Funktionen das Attribut __name__ nicht verwenden. Dies impliziert die Verwendung von @wraps (oder das manuelle Setzen des __name__ des Wrappers) funktioniert nicht!

Stattdessen wird die Anzeige dieses Namens, der Call-Frame untersucht. Er enthält eine Liste von Code -Einzelteile (im Grunde der Stapel). Dort wird der Funktionsname gelesen, sowie der Dateiname und die Zeilennummer. Wenn ein Logging-Dekorator verwendet wird, ist der Wrapper-Name immer gedruckt da sie diejenige ist, die das Protokoll aufruft.

ÜBRIGENS. Die Protokollierung. Ebene ()-Funktionen rufen alle logging._log(*level*, ...) , die auch andere (Log-)Funktionen aufruft. Diese landen alle auf dem Stack. Um zu verhindern, dass diese Log-Funktionen angezeigt werden, wird die Liste der Frames nach dem ersten ( niedrigste ) Funktion, deren Dateiname nicht Teil von 'logging' ist. Das sollte die eigentliche Funktion sein, die protokolliert werden soll: die, die logger aufruft. func ().

Bedauerlicherweise ist es wrapper .

Es wäre jedoch möglich, einen log-decorator: zu verwenden, wenn er Teil der Quelldatei der Protokollierung ist. Aber es gibt (noch) keinen

Answer 4

Hier ist ein einfacher generischer Dekorator:

def logged(fn):
    from functools import wraps
    from datetime import datetime,timezone
    @wraps(fn)
    def inner(*args, **kwargs):
        run_time=datetime.now(timezone.utc)
        result=fn(*args,**kwargs)
        print('{0} called at {1}'.format(fn.__name__,run_time))
        return result
    return inner

Answer 5

Wir schreiben das Jahr 2022 und es ist immer noch schwierig.

Hier ist ein vollständiges Beispiel mit korrektem Dateinamen und Zeilennummer, falls gewünscht. Dies ist eine Adaption der Antwort von @zeekay.

from inspect import getframeinfo, stack
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
        if hasattr(record, 'file_override'):
            record.filename = record.file_override
        if hasattr(record, 'line_override'):
            record.lineno= record.line_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('%(asctime)s - %(filename)s:%(lineno)s - %(funcName)s - %(levelname)s - %(message)s'))
logger.addHandler(handler)

def log_and_call(statement):
    def decorator(func):
        caller = getframeinfo(stack()[1][0])
        @wraps(func)
        def wrapper(*args, **kwargs):
            # set name_override to func.__name__
            logger.info(statement, extra={
                'name_override': func.__name__,
                'file_override': os.path.basename(caller.filename),
                'line_override': caller.lineno
                })
            return func(*args, **kwargs)
        return wrapper
    return decorator

@log_and_call("This should be logged by 'decorated_function'")
def decorated_function():  # <- the logging in the wrapped function will point to/log this line for lineno.
    logger.info('I ran')

decorated_function()

Definition von caller vor der wrapper Funktion wird die Funktion des Aufrufers (d.h. decorated_function ) Dateiname und Zeilennummer.