Printing a function's local variable names and values

Question

To help me debug some of the code I write, I want to make a function decorator that prints off the name of a variable and its value as each variable is created or modified, essentially giving me a "play-by-play" view of what happens when I call the function.

The approach I had been using up until this point is simply adding a line like print(foo) wherever I wanted to see what was happening, but this is extremely time-consuming and makes my code messy to look at (possibly the epitome of un-Pythonicness).

Effectively what I want to do is have this:

@show_guts
def foo(a,b):
    biz = str(a)
    baz = str(b)
    return biz + baz

foo("banana","phone")

print something like this in the IDE:

biz = "banana"
baz = "phone"
bananaphone

My question is what @show_guts would look like. I know it's possible to print only the values of a and b with a decorator like

def print_args(function):
    def wrapper(*args,**kwargs):
        print("Arguments:",args)
        print("Keyword Arguments:",kwargs)
        return function(*args,**kwargs)
    return wrapper

which gives me

Arguments: ('banana', 'phone')
Keyword Arguments: {}
'bananaphone'

but I'm totally stumped as to how to print the local variable names as well as their values. Not to mention do it in a "neat" way.

Answer 1

You cannot do this without enabling tracing; this will hurt performance. Function locals are constructed when the function is called, and cleaned up when it returns, so there is no other way to access those locals from a decorator.

You can insert a trace function using sys.settrace(), then respond to the events the Python interpreter sends that function. What we want to do is trace just the decorated function, and record the locals when the function returns:

import sys
import threading

def show_guts(f):
    sentinel = object()
    gutsdata = threading.local()
    gutsdata.captured_locals = None
    gutsdata.tracing = False

    def trace_locals(frame, event, arg):
        if event.startswith('c_'):  # C code traces, no new hook
            return 
        if event == 'call':  # start tracing only the first call
            if gutsdata.tracing:
                return None
            gutsdata.tracing = True
            return trace_locals
        if event == 'line':  # continue tracing
            return trace_locals

        # event is either exception or return, capture locals, end tracing
        gutsdata.captured_locals = frame.f_locals.copy()
        return None

    def wrapper(*args, **kw):
        # preserve existing tracer, start our trace
        old_trace = sys.gettrace()
        sys.settrace(trace_locals)

        retval = sentinel
        try:
            retval = f(*args, **kw)
        finally:
            # reinstate existing tracer, report, clean up
            sys.settrace(old_trace)
            for key, val in gutsdata.captured_locals.items():
                print '{}: {!r}'.format(key, val)
            if retval is not sentinel:
                print 'Returned: {!r}'.format(retval)
            gutsdata.captured_locals = None
            gutsdata.tracing = False

        return retval

    return wrapper

Demonstration:

>>> @show_guts
... def foo(a,b):
...     biz = str(a)
...     baz = str(b)
...     return biz + baz
... 
>>> result = foo("banana","phone")
a: 'banana'
biz: 'banana'
b: 'phone'
baz: 'phone'
Returned: 'bananaphone'

Answer 2

In the spirit of debugging, I present my hax:

import re
import inspect

assignment_regex = re.compile(r'(\s*)([\w\d_]+)\s*=\s*[\w\d+]')

def show_guts(fn):
    source = inspect.getsource(fn)
    lines = []
    for line in source.split('\n'):
        if 'show_guts' in line:
            continue
        lines.append(line)
        if 'def' in line:
            # kwargs will match the regex
            continue
        search = assignment_regex.search(line)
        try:
            groups = search.groups()
            leading_whitespace = groups[0]
            variable_name = groups[1]
            lines.append(leading_whitespace + 'print "Assigning {0} =", {0}'.format(variable_name))
        except AttributeError:  # no match
            pass
    new_source = '\n'.join(lines)
    namespace = {}
    exec new_source in namespace
    fn = namespace[fn.__name__]

    def wrapped(*args, **kwargs):
        arg_string = ', '.join(map(str, args))
        kwarg_string = ', '.join(key + '=' + str(value) for key, value in kwargs.iteritems())
        print "Calling", fn.__name__ + '(' + ', '.join((arg_string, kwarg_string)) + ')'
        return fn(*args, **kwargs)
    return wrapped

Basically, this is automatically doing what you were doing. It gets the source for the function passed in, loop over each line in the source and for each assignment statement, create a new print statement and append it to the source body. The new source is compiled and the function is replaced with the newly compiled function. Then to get the *args and **kwargs, I create the normal decorator wrapper function and throw in some nice print statements. That part could probably be a little better with some help from the inspect module, but whatevs.

foo() -> foo() with print statements

# This...
@show_guts
def complicated(a, b, keyword=6):
    bar = str(a)
    baz = str(b)
    if a == b:
        if keyword != 6:
            keyword = a
    else:
        keyword = b
    return bar + baz

# becomes this
def complicated(a, b, keyword=6):
    bar = str(a)
    print "Assigning bar =", bar
    baz = str(b)
    print "Assigning baz =", baz
    if a == b:
        if keyword != 6:
            keyword = a
            print "Assigning keyword =", keyword
    else:
        keyword = b
        print "Assigning keyword =", keyword
    return bar + baz

Usage

@show_guts
def foo(a, b):
    bar = str(a)
    baz = str(b)
    return bar + baz


@show_guts
def complicated(a, b, keyword=6):
    bar = str(a)
    baz = str(b)
    if a == b:
        if keyword != 6:
            keyword = a
    else:
        keyword = b
    return bar + baz


foo(1, 2)
complicated(3, 4)
complicated(3, 3)
complicated(3, 3, keyword=123)

Output

Calling foo(1, 2, )
Assigning bar = 1
Assigning baz = 2
Calling complicated(3, 4, )
Assigning bar = 3
Assigning baz = 4
Assigning keyword = 4
Calling complicated(3, 3, )
Assigning bar = 3
Assigning baz = 3
Calling complicated(3, 3, keyword=123)
Assigning bar = 3
Assigning baz = 3
Assigning keyword = 3

There are probably some corner cases that I'm missing with the regex, but this will get you close.