Ayman Hourieh's Blog

This article covers several techniques for debugging Python programs. The applicability of these techniques ranges from simple scripts to complex applications. The topics that are covered include launching an interactive console from within your program, using the Python debugger, and implementing robust logging. Various tips are included along the way to help you debug and fix problems quickly and efficiently.

Launching an interactive console with code.interact()

The Python interactive console is an awesome tool for experimenting with Python code. It provides a read-eval-print loop that allows you to experiment with Python code easily and quickly, without having to write and run a complete program. Wouldn't be convenient if you could use the same technique to debug an existing program? Fortunately, this is already possible thanks to the code module. This module has a function called interact() that stops execution and gives you an interactive console to examine the current state of your program. To use this function, simply embed the following at the line were you want the console to start:

import code; code.interact(local=locals())

The resulting console inherits the local scope of the line on which code.interact() is called. This enables you to check the current state of your program to understand its behavior and make any necessary corrections.

To exit the interactive console and continue with the execution of your program, press Ctrl+D in Unix/Linux systems, or Ctrl+Z in Windows. Alternatively, you can type exit() in the console and hit enter to exit the console and abort your program.

Using the Python Debugger

When you need to examine the execution flow of your program, an interactive console is not going to be enough. For situations like this, you can use the Python debugger. It provides a full-fledged debugging environment that supports breakpoints, stepping through source code, stack inspection and much more. This debugger comes with the standard python distribution as a module named pdb.

To learn how to use pdb, let's write a simple program that calculates the first 10 Fibonacci numbers:

def main():
  low, high = 0, 1
  for i in xrange(10):
    print high
    low, high = high, low + high
 
if __name__ == '__main__':
  main()

Assuming that the file name is fib.py, we can run the program in pdb using the following command:

$ python -m pdb fib.py

The command results in the following output:

> fib.py(1)<module>()
-> def main():
(Pdb) 

The first line of output contains the current module name, line number and function name (function name currently appears as <module>() because we are still at module level). The second line of output contains the current line of source code that is being executed. pdb also provides an interactive console to debug the program. This console is different from the familiar Python console. You can see its commands by typing help and hitting enter. Also, typing help <command> gives you help on the command you provided. Let's learn about these commands.

Stepping through program execution

The list command prints a few lines of context around the current line. Let's give it a try:

(Pdb) list
  1  -> def main():
  2       low, high = 0, 1
  3       for i in xrange(10):
  4         print high
  5         low, high = high, low + high
  6  
  7     if __name__ == '__main__':
  8       main()
[EOF]

Next, let's step through our program. The next command executes the current line and moves next.

(Pdb) next
> fib.py(7)<module>()
-> if __name__ == '__main__':

At this point, the main() function has been defined, but not called. This is why the execution has jumped to the if condition on line 7. Let's call next again:

(Pdb) n
> fib.py(8)<module>()
-> main()

We are now about to call the main() function. Running next at this point will call main() and move to the next line. Since we are at the end of the file, this means that the program will finish executing. But we don't want this; we want to step into the main() function. To do this, we use the step command:

(Pdb) step
--Call--
> fib.py(1)main()
-> def main():

From here, you can continue calling next to step through the main(). If at some point you want to examine the value of a variable, you can use the pp command (short for pretty-print):

(Pdb) pp high
2

If you are done with examining the main() function, you can either use the continue command, which exits the debugging console and continues the execution of the program, or use the return, which continues the execution until the current function returns. Alternatively, you can stop the execution altogether and abort by using the exit command.

Setting breakpoints

Next, we will learn about breakpoints. More often than not, you want to invoke the debugger at a particular function or line number, rather than step through the execution of the whole program. To do so, you can set a breakpoint and continue the execution of the program. When the breakpoint is reached, the debugger is invoked.

To set a breakpoint, use the break command. It takes a file name and line number or function name. To break at line 4 in fib.py, use:

(Pdb) break fib.py:4

To break when the main() function is called, use:

(Pdb) break fib.main

Furthermore, you can attach a condition to the breakpoint. Execution breaks only if this condition is True. For example, to break at line 4 in fib.py when high is greater than 10, use:

(Pdb) break fib.py:4, high > 10

The best pdb tip

Now it's time for my favorite feature in pdb. It you put the following snippet somewhere in your program and run it normally, execution will stop and a debugging session will start when this line is reached:

import pdb; pdb.set_trace()

This approach is very convenient because it does not require launching your program in a special way or remembering to set breakpoints. You simply add the line above and start the program normally, and the debugger will be invoked exactly where you want. In practice, I think you will use this snippet to start pdb most of the time.

Summary of pdb commands and short forms

Finally, pdb commands have short forms. The following table summarizes the commands presented in this section, and their short forms:

Logging

A primitive way of debugging programs is to embed print statements through out the code to track execution flow and state. However, this approach can quickly become unmaintainable for a number of reasons:

• Normal program output is mixed with debugging output. This makes it difficult to distinguish between the two.
• There is no easy way to disable debugging output, or redirect it to a file.
• When done with debugging, it may be difficult to track down and remove all print statements that are scattered over the code.

Python provides an alternative to debug print statements that doesn't suffer from the shortcomings above. This alternative comes in the form of a module called logging, and it is very powerful and easy to use.

Let's start with a simple example. The following snippet imports the logging module and sets the logging level to debug:

import logging
 
logging.basicConfig(level=logging.DEBUG)

The call to logging.basicConfig() should be done once when your program starts. Now, whenever you want to print a debug message, call logging.debug():

logging.debug('This is a debug message.')

This will send the following string to stderr:

DEBUG:root:This is a debugging message.

DEBUG indicates that this is a debug message. root indicates that this is the root logger, as it is possible to have multiple loggers (don't worry about this for now).

Now we have a better logging system that can be globally switched on and off. To turn off debug messages, simply omit the level argument when calling logging.basicConfig():

logging.basicConfig()

Logging to a file and adding date/time

To take full advantage of the logging module, let's have a look at some of the options that can be provided to logging.basicConfig():

For example, to configure the logging module to send debug messages to a file called debug.log, use:

logging.basicConfig(level=logging.DEBUG, filename='debug.log')

Log messages will be appended to debug.log if the file already exists. This means that your log messages will be kept even if you run your program multiple times.

To add date/time to your log messages, use:

logging.basicConfig(level=logging.DEBUG, filename='debug.log',
                    format='%(asctime)s %(levelname)s: %(message)s',
                    datefmt='%Y-%m-%d %H:%M:%S')

This will result in log messages like the following:

2009-08-30 23:30:49 DEBUG: This is a debug message.

Logging levels

The logging supports multiple levels of log messages in addition to DEBUG. Here is the full list:

Setting the logging level to a value enables log messages for this level and all levels above it. So if you set the level to logging.WARNING, you will get WARNING, ERROR and CRITICAL messages. This allows you to have different levels of log verbosity.

Convenient template for logging

Before I conclude this section, I will provide a simple template for enabling logging functionality in your programs. This template uses command-line flags to change the level logging, which is more convenient that modifying source code.

import logging
import optparse
 
LOGGING_LEVELS = {'critical': logging.CRITICAL,
                  'error': logging.ERROR,
                  'warning': logging.WARNING,
                  'info': logging.INFO,
                  'debug': logging.DEBUG}
 
def main():
  parser = optparse.OptionParser()
  parser.add_option('-l', '--logging-level', help='Logging level')
  parser.add_option('-f', '--logging-file', help='Logging file name')
  (options, args) = parser.parse_args()
  logging_level = LOGGING_LEVELS.get(options.logging_level, logging.NOTSET)
  logging.basicConfig(level=logging_level, filename=options.logging_file,
                      format='%(asctime)s %(levelname)s: %(message)s',
                      datefmt='%Y-%m-%d %H:%M:%S')
 
  # Your program goes here.
  # You can access command-line arguments using the args variable.
 
if __name__ == '__main__':
  main()

By default, the logging module prints critical, error and warning messages. To change this so that all levels are printed, use:

$ ./your-program.py --logging=debug

To send log messages to a file called debug.log, use:

$ ./your-program.py --logging-level=debug --logging-file=debug.log