Using functools.wraps with a logging decorator

user_440260 0
Viewed 13673

I'm trying to write a simple decorator that logs a given statement before calling the decorated function. The logged statements should both appear to come from the same function, which I thought was the purpose of functools.wraps().

Why does the following 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()

result in log statements like:

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

I thought the call to wraps would rename wrapper with decorated_function's name.

I'm using python 2.7.1.

logging python
6 Answers

I have found in docs how it can be done, just add this code to your 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

or instead of functools.wrap use this decorator:

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
user_2729330

Here is a simple generic decorator:

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

enter image description here

user_102628050

It's 2022 and this is still difficult.

Here's a complete example with correct filename and line number as well in case it's desired. This is adapted from @zeekay's answer.

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

Defining caller before the wrapper function will correctly get the calling function's (i.e. decorated_function) filename and line number.

user_109578440
Related