Logging decorator in Python (log every function call)

A logging decorator prints a line every time a function is called, showing the arguments it received and the value it returned. It is useful when you want to see what your program is doing without adding print() lines inside every function.

The program

python

import functools


def log_calls(func):
    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        arg_parts = [repr(a) for a in args] + [f"{k}={v!r}" for k, v in kwargs.items()]
        print(f"Calling {func.__name__}({', '.join(arg_parts)})")
        result = func(*args, **kwargs)
        print(f"{func.__name__} returned {result!r}")
        return result
    return wrapper


@log_calls
def add(a, b):
    return a + b


@log_calls
def greet(name, greeting="Hello"):
    return f"{greeting}, {name}!"


total = add(3, 4)
message = greet("Ada", greeting="Hi")
print(total, message)

+ setup added so this can run · defines args, kwargs

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

args = ["alpha", "beta", "gamma"]
kwargs = _AutoMock('kwargs')

output

Calling add(3, 4)
add returned 7
Calling greet('Ada', greeting='Hi')
greet returned 'Hi, Ada!'
7 Hi, Ada!

How it works

@log_calls above a function means add = log_calls(add). From then on, every call to add runs wrapper instead.
*args collects the positional arguments into a tuple and **kwargs collects the keyword arguments into a dictionary, so the same wrapper works for any function.
repr() and !r show values the way you would type them in code, so the string Ada shows as 'Ada' with quotes.
The wrapper returns the result, so the decorated function still works exactly as before. Without return result, add(3, 4) would give None.
functools.wraps(func) keeps the original __name__, so the messages say add and not wrapper.

Another way: the logging module

In a real program, use the logging module instead of print(). You can then turn the messages on or off, or send them to a file, without changing the decorator:

python

import functools
import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG, format="%(levelname)s %(message)s")
logger = logging.getLogger(__name__)


def log_calls(func):
    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        logger.debug("calling %s args=%r kwargs=%r", func.__name__, args, kwargs)
        result = func(*args, **kwargs)
        logger.debug("%s returned %r", func.__name__, result)
        return result
    return wrapper


@log_calls
def add(a, b):
    return a + b


add(3, 4)

+ setup added so this can run · defines args, kwargs

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

args = _AutoMock('args')
kwargs = _AutoMock('kwargs')

output

DEBUG calling add args=(3, 4) kwargs={}
DEBUG add returned 7

Add %(asctime)s to the format string to put the date and time at the start of each line. This page leaves it out because the time would be different on every run. Change level=logging.DEBUG to logging.INFO and the debug messages stop, with no other changes.

Related programs: Decorator, Retry decorator.