Logging via decorators in python - function called twice?-CodePudding

I am trying to log expectations via decorators and came across a code snippet (see below)

from functools import wraps

def logged(log='trace'):
    def wrap(function):
        @wraps(function)
        def wrapper(*args, **kwargs):
            logger = logging.getLogger(log)
            logger.debug("Calling function '{}' with args={} kwargs={}"
                             .format(function.__name__, args, kwargs))
            try:
                response = function(*args, **kwargs)
            except Exception as error:
                logger.debug("Function '{}' raised {} with error '{}'"
                                 .format(function.__name__,
                                         error.__class__.__name__,
                                         str(error)))
                raise error
            logger.debug("Function '{}' returned {}"
                             .format(function.__name__,
                                     response))
            return response
        return wrapper
    return wrap 


@logged()
def add(a, b):
    return a   b

The code works fine but say if I call add(2,3) it appears the add function is called twice, once inside the decorator (added value stored in response variable) and then when I actually call add(2,3) somewhere in my code.

Is my understanding correct ? If so I would ideally want the decorator to only do the following:

print "Calling function" with args
If exception occurs when I call add(2,3) log the error. This should happen without doing response = function(*args, **kwargs) in the decorator

Is that possible ?

CodePudding user response：

it appears the add function is called twice [...] Is my understanding correct?

No. You need to understand that a decorator is nothing but syntactic sugar for a function that (typically) takes a callable object (i.e. function) as an argument and returns a callable/function.

In this case there are a few layers of nesting, but ultimately, what you have after the interpreter gets to the end of the definition of the decorated function, is the inner function wrapper that masquerades as the add function.

That wrapper is what is called, when you later on call add(2, 3). And by its definition it will in turn call the "actual" add, passed to the definition of wrapper as the argument function of wrap.

Before that, the "actual" add is not called because the wrapper is not called. add is merely passed as a callable to the inner decorator and used to construct the wrapper function. The wrapper function is then returned to you after decoration.

This should happen without doing response = function(*args, **kwargs) in the decorator

If you don't call function somewhere in there, the actual function (in this case add) will never be called.