Using functools.wraps with a logging decorator

Question

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.

Answer 1

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.

Answer 2

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

Answer 3

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

Answer 4

Unlike you may suspect, the logging.functions do no use the __name__ attribute. This implies using @wraps (or setting the __name__ of the wrapper manually) does not work!

Instead, the show that name, the call-frame is examined. It contains a list of code-items (basically the stack). There the function name read, as well as the filename and line-number. When using a logging-decorator, the wrapper-name is always printed, as it is the one that calls log.

BTW. The logging.level() functions all call logging._log(*level*, ...), which calls other (log) functions as well. Which all end-up on the stack. To prevent those log-functions are shown, the list of frames is searched for the first (lowest) function which filename is not part of 'logging'. That should be the real function to log: the one calling logger.func().

Regrettably, it is wrapper.

It would, however, be possible to use a log-decorator: when it is part of the logging source file. But there is none (yet)

Answer 5

Unfortunately logging uses the function code object to infer the name. You could work around this by using the extra keyword argument to specify some additional attributes for the record, which you could then use during formatting. You could do something like:

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

...

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

The only downside to this approach is that you have to pass in the extra dictionary every time. To avoid that you could use a custom formatter and have it override 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()

Which does what you want:

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

Answer 6

I suspect that the logging module uses the __name__ attribute on a function object. That doesn't typically change even if you assign the function to another name...you'd see the same results doing something like:

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

You will get foo - in foo, not bar - in foo when you call bar.

Decorators are doing something similar under the hood.