Debugging techniques

In this part, we will introduce you to some of the techniques we use most often. This is not an exhaustive list, but it should give you some useful ideas for where to start when debugging your own Python code.

Debugging with print

The key to understanding any bug is to understand what your code is doing at the point where the bug occurs. For this reason, we will be looking at a few different techniques for inspecting the state of a program while it is running.

The easiest technique of all is to add print() calls at various points in your code. This allows you to easily see which parts of your code are executed, and what the values of key variables are at different points during execution. For example, if you are developing a Django website and what happens on a page is not what you would expect, you can fill the view with prints and keep an eye on the console while you reload the page.

There are several drawbacks and limitations to using print() for debugging. To use this technique, you need to be able to modify the source code and run it in a terminal where you can see the output of your print() function calls. This is not a problem in your development environment on your own machine, but it does limit the usefulness of this technique in other environments.

When you scatter calls to print() in your code, you can easily end up duplicating a lot of debugging code. For example, you may want to print timestamps (like we did when we were measuring how fast list comprehensions and generators were), or somehow build up a string with the information that you want to display. Another disadvantage of this technique is that it is easy to forget calls to print() in your code.

For these reasons, we sometimes prefer to use a custom debugging function rather than just bare calls to print(). Let us see how.

Debugging with a custom function

Having a custom debugging function saved in a file somewhere that you can quickly grab and paste into the code can be particularly useful. If you are fast, you can also code one on the fly. The important thing is to write it in such a way that it will not leave anything behind when you eventually remove the calls and their definitions. Therefore, it is important to code it in a way that is completely self-contained. Another good reason for this requirement is that it will avoid potential name clashes with the rest of the code.

Let us see an example of such a function:

# custom.py
def debug(*msg, print_separator=True):
    print(*msg)
    if print_separator:
        print("-" * 40)
debug("Data is ...")
debug("Different", "Strings", "Are not a problem")
debug("After while loop", print_separator=False)

In this case, we are using a keyword-only argument to be able to print a separator, which is a line of 40 dashes.

The function just passes whatever is in msg to a call to print() and, if print_separator is True, it prints a line separator. Running the code will show the following:

$ python custom.py
Data is ...
----------------------------------------
Different Strings Are not a problem
----------------------------------------
After while loop

As you can see, there is no separator after the last line.

This is just one easy way to augment a simple call to the print() function. Let us see how we can calculate a time difference between calls, using one of Python’s tricky features to our advantage:

# custom_timestamp.py
from time import sleep
def debug(*msg, timestamp=[None]):
    from time import time  # local import
    print(*msg)
    if timestamp[0] is None:
        timestamp[0] = time()  # 1
    else:
        now = time()
        print(f" Time elapsed: {now - timestamp[0]:.3f}s")
        timestamp[0] = now  # 2
debug("Entering buggy piece of code...")
sleep(0.3)
debug("First step done.")
sleep(0.5)
debug("Second step done.")

This is a bit more complicated. First, notice that we used an import statement inside the debug() function to import the time() function from the time module. This allows us to avoid having to add that import outside the function and risk forgetting to remove it.

Look at how we defined timestamp. It is a function parameter with a list as its default value. In Chapter 4, Functions, the Building Blocks of Code, we warned against using mutable defaults for parameters because the default value is initialized when Python parses the function, and the same object persists across different calls to the function. Most of the time, this is not the behavior you want. In this case, however, we are taking advantage of this feature to store a timestamp from the previous call to the function, without having to use an external global variable. We borrowed this trick from our studies on closures, a technique that we encourage you to read about.

After printing the message, we inspect the content of the only item in timestamp. If it is None, we have no previous timestamp, so we set the value to the current time (#1). On the other hand, if we have a previous timestamp, we can calculate a difference (which we neatly format to three decimal digits), and finally, we put the current time in timestamp (#2).

Running this code outputs the following:

$ python custom_timestamp.py
Entering buggy piece of code...
First step done.
 Time elapsed: 0.300s
Second step done.
 Time elapsed: 0.500s

Using a custom debug function solves some of the problems associated with just using print(). It reduces duplication of debugging code and makes it easier to remove all your debugging code when you no longer need it. However, it still requires modifying the code and running it in a console where you can inspect the output. Later in this chapter, we will see how we can overcome those difficulties by adding logging to our code.

Using the Python debugger

Another effective way of debugging Python is to use an interactive debugger. The Python standard library module pdb provides such a debugger; however, we usually prefer to use the third-party pdbpp package. pdbpp is a drop-in replacement for pdb, with a somewhat friendlier user interface and some handy additional tools, our favorite of which is sticky mode, which allows you to see a whole function while you step through its instructions.

There are a few different ways to activate the debugger (if you have the pdbpp package installed, it will be loaded instead of the standard pdb debugger). The most common approach is to add a call invoking the debugger to your code. This is known as adding a breakpoint to the code.

When the code is run and the interpreter reaches the breakpoint, execution is suspended, and you get console access to an interactive debugger session. You can then inspect all the names in the current scope, and step through the program one line at a time. You can also alter data on the fly to change the flow of the program.

As a toy example, suppose we have a program that receives a dictionary and a tuple of keys as input. It then processes the dictionary items with the given keys. The program is raising a KeyError because one of the keys is missing from the dictionary. Suppose we cannot control the input (perhaps it comes from a third-party API), but we want to get past the error so that we can verify that our program would behave correctly on valid input. Let us see how we could use the debugger to interrupt the program, inspect and fix the data, and then allow execution to proceed:

# pdebugger.py
# d comes from an input that we do not control
d = {"first": "v1", "second": "v2", "fourth": "v4"}
# keys also comes from an input we do not control
keys = ("first", "second", "third", "fourth")
def do_something_with_value(value):
    print(value)
for key in keys:
    do_something_with_value(d[key])
print("Validation done.")

As you can see, this code will break when key gets the value "third", which is missing from the dictionary. Remember, we’re pretending that both d and keys come from an input source that we cannot control. If we run the code as it is, we get the following:

$ python pdebugger.py
v1
v2
Traceback (most recent call last):
  File ".../ch11/pdebugger.py", line 13, in <module>
    do_something_with_value(d[key])
                            ~^^^^^
KeyError: 'third'

We see that that key is missing from the dictionary, but since every time we run this code, we may get a different dictionary or keys tuple, this information does not really help us. We want to inspect and modify the data while the program is running, so let us insert a breakpoint just before the for loop. In modern versions of Python, the simplest way of doing this is to call the built-in breakpoint() function:

breakpoint()

Before Python 3.7, you would have needed to import the pdb module and call the pdb.set_trace() function:

import pdb; pdb.set_trace()

Note that we have used a semi-colon to separate multiple statements on the same line. PEP 8 discourages this, but it is quite common when setting a breakpoint like this, as there are fewer lines to remove when you no longer need the breakpoint.

The breakpoint() function calls sys.breakpointhook(), which, in turn, calls pdb.set_trace(). You can override the default behavior of sys.breakpointhook() by setting the PYTHONBREAKPOINT environment variable to point to an alternative function to import and call instead of pdb.set_trace().

The code for this example is in the pdebugger_pdb.py module. If we now run this code, things get interesting (note that your output may vary a little and that all the comments in this output were added by us):

$ python pdebugger_pdb.py
[0] > .../ch11/pdebugger_pdb.py(17)<module>()
-> for key in keys:
(Pdb++) l
 16
 17 -> for key in keys:  # breakpoint comes in
 18 do_something_with_value(d[key])
 19
(Pdb++) keys  # inspect the keys tuple
('first', 'second', 'third', 'fourth')
(Pdb++) d.keys()  # inspect keys of d
dict_keys(['first', 'second', 'fourth'])
(Pdb++) d['third'] = 'placeholder'  # add missing item
(Pdb++) c  # continue
v1
v2
placeholder
v4
Validation done.

First, note that when you reach a breakpoint, you are served a console that tells you where you are (the Python module) and which line is the next one to be executed. You can, at this point, perform some exploratory actions, such as inspecting the code before and after the next line, printing a stack trace, and interacting with the objects. In our case, we first inspect the keys tuple. We also inspect the keys of d. We see that 'third' is missing, so we put it in ourselves (could this be dangerous? Think about it.). Finally, now that all the keys are in, we type c to continue normal execution.

The debugger also gives you the ability to execute your code one line at a time using the n command (for next). You can use the s command to step into a function for deeper analysis or set additional breakpoints with the b command. For a complete list of commands, please refer to the documentation (which you can find at https://docs.python.org/3.12/library/pdb.html) or type h (for help) in the debugger console.

You can see, from the output of the preceding run, that we could finally get to the end of the validation.

pdb (or pdbpp) is an invaluable tool that we use every day. So, please experiment with it. Set a breakpoint somewhere and try to inspect it, follow the official documentation, and try the commands in your code to see their effect and learn them well.

Notice that, in this example, we have assumed you installed pdbpp. If that is not the case, then you might find that some commands behave a bit differently in plain pdb. One example is the letter d, which pdb interprets as the down command. To get around that, you would have to add an ! in front of d to tell pdb that it is meant to be interpreted literally, and not as a command.

Inspecting logs

Another way of debugging a misbehaving application is to inspect its logs. A log is an ordered list of events that occurred or actions that were taken during the running of an application. If a log is written to a file on disk, it is known as a log file.

Using logs for debugging is, in some ways, similar to adding print() calls or using a custom debug function. The key difference is that we typically add logging to our code from the start to aid future debugging, rather than adding it during debugging and then removing it again. Another difference is that logging can easily be configured to output to a file or a network location. These two aspects make logging ideal for debugging code that is running on a remote machine that you might not have direct access to.

The fact that logging is usually added to the code before a bug has occurred does pose the challenge of deciding what to log. We would typically expect to find entries in the logs corresponding to the start and completion (and potentially also intermediate steps) of any important process that takes place within the application. The values of important variables should be included in these log entries. Errors also need to be logged so that if a problem occurs, we can inspect the logs to find out what went wrong.

Nearly every aspect of logging in Python can be configured in various ways. This gives us a lot of power, as we can change where logs are output to, which log messages are output, and how log messages are formatted, simply by changing the logging configuration and without changing any other code. The four main types of objects involved in logging in Python are:

• Loggers: Expose the interface that the application code uses directly
• Handlers: Send the log records (created by loggers) to the appropriate destination
• Filters: Provide a finer-grained facility for determining which log records to output
• Formatters: Specify the layout of the log records in the final output

Logging is performed by calling methods on instances of the Logger class. Each line you log has a severity level associated with it. The most commonly used levels are DEBUG, INFO, WARNING, ERROR, and CRITICAL. Loggers use these levels to determine which log messages to output. Anything below the logger’s level will be ignored. This means that you must take care to log at the appropriate level. If you log everything at the DEBUG level, you will need to configure your logger at (or below) the DEBUG level to see any of your messages. This can quickly result in your log files becoming extremely large. A similar problem occurs if you log everything at the CRITICAL level.

Python gives you several choices of where to log to. You can log to a file, a network location, a queue, a console, your operating system’s logging facilities, and so on. Where you send your logs will typically depend very much on the context. For example, when you run your code in your development environment, you will typically log to your terminal. If your application runs on a single machine, you might log to a file or send your logs to the operating system’s logging facilities.

On the other hand, if your application uses a distributed architecture that spans multiple machines (such as in the case of service-oriented or microservice architectures), it is better to implement a centralized solution for logging so that all log messages coming from each service can be stored and investigated in a single place. This makes debugging much easier because trying to correlate giant files from multiple sources to figure out what went wrong can become truly challenging.

A service-oriented architecture (SOA) is an architectural pattern in software design in which application components provide services to other components via a communications protocol, typically over a network. The beauty of this system is that, when coded properly, each service can be written in the most appropriate language to serve its purpose. The only thing that matters is the communication with the other services, which needs to happen via a common format so that data exchange can be done.

Microservice architectures are an evolution of SOAs but follow a different set of architectural patterns.

The downside of the configurability of Python’s logging is that the logging machinery is somewhat complex. Fortunately, the defaults are often sufficient, and you only need to override settings when you have a specific need for customization. Let us see a simple example of logging a few messages to a file:

# log.py
import logging
logging.basicConfig(
    filename="ch11.log",
    level=logging.DEBUG, 
    format="[%(asctime)s] %(levelname)s: %(message)s",
    datefmt="%m/%d/%Y %I:%M:%S %p")
mylist = [1, 2, 3]
logging.info("Starting to process 'mylist'...")
for position in range(4):
    try:
        logging.debug(
            "Value at position %s is %s",
            position,
            mylist[position]
        )
    except IndexError:
        logging.exception("Faulty position: %s", position)
logging.info("Done processing 'mylist'.")

First, we import the logging module, then we set up a basic configuration. We specify a filename, configure the logger to output any log messages with the level DEBUG or higher, and set the message format. We want to log the date and time information, the level, and the message.

With the configuration in place, we can start logging. We start by logging an info message that tells us we are about to process our list. Inside the loop, we will log the value at each position (we use the debug() function to log at the DEBUG level). We use debug() here so that we can filter out these logs in the future (by configuring the logger’s level to logging.INFO or more) because we might have to handle large lists, and we do not want to always log all the values.

If we get IndexError (and we do, since we are looping over range(4)), we call logging.exception(), which logs at the ERROR level, but also outputs the exception traceback.

At the end of the code, we log another info message to say that we are done. After running this code, we will have a new ch11.log file with the following content:

# ch11.log
[10/06/2024 10:08:04 PM] INFO: Starting to process 'mylist'...
[10/06/2024 10:08:04 PM] DEBUG: Value at position 0 is 1
[10/06/2024 10:08:04 PM] DEBUG: Value at position 1 is 2
[10/06/2024 10:08:04 PM] DEBUG: Value at position 2 is 3
[10/06/2024 10:08:04 PM] ERROR: Faulty position: 3
Traceback (most recent call last):
  File ".../ch11/log.py", line 20, in <module>
    mylist[position],
    ~~~~~~^^^^^^^^^^
IndexError: list index out of range
[10/06/2024 10:08:04 PM] INFO: Done processing 'mylist'.

This is precisely what we need to be able to debug an application that is running on a remote machine, rather than our own development environment. We can see what our code did, the traceback of any exception raised, and so on.

Feel free to modify the logging levels in the previous example, both the code and the configuration. This way, you’ll be able to see how the output changes according to your setup.

The example presented here only scratches the surface of logging. For a more in-depth explanation, you can find information in the Python HOWTOs section of the official Python documentation: Logging HOWTO and Logging Cookbook.

Logging is an art. You need to find a good balance between logging everything and logging nothing. Ideally, you should log anything that you need to make sure your application is working correctly, and possibly all errors or exceptions.

Other techniques

We will end this section on debugging by briefly mentioning a couple of other techniques that you may find useful.

Reading tracebacks

Bugs often manifest as unhandled exceptions. The ability to interpret an exception traceback is therefore a crucial skill for successful debugging. Make sure that you have read and understood the section on tracebacks in Chapter 7, Exceptions and Context Managers. If you are trying to understand why an exception happened, it is often useful to inspect the state of your program (using the techniques we discussed above) at the lines mentioned in the traceback.

Assertions

Bugs are often the result of incorrect assumptions in our code. Assertions can be helpful for validating those assumptions. If our assumptions are valid, the assertions pass and execution proceeds normally. If they are not, we get an exception telling us which of our assumptions are incorrect. Sometimes, instead of inspecting with a debugger or print() statements, it is quicker to drop a couple of assertions in the code just to exclude possibilities. Let us see an example:

# assertions.py
mylist = [1, 2, 3]  #  pretend this comes from an external source
assert 4 == len(mylist)  # this will break
for position in range(4):
    print(mylist[position])

In this example, we pretend that mylist comes from some external source that we do not control (maybe user input). The for loop assumes that mylist has four elements and we have added an assertion to validate that assumption. When we run the code, the result is this:

$ python assertions.py
Traceback (most recent call last):
  File ".../ch11/assertions.py", line 4, in <module>
    assert 4 == len(mylist)  # this will break
           ^^^^^^^^^^^^^^^^
AssertionError

This tells us exactly where the problem is.

Running a program with the -O flag active will cause Python to ignore all assertions. This is something to keep in mind if our code depends on assertions to work.

Assertions also allow for a longer format that includes a second expression, such as:

assert expression1, expression2

The second expression is passed to the AssertionError exception raised by the statement. It is typically a string with an error message. For example, if we changed the assertion in the last example to the following:

assert 4 == len(mylist), f"Mylist has {len(mylist)} elements"

the result would be:

$ python assertions.py
Traceback (most recent call last):
  File ".../ch11/assertions.py", line 19, in <module>
    assert 4 == len(mylist), f"Mylist has {len(mylist)} elements"
           ^^^^^^^^^^^^^^^^
AssertionError: Mylist has 3 elements

Where to find information

The official Python documentation contains a section dedicated to debugging and profiling. There, you can read about the bdb debugger framework and about modules such as faulthandler, timeit, trace, tracemalloc, and pdb.

Let us now explore some troubleshooting guidelines.