Decorator that prints function call details (argument names and values)?

Question

I want to make a function that being a decorator to another function will print that function call details - parameters names and effective values. My current implementation is this.

def describeFuncCall(func):
    """
    Decorator to print function call details.

    parameters names and effective values.
    """

    def wrapper(*func_args, **func_kwargs):
        print "func_code.co_varnames =", func.func_code.co_varnames
        print "func_code.co_argcount =", func.func_code.co_argcount
        print "func_args =", func_args
        print "func_kwargs =", func_kwargs
        params = []
        for argNo in range(func.func_code.co_argcount):
            argName = func.func_code.co_varnames[argNo]
            argValue = (
                func_args[argNo]
                if argNo < len(func_args)
                else func.func_defaults[argNo - func.func_code.co_argcount]
            )
            params.append((argName, argValue))
        for argName, argValue in func_kwargs.items():
            params.append((argName, argValue))
        params = [argName + " = " + repr(argValue)
                  for argName, argValue in params]
        print (func.__name__ + " ( " + ", ".join(params) + " )")
        return func(*func_args, **func_kwargs)

    return wrapper


@describeFuncCall
def test(a, b=4, c="blah-blah", *args, **kwargs):
    pass


test(1)
# test(1, 3)
# test(1, d = 5)
test(1, 2, 3, 4, 5, d=6, g=12.9)

Kinda works, but with some bugs:

For call

test(1, 2, 3, 4, 5, d = 6, g = 12.9)

it prints

test ( a = 1, b = 2, c = 3, d = 6, g = 12.9 ).

The expected result is

test ( a = 1, b = 2, c = 3, args = [4, 5], kwargs = {'d': 6, 'g': 12.9} )

I got stuck here. Can you help me to find the right solution?

If this is for debugging, might it not be useful also to show the function return value? — Curt, May 11 '17 at 02:17

score 29 · Answer 1 · edited Mar 15 '23 at 23:42

Here is the updated version for Python 3.6+

import inspect
from functools import wraps

def dump_args(func):
    """
    Decorator to print function call details.

    This includes parameters names and effective values.
    """

    @wraps(func)
    def wrapper(*args, **kwargs):
        func_args = inspect.signature(func).bind(*args, **kwargs).arguments
        func_args_str = ", ".join(map("{0[0]} = {0[1]!r}".format, func_args.items()))
        print(f"{func.__module__}.{func.__qualname__} ( {func_args_str} )")
        return func(*args, **kwargs)

    return wrapper


@dump_args
def test(a, b=4, c="blah-blah", *args, **kwargs):
    pass


test(1)
test(1, 3)
test(1, d=5)
test(1, 2, 3, 4, 5, d=6, g=12.9)

Old version

Working version with default values:

def dumpArgs(func):
    '''Decorator to print function call details - parameters names and effective values'''
    def wrapper(*func_args, **func_kwargs):
        arg_names = func.func_code.co_varnames[:func.func_code.co_argcount]
        args = func_args[:len(arg_names)]
        defaults = func.func_defaults or ()
        args = args + defaults[len(defaults) - (func.func_code.co_argcount - len(args)):]
        params = zip(arg_names, args)
        args = func_args[len(arg_names):]
        if args: params.append(('args', args))
        if func_kwargs: params.append(('kwargs', func_kwargs))
        print func.func_name + ' (' + ', '.join('%s = %r' % p for p in params) + ' )'
        return func(*func_args, **func_kwargs)
    return wrapper  

@dumpArgs
def test(a, b = 4, c = 'blah-blah', *args, **kwargs):
    pass

test(1)
test(1, 3)
test(1, d = 5)
test(1, 2, 3, 4, 5, d = 6, g = 12.9)

Result:

>>> test  (  a = 1, b = 4, c = 'blah-blah' )
test  (  a = 1, b = 3, c = 'blah-blah' )
test  (  a = 1, b = 4, c = 'blah-blah', kwargs = {'d': 5} )
test  (  a = 1, b = 2, c = 3, args = (4, 5), kwargs = {'d': 6, 'g': 12.9} )

This question is old but still useful. You should note that the core library exposes a standard way to perform this mapping from `*args` and `**kwargs` to actual parameter names: [Signature.bind](https://docs.python.org/3/library/inspect.html#inspect.Signature.bind) — Demurgos, Jul 21 '16 at 10:18

score 13 · Accepted Answer · edited Jan 28 '21 at 14:55

13

Sorry its a bit messy. I modified some code from Easy Dump of Function Arguments in the PythonDecoratorLibrary.

def dump_args(func):
    "This decorator dumps out the arguments passed to a function before calling it"
    argnames = func.func_code.co_varnames[:func.func_code.co_argcount]
    fname = func.func_name
    def echo_func(*args,**kwargs):
        print fname, "(", ', '.join(
            '%s=%r' % entry
            for entry in zip(argnames,args[:len(argnames)])+[("args",list(args[len(argnames):]))]+[("kwargs",kwargs)]) +")"
    return echo_func

@dump_args
def test(a, b = 4, c = 'blah-blah', *args, **kwargs):
    pass

test(1, 2, 3, 4, 5, d = 6, g = 12.9)

Output:

test ( a=1, b=2, c=3, args=[4, 5], kwargs={'d': 6, 'g': 12.9})

edited Jan 28 '21 at 14:55

martineau

119,623
25
170
301

answered Jun 01 '11 at 11:28

Rusty Rob

16,489
8
100
116

it has some bugs which i fixed, but it doesn't take into consideration default values: `test(1)`: test ( a = 1, args = (), kwargs = {} ) – warvariuc Jun 01 '11 at 13:15
2

Unfortunately this example does not call wrapped function at all - you will not catch any error on "test()" call. – Denis Barmenkov Sep 01 '18 at 16:06
Note that this is for python 2. See other answers for Python 3. – nealmcb Nov 02 '20 at 00:26

x10an14 · Answer 3 · 2020-06-11T20:30:40.147

Here's how I solved it in Python 3, based on aliteralmind's answer, put more cleanly (PEP8) if I may say so. Majority of the inspiration for the cleanup came from the (currently) accepted answer by Robert King.

Code (test.py):

#!/usr/bin/env python3

import functools
import inspect
import logging
import time


class CustomFormatter(logging.Formatter):
    """
    Custom formatter, overrides funcName with value of name_override if it exists

    Inspired by; https://stackoverflow.com/a/7004565/1503549
    """
    def format(self, record):
        if hasattr(record, 'func_name'):
            record.funcName = record.func_name
        return super(CustomFormatter, self).format(record)


def log_function_entry_and_exit(decorated_function):
    """
    Function decorator logging entry + exit and parameters of functions.

    Entry and exit as logging.info, parameters as logging.DEBUG.
    """

    @functools.wraps(decorated_function)
    def wrapper(*dec_fn_args, **dec_fn_kwargs):
        # Log function entry
        func_name = decorated_function.__name__
        name_dict = dict(func_name=func_name)
        logging.info(f"Entering {func_name}()...", extra=name_dict)

        # Log function params (args and kwargs)
        func_args = inspect.signature(decorated_function).bind(*dec_fn_args, **dec_fn_kwargs).arguments
        func_args_str = ', '.join(
            f"{var_name} = {var_value}"
            for var_name, var_value
            in func_args.items()
        )
        logging.debug(f"\t{func_args_str}", extra=name_dict)

        # Execute wrapped (decorated) function:
        out = decorated_function(*dec_fn_args, **dec_fn_kwargs)

        time.sleep(1)   # Test to ensure timestamp is real
        logging.info(f"Done running {func_name}()!", extra=name_dict)

        return out
    return wrapper


@log_function_entry_and_exit
def func2(*args, **kwargs):
    print('\t\thello')


@log_function_entry_and_exit
def func1(a, b, c):
    func2(1, 2, 3, 4, b=5)
    print('Hello2!')


if __name__ == '__main__':
    log = logging.getLogger()

    # Must get handler to set format
    handler = logging.StreamHandler()   # Get default root logger
    handler.setFormatter(
        CustomFormatter(
            (
                '[%(asctime)s]'
                ' %(levelname)s:%(funcName)s():%(lineno)s>'
                ' %(message)s'
            ),
            datefmt='%Y-%m-%dT%H:%M:%S',
        )
    )

    # Set logLevel
    log.setLevel(logging.DEBUG)
    handler.setLevel(logging.DEBUG)

    # Combine the two again
    log.addHandler(handler)

    log.info('yolo!', extra=dict(func_name='__main__'))

    func1(2, b="y", c={'z': 4})

Output:

[2020-06-11 22:22:15] 0 x10an14@x10-desktop:~/Desktop/testy
-> $ python3 test.py 
[2020-06-11T22:22:53] INFO:__main__():88> yolo!
[2020-06-11T22:22:53] INFO:func1():33> Entering func1()...
[2020-06-11T22:22:53] DEBUG:func1():42>     a = 2, b = y, c = {'z': 4}
[2020-06-11T22:22:53] INFO:func2():33> Entering func2()...
[2020-06-11T22:22:53] DEBUG:func2():42>     args = (1, 2, 3, 4), kwargs = {'b': 5}
        hello
[2020-06-11T22:22:54] INFO:func2():48> Done running func2()!
Hello2!
[2020-06-11T22:22:55] INFO:func1():48> Done running func1()!
[2020-06-11 22:22:55] 0 x10an14@x10-desktop:~/Desktop/testy
-> $

When I get the magical resources known as "time and energy", I'm interested in playing around with LOG_FORMAT, and figure out how I can replace the wrapper substring with say filename and line number of function invocation =)

EDIT(2020-06-11): Fixed wrapper issue after prompt from @Gahan's comment (dated 2020-06-10).

It seems to be impossible (ref. https://stackoverflow.com/a/8339710/1503549) to have a wrapper report (via the logging module) the line-number of the wrapped / decorated function. Maybe wrapt could be leveraged for this purpose?

Any solution for `wrapper` replacing filename and line number of function invocation? — Gahan, Jun 10 '20 at 17:15

aliteralmind · Answer 4 · 2014-08-08T14:48:41.907

@warvariuc's answer, upgraded to Python 3:

def dumpArgs(func):
    '''Decorator to print function call details - parameters names and effective values'''
    def wrapper(*func_args, **func_kwargs):
        arg_names = func.__code__.co_varnames[:func.__code__.co_argcount]
        args = func_args[:len(arg_names)]
        defaults = func.__defaults__ or ()
        args = args + defaults[len(defaults) - (func.__code__.co_argcount - len(args)):]
        params = list(zip(arg_names, args))
        args = func_args[len(arg_names):]
        if args: params.append(('args', args))
        if func_kwargs: params.append(('kwargs', func_kwargs))
        print(func.__name__ + ' (' + ', '.join('%s = %r' % p for p in params) + ' )')
        return func(*func_args, **func_kwargs)
    return wrapper  

@dumpArgs
def test(a, b = 4, c = 'blah-blah', *args, **kwargs):
    pass

test(1)
test(1, 3)
test(1, d = 5)
test(1, 2, 3, 4, 5, d = 6, g = 12.9)

Pascal T. · Answer 5 · 2022-05-03T11:02:57.273

Here is a version that also works for native functions (python 3 only)

import logging
import inspect


def dump_args(func):
    """
    Decorator to print function call details.
    This includes parameters names and effective values.
    """
    def wrapper(*args, **kwargs):
        try:
            # For standard functions, inspect the signature
            signature = inspect.signature(func)
            func_args = signature.bind(*args, **kwargs).arguments
            func_args_str = ", ".join(map("{0[0]} = {0[1]!r}".format, func_args.items()))
            msg =  f"{func.__module__}.{func.__qualname__} ( {func_args_str} )"
        except ValueError:
            # For native functions, the signature cannot be inspected
            args_strs = map(lambda arg: f"arg_{arg[0]} = {arg[1]}", enumerate(args) )
            kwargs_strs = map(lambda kwarg: f"{kwarg[0]} = {kwarg[1]}", kwargs )
            func_args_str = ", ".join(list(args_strs) + list(kwargs_strs))
            msg =  f"{func.__module__}.{func.__name__} ( {func_args_str} )"
        logging.debug(msg)
        return func(*args, **kwargs)
    return wrapper

And I can activate it at module level like this:

__init__.py

_DEBUG_MY_MODULE = True

if _DEBUG_MY_MODULE:
    from .decorators import dump_args
    SDL_CreateWindow = dump_args(SDL_CreateWindow)

And I get outputs like this:

DEBUG:root:ctypes.SDL_CreateWindow ( arg_0 = b'', arg_1 = 863, arg_2 = 548, arg_3 = 150, arg_4 = 150, arg_5 = 8226 )

For a more complete version, that include return values, output parameters and fancy output, see this gist

This doesn't take into account defaults, you can use `.apply_defaults()` on the result of `signature.bind` to get them, then it gets the correct values. — Stuart Axon, Dec 14 '22 at 16:57

score 0 · Answer 6 · edited Aug 17 '22 at 18:34

Its a bit old post but wanted to add my bit. Solution given by warvariuc does not work in all cases. If a method have default values as well as we send named arguments while calling, it does not give proper output. e.g. we get two values of b.

test(1, b = 5)
test (a = 1, b = 4, c = 'blah-blah', kwargs = {'b': 5} )

Adding my modified code.

def print_args(func):
    """
    Function to print all args of decorated function
    """

    def wrapper(*func_args, **func_kwargs):
        arg_names = func.__code__.co_varnames[:func.__code__.co_argcount]
        args = func_args[:len(arg_names)]
        defaults = func.__defaults__ or ()
        args = args + defaults[len(defaults) - (func.__code__.co_argcount - len(args)):]
        params = zip(arg_names, args)
        new_arg_list = [list(i) for i in params]
        for key in func_kwargs:
            for param in new_arg_list:
                if key == param[0]:
                    param[1] = func_kwargs[key]
        new_arg_list = [tuple(i) for i in new_arg_list]
        result = func(*func_args, **func_kwargs)
        print(f'{func.__name__} (' + ', '.join('%s = %r' % p for p in new_arg_list) + f'): {result}')

        return result

    return wrapper
    

@print_args
def test_params(a=7,b=5):
    pass
    
test_params(a=3)

Output

test_params (a = 3, b = 5)

Decorator that prints function call details (argument names and values)?

6 Answers6

Linked