27

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?

2
  • If this is for debugging, might it not be useful also to show the function return value?
    – Curt
    May 11, 2017 at 2:17
  • @Curt yes, sure
    – warvariuc
    May 11, 2017 at 4:37

6 Answers 6

28

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} )
1
  • 3
    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
    – Demurgos
    Jul 21, 2016 at 10:18
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})
3
  • 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 1, 2011 at 13:15
  • 2
    Unfortunately this example does not call wrapped function at all - you will not catch any error on "test()" call. Sep 1, 2018 at 16:06
  • Note that this is for python 2. See other answers for Python 3.
    – nealmcb
    Nov 2, 2020 at 0:26
7

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?

1
  • Any solution for wrapper replacing filename and line number of function invocation?
    – Gahan
    Jun 10, 2020 at 17:15
4

@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)
0
1

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

1
  • 1
    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. Dec 14, 2022 at 16:57
0

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)

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.