Decorator to log function execution line by line

Question

I'm working on a script that takes a few minutes to run, and would like to provide some output to the user about its progress. Unfortunately i'm exceedingly lazy. what I'd like to do is write a function without the logging, and then apply a decorator to it which steps through the function and prints each line before executing that line. Basically what I'm looking for is a loggingdecorator such that:

>>> @loggingdecorator
... def myfunction():
...     foo()
...     bar()
...     baz()
>>> myfunction()
Starting myfunction
foo() ... [OK]
bar() ... [OK]
baz() ... [OK]
myfunction Done!

Here's what I've tried so far:

import sys


def logging_tracer(frame, event, arg):
    def local_tracer(local_frame, event, arg):
        if frame is local_frame:
            print frame.f_code.co_name, event, arg

    print frame.f_code.co_name, event, arg
    return local_tracer


def loggingdecorator(func):
    def _wrapper():
        old_trace_function = sys.gettrace()
        sys.settrace(logging_tracer)
        try:
            result = func()
        except:
            raise
        else:
            return result
        finally:
            sys.settrace(old_trace_function)
    return _wrapper

Unfortunately, this prints a bit too much; it follows function calls and prints them out, line by line as well (well, this doesn't actually print the source line, existing answers using inspect, combined with stuff on the frame object in the trace function would do it), but I'm a bit stumped as to how the logging_tracer unless the function in question is actually decorated.

Answer 1

So here's what I came up with. @Corley Brigman's comment got me started in the right direction. This is a bit hackey, sys.gettrace/settrace are rather promenently documented as "CPython implementation details", and so this solution should not be expected to work in other implementations. That said, it seems to work out pretty well. The tracing functionality in cpython does not provide any notification of "line finished executing", so the [ok] from my question doesn't really make any sense.

Fixing the recursive tracing issue is just a simple matter of keeping a cache of the functions that were decorated, and then only produce output if the frame being traced is from a function that was decorated.

import inspect
import sys


def logging_tracer(frame, event, arg):
    lines, firstline = inspect.getsourcelines(frame)

    def local_tracer(local_frame, event, arg):
        if event == 'line' and frame is local_frame:
            print event, frame.f_lineno,'\t', lines[frame.f_lineno - firstline]
            #print event, lines[frame.f_lineno - firstline]
            #print frame.f_code.co_name, frame.f_lineno, event, arg

    if frame.f_code in LOG_THESE_FUNCTIONS:
        print event, frame.f_lineno,'\t', lines[frame.f_lineno - firstline + (event == 'call')]
        #print frame.f_code.co_name, event, arg
        return local_tracer
    else:
        return None


LOG_THESE_FUNCTIONS = set()


def loggingdecorator(func):
    LOG_THESE_FUNCTIONS.add(func.func_code)

    def _wrapper():
        old_trace_function = sys.gettrace()
        sys.settrace(logging_tracer)
        try:
            result = func()
        except:
            raise
        else:
            return result
        finally:
            sys.settrace(old_trace_function)
    return _wrapper

Answer 2

Here's an ugly example that works if there's only one indentation level:

import inspect


def myDec(func):
    temp = list(inspect.getsourcelines(func)[0])

    temp.append('    print("{} Done!")\n'.format(func.__name__))
    for index in range(len(temp)-2, 0, -1):
        temp.insert(index+1, "    print('''{}...[OK]''')\n".format(temp[index].strip().rstrip("\n")))
    temp.insert(1, '    print("Starting {}")\n'.format(func.__name__))
    temp = "".join(temp)
    exec(temp)
    return locals()[func.__name__]

def foo():
    a = 4+5
    list_int = range(100)


foo = myDec(foo)
foo()

Really ugly though...