Decorator that prints function call details (parameters names and effective values)?
Here is the updated version for Python 3.6+
import inspect
def dump_args(func):
"""
Decorator to print function call details.
This includes parameters names and effective values.
"""
def wrapper(*args, **kwargs):
func_args = inspect.signature(func).bind(*args, **kwargs).arguments
func_args_str = ", ".join(
"{} = {!r}".format(*item) for item in 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} )
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})
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?