PDB style function backtrace in python using Inspect module.

A while back I had a conversation with a friend of mine, which went something like this(with some paraphrasing).

Friend : Hey, is there a way in python to display the function calls which end up calling a certain function, kind of like a function call flow but displaying only the ones which call a certain function.
Me : Have you tried a python debugger like PDB? Check out the backtrace command.
Friend : Oh, I Don’t have any idea about PDB, and there are only few such functions, I don’t need any other debugger functionality, Debugger may be bit of a overkill here.
Me : Oh Ok, Let me see what I can do!!.

I found it to be the perfect excuse to play with Inspect Module, which provides several useful functions to help get information about live objects in a running program.
About 5 minutes later, I had the working code. (Isn’t python Freakin Awesome!!)

import inspect
def getBackTrace():
    for idx, frame in enumerate(inspect.stack()[1:-1]):
        print '#%d  %s at %s'%(idx, frame[3], frame[1])

Suffice it to say, that his problem was solved. Now he can just invoke getBackTrace() to get the list of functions in outer frames from within a function. 🙂

On my way back home that day, I thought that this could be a good utility for someone who loves to read other people code, but considers a full debugging session a overkill to get a better understanding of the unfamiliar code.You can also think of it as a addition to the old school Printf Debugging.FWIW, If it’s well written code in python, most of the times you will just get what the code is trying to do. Python code is really just executable pseudo-code.

My friend suggested that I should add this code to my collection of Gists@github. I asked him if he can think of some other features I should be adding to this code. After some talking, we narrowed down to the following two nice-to-have features.

  • Add some more context, by printing function arguments, source code line number for each of the frames.
  • The ability to log this information to a external log file, defaulting to the standard outstream.

It took me some more time to do the code/testing, but it was worth the effort. Overall what’s really great about this utility function is that tracing a function call is as easy as putting @getBackTrace() decorator before the function definition and just run the code. The other ( rather tedious) way is to start a pdb debugger session, setting the function breakpoint, running the code and then inspecting the stack once breakpoint is reached. So choose the way you like ;). Here is the code. (Tip: Looks a lot better @Github)

import sys, inspect
def getBackTrace(printArgs=None , logger=sys.stdout.write):
    '''
    This decorator method can be used to get GDB style backtrace (Stack trace) of 
    currently active stack frames during the execution of a program, 
    optionally printing positional/variable/keyword arguments for the 
    functions in the outer frames.
    It can be used to easily trace the function call flow in a running application, 
    without having to use a external debugger like pdb.
    
    @Input
      printArgs - This is a boolean value which is true/false depending on 
                  whether function arguments need to be displayed.
      logger    - This can be a python logger instance to log information to a log file.
                  By default information is printed on stdout.
    @Output
      Output is similar to GNU Debugger Stack traces, the difference being 
      in the way arguments are displayed.
      More info on GDB backtrace command here - 
      http://inside.mines.edu/fs_home/lwiencke/elab/gdb/gdb_42.html

    Note: AFAIK, Once a function is called with the respective arguments, 
    these arguments become part of locals() function scope in python, and they can be 
    mutated by function code. So, the argument values may be **DIFFERENT**
    than what the function initially may have got and I am only displaying 
    values the variables had at the time stack trace was done.
    
    '''
    log = logger or logger.debug
    log('*'*50 + ' BackTrace START ' + '*'*50+'\n')
    def wrap(f):
        log("#0   %s at %s\n"%(f.__name__, f.__module__))
        def wrapped_f(*args, **kwargs):
            outerFrames = inspect.stack()[1:-1]
            for frame_idx, frame in enumerate(outerFrames):
                functionName = frame[3]
                moduleName = inspect.getmodulename(frame[1]) or frame[1]
                traceStr = "#%d   %s at %s:%s\n"%(frame_idx+1, functionName, 
                                                  moduleName, frame[2])
                if printArgs:
                    argObj = inspect.getargvalues(frame[0])
                    posArgs = sorted([ [arg, argObj.locals.get(arg)] for \
                                       arg in argObj.args or []])
                    varArgs = sorted(argObj.locals.get(argObj.varargs,{}))
                    keywordArgs = sorted(argObj.locals.get(argObj.keywords,{}).items())

                    prettyArgsString = ', '.join('%s=%s'%(str(item[0]), 
                                                          str(item[1])) for item in posArgs)
                    prettyVarArgsString = ', '.join('%s'%(str(item)) for item in varArgs)
                    prettyKeywordArgsString = ', '.join('%s=%s'%(str(item[0]), 
                                                                 str(item[1])) for item in keywordArgs)

                    traceStr+="%-10sPositional Arguments : %s\n"%('',prettyArgsString)
                    traceStr+="%-10s*Variable Aruguments : %s\n"%('',prettyVarArgsString)
                    traceStr+="%-10s**Keyword Arguments  : %s\n"%('',prettyKeywordArgsString)
                    traceStr+= '\n'
                log(traceStr)
            log('\n')
            log('*'*50 + ' BackTrace END ' + '*'*50+'\n\n')
            f(*args, **kwargs) #Call the function
        return wrapped_f
    return wrap



#################################
## Example Usage
## Output
"""
#0   func3 at __main__
#1   func2 at getBackTrace:67
          Positional Arguments : i=10000
          *Variable Aruguments : 1230, 12345
          **Keyword Arguments  : oi=20

#2   func1 at getBackTrace:64
          Positional Arguments : i=100
          *Variable Aruguments : 
          **Keyword Arguments  : 


"""
def func1(i):
    func2(i**2, 1230, 12345, oi=20)

def func2(i, *args, **kwargs):
    func3(i**2)

#@getBackTrace()
@getBackTrace(printArgs=True)
def func3(i, **kwargs):
    pass

if __name__ == '__main__':
    func1(100)

If you are thinking of some other Nice-to-have features, The code is just one Fork away, or give me a shoutout in the comments below.

Advertisements

About Ashish Yadav

Hey there!!! I am Ashish Yadav, a Geek | Music Lover | Open Web enthusiast | Wannabe entrepreneur. I currently live in Chennai, India and share my thoughts, nifty hacks rather infrequently here with rest of the world. If you like my posts, may I suggest subscribing to the blog to read them as they are written :) . As a part of my day job I enjoy writing ubercool python code, and have loads of fun while at it. Opinions presented here are mine and not to be associated with my employer or anyone else. Opinions presented here are mine and not to be associated with my employer or anyone else.
This entry was posted in code, hack and tagged , , , , , , , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s