14.3 Tracing Expressions and Comments in Debug Mode

Credit: Olivier Dagenais

14.3.1 Problem

You are coding a program that cannot use an interactive, step-by-step debugger, so you need detailed logging of state and control flow to perform debugging effectively despite this.

14.3.2 Solution

The extract_stack function from the traceback module is the key here, as it lets our code easily perform runtime introspection to find out about the code that called it:

import types, string, sys
from traceback import *

traceOutput = sys.stdout
watchOutput = sys.stdout
rawOutput = sys.stdout

""" Should print out something like:
File "trace.py", line 57, in _ _testTrace
  secretOfUniverse <int> = 42
"""
def watch(variableName):
    if _ _debug_ _:
        stack = extract_stack(  )[-2:][0]
        actualCall = stack[3]
        if actualCall is None:
            actualCall = "watch([unknown])"
        left = string.find(actualCall, '(')
        right = string.rfind(actualCall, ')')
        paramDict = {}
        paramDict["varName"]    = string.strip(
            actualCall[left+1:right]) # all from '(' to ')'
        paramDict["varType"]    = str(type(variableName))[7:-2]
        paramDict["value"]      = repr(variableName)
        paramDict["methodName"] = stack[2]
        paramDict["lineNumber"] = stack[1]
        paramDict["fileName"]   = stack[0]
        outStr = 'File "%(fileName)s", line %(lineNumber)d, in' \
                 ' %(methodName)s\n   %(varName)s <%(varType)s>' \
                 ' = %(value)s\n\n'
        watchOutput.write(outStr % paramDict)

""" Should print out something like:
File "trace.py", line 64, in ?
  This line was executed!
"""
def trace(text):
    if _ _debug_ _:
        stack = extract_stack(  )[-2:][0]
        paramDict = {}
        paramDict["methodName"] = stack[2]
        paramDict["lineNumber"] = stack[1]
        paramDict["fileName"]   = stack[0]
        paramDict["text"]       = text
        outStr = 'File "%(fileName)s", line %(lineNumber)d, in' \
                 ' %(methodName)s\n  %(text)s\n\n'
        traceOutput.write(outStr%paramDict)

""" Should print out something like:
   Just some raw text
"""
def raw(text):
    if _ _debug_ _:
        rawOutput.write(text)

14.3.3 Discussion

Many different programs don't make it easy to use traditional, interactive step-by-step debuggers. Examples include CGI programs; servers intended to be accessed from the Web and/or via protocols such as sockets, XML-RPC, and SOAP; and Windows services and Unix daemons.

Of course, you can remedy this by sprinkling a bunch of print statements all through the program, but this is unsystematic and needs clean-up when a given problem is fixed. This recipe shows that a better-organized approach is quite feasible, by supplying a few functions that allow you to output the value of an expression, a variable, or a function call, with scope information, trace statements, and general comments.

The key is the extract_stack function from the traceback module. traceback.extract_stack returns a list of tuples with four items�giving the filename, line number, function name, and source code of the calling statement�for each call in the stack. Item [-2] (the penultimate item) of this list is the tuple of information about our direct caller, and that's the one we use in this recipe to prepare the information to emit on file-like objects bound to the traceOutput and watchOutput variables.

If you bind the traceOutput, watchOutput, or rawOutput variables to an appropriate file-like object, each kind of output is redirected appropriately. When _ _debug_ _ is false (i.e., when you run the Python interpreter with the -O or -OO switch), all the debugging-related code is automatically eliminated. And this doesn't even make your byte-code any larger, because the compiler knows about the _ _debug_ _ variable.

Here is a usage example, leaving all output streams on standard output, in the form we'd generally use to make such a module self-testing, by appending the example at the end of the module:

def _ _testTrace(  ):
    secretOfUniverse = 42
    watch(secretOfUniverse)

if _ _name_ _ == "_ _main_ _":
    a = "something else"
    watch(a)
    _ _testTrace(  )

    trace("This line was executed!")
    raw("Just some raw text...")

When run with just python (no -O switch), this emits:

File "trace.py", line 61, in ?
  a <str> = 'something else'
File "trace.py", line 57, in _ _testTrace
  secretOfUniverse <int> = 42
File "trace.py", line 64, in ?
  This line was executed!
Just some raw text...

This recipe is meant to look very much like the traceback information printed by good old Python 1.5.2 and to be compatible with any version of Python. It's easy to modify the formats to your liking, of course.

14.3.4 See Also

Recipe 14.4 and Recipe 14.5; documentation on the traceback standard library module in the Library Reference; the section on the _ _debug_ _ flag in the Language Reference.