Python debugging: get filename and line number fro

Question

I'm currently building quite a complex system in Python, and when I'm debugging I often put simple print statements in several scripts. To keep an overview I often also want to print out the file name and line number where the print statement is located. I can of course do that manually, or with something like this:

from inspect import currentframe, getframeinfo
print getframeinfo(currentframe()).filename + ':' + str(getframeinfo(currentframe()).lineno) + ' - ', 'what I actually want to print out here'

which prints something like:

filenameX.py:273 - what I actually want to print out here

To make it more simple, I want to be able to do something like:

print debuginfo(), 'what I actually want to print out here'

So I put it into a function somewhere and tried doing:

from debugutil import debuginfo
print debuginfo(), 'what I actually want to print out here'
print debuginfo(), 'and something else here'

unfortunately, I get:

debugutil.py:3 - what I actually want to print out here
debugutil.py:3 - and something else here

It prints out the file name and line number on which I defined the function, instead of the line on which I call debuginfo(). This is obvious, because the code is located in the debugutil.py file.

So my question is actually: How can I get the filename and line number from which this debuginfo() function is called? All tips are welcome!

Answer 1

The function inspect.stack() returns a list of frame records, starting with the caller and moving out, which you can use to get the information you want:

from inspect import getframeinfo, stack

def debuginfo(message):
    caller = getframeinfo(stack()[1][0])
    print "%s:%d - %s" % (caller.filename, caller.lineno, message)

def grr(arg):
    debuginfo(arg)

grr("aargh")

Output:

example.py:8 - aargh

Answer 2

If you put your trace code in another function, and call that from your main code, then you need to make sure you get the stack information from the grandparent, not the parent or the trace function itself

Below is a example of 3 level deep system to further clarify what I mean. My main function calls a trace function, which calls yet another function to do the work.

######################################

import sys, os, inspect, time
time_start = 0.0                    # initial start time

def trace_libary_init():
    global time_start

    time_start = time.time()      # when the program started

def trace_library_do(relative_frame, msg=""):
    global time_start

    time_now = time.time()

        # relative_frame is 0 for current function (this one), 
        # 1 for direct parent, or 2 for grand parent.. 

    total_stack         = inspect.stack()                   # total complete stack
    total_depth         = len(total_stack)                  # length of total stack
    frameinfo           = total_stack[relative_frame][0]    # info on rel frame
    relative_depth      = total_depth - relative_frame      # length of stack there

        # Information on function at the relative frame number

    func_name           = frameinfo.f_code.co_name
    filename            = os.path.basename(frameinfo.f_code.co_filename)
    line_number         = frameinfo.f_lineno                # of the call
    func_firstlineno    = frameinfo.f_code.co_firstlineno

    fileline            = "%s:%d" % (filename, line_number)
    time_diff           = time_now - time_start

    print("%13.6f %-20s %-24s %s" % (time_diff, fileline, func_name, msg))

################################

def trace_do(msg=""):
    trace_library_do(1, "trace within interface function")
    trace_library_do(2, msg)
    # any common tracing stuff you might want to do...

################################

def main(argc, argv):
    rc=0
    trace_libary_init()
    for i in range(3):
        trace_do("this is at step %i" %i)
        time.sleep((i+1) * 0.1)         # in 1/10's of a second
    return rc

rc=main(sys.argv.__len__(), sys.argv)
sys.exit(rc)

This will print something like:

$ python test.py 
    0.000005 test.py:39           trace_do         trace within interface func
    0.001231 test.py:49           main             this is at step 0
    0.101541 test.py:39           trace_do         trace within interface func
    0.101900 test.py:49           main             this is at step 1
    0.302469 test.py:39           trace_do         trace within interface func
    0.302828 test.py:49           main             this is at step 2

The trace_library_do() function at the top is an example of something that you can drop into a library, and then call it from other tracing functions. The relative depth value controls which entry in the python stack gets printed.

I showed pulling out a few other interesting values in that function, like the line number of start of the function, the total stack depth, and the full path to the file. I didn't show it, but the global and local variables in the function are also available in inspect, as well as the full stack trace to all other functions below yours. There is more than enough information with what I am showing above to make hierarchical call/return timing traces. It's actually not that much further to creating the main parts of your own source level debugger from here -- and it's all mostly just sitting there waiting to be used.

I'm sure someone will object that I'm using internal fields with data returned by the inspect structures, as there may well be access functions that do this same thing for you. But I found them in by stepping through this type of code in a python debugger, and they work at least here. I'm running python 2.7.12, your results might very if you are running a different version.

In any case, I strongly recommend that you import the inspect code into some python code of your own, and look at what it can provide you -- Especially if you can single step through your code in a good python debugger. You will learn a lot on how python works, and get to see both the benefits of the language, and what is going on behind the curtain to make that possible.

Full source level tracing with timestamps is a great way to enhance your understanding of what your code is doing, especially in more of a dynamic real time environment. The great thing about this type of trace code is that once it's written, you don't need debugger support to see it.

Answer 3

Just put the code you posted into a function:

from inspect import currentframe, getframeinfo

def my_custom_debuginfo(message):
    print getframeinfo(currentframe()).filename + ':' + str(getframeinfo(currentframe()).lineno) + ' - ', message

and then use it as you want:

# ... some code here ...
my_custom_debuginfo('what I actually want to print out here')
# ... more code ...

I recommend you put that function in a separate module, that way you can reuse it every time you need it.