Debugging in Python, part 4: Bugs in multi-file projects

MP 143: How do you find a bug in a larger project?

Note: This post is part of an ongoing series about debugging in Python. The posts in this series will only be available to paid subscribers for the first 6 weeks. After that they will be available to everyone. Thank you to everyone who supports my ongoing work on Mostly Python.

Debugging tends to be simpler when working in a single-file project, in part because the tracebacks are shorter. There's a small amount of information to work through when reading the traceback, and you can usually see where the issue is pretty quickly. You still have to do some thinking in order to figure out what's wrong with the code and how to fix it, but it doesn't usually take long to sort things out.

Most real-world projects, however, involve many .py files spread across multiple directories. In this post we'll look at a small project with a number of .py files, and see how a slightly longer traceback is structured. We'll continue to use py-bugger to introduce errors, so you can practice doing what you see here as much as you like.

Refactoring Dice Battle

In the last post we worked with a single-file project called dice_battle.py. That project had enough going on that it could be refactored into smaller parts. I won't walk through the entire refactoring process here, but I'll share a summary of the changes that were made:

• Before making any changes, I added a single end-to-end test. This test only focuses on the project's external behavior; it doesn't rely on the internal implementation at all. This is a great way to start testing a new project. If the overall behavior of the project changes, the test will fail and we'll know it. But we're free to change the internal structure and implementation of the project without having to rewrite any tests. We also won't have to figure out if a bunch of unit tests failed because critical behavior in the project is wrong, or if they failed because we've changed how we're doing things internally.
• Move the Die class to a separate file called die.py. This isolates the code specific to modeling a die, and it's a model that can grow if we want to model additional behavior related to dice.
• Move some of the functionality to a utils.py file. This moves implementation code out of the project's main file, leaving that file much more readable. It also moves us closer to being able to write an effective set of unit tests. Unit tests become appropriate once we have smaller functions that carry out specific tasks.

The original single-file dice_battle.py was about 50 lines long. After refactoring, we're left with a much smaller main file that's easier to reason about:

import utils

# Simulate some battles between players A and B.
num_battles = 10
results = {
    "wins_a": 0,
    "wins_b": 0,
    "ties": 0,
}

for _ in range(num_battles):
    a_result, b_result = utils.battle()
    print(f"\nPlayer A: {a_result}")
    print(f"Player B: {b_result}")

    utils.update_results(a_result, b_result, results)

utils.show_summary(results)

You can skim through this file and get a sense of what's happening. We're setting up 10 battles. We want to track results including wins for Player A, wins for Player B, and the number of ties. We then run a loop once for each battle. We call the utils.battle() function, and print the results. We then call the utils.update_results() function to update the overall results. When all the battles have been run, we call the utils.show_summary() function.

Running the new version of Dice Battle

If you want to follow along, you can download and run the refactored version of Dice Battle. There's a full set of instructions for downloading the project, setting up a local environment, running the file, running the tests, and running py-bugger against the project.

Introducing a bug

Let's use py-bugger to introduce a specific kind of error, in a specific file:

(.venv)$ py-bugger -e AttributeError --target-file die.py
Added bug.
All requested bugs inserted.

Here we're asking py-bugger to introduce a bug in the file die.py, which will generate an AttributeError. (See the notes at the end of this post if py-bugger doesn't seem to generate a bug in your version of the project.)

Reading a longer traceback

Now let's see what happens when we run the project again:

(.venv)$ python dice_battle.py 
Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

This traceback is longer than what we saw in the last post, for a couple reasons. First, Python is using carets (^^^) to show the specific parts of each line that seem to be involved in the error. But the bigger reason for the longer traceback is the execution path. Rather than one file, Python is running a number of files during the program's execution.

Even with a longer traceback, it's still a good idea to read through the output backwards. Let's focus on the last two lines:

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

This tells us the program failed to finish running because of an AttributeError. More specifically, the Die object we're working with doesn't have an attribute named num_sids, but we tried to use that attribute somewhere. Older versions of Python would stop there; newer versions suggest the name of the attribute you might have been looking for, if there's an existing attribute with a similar name. Here, Python is asking us if we meant to type num_sides, which is an attribute of the Die object.

That's a pretty good start. We probably made a typo when writing num_sides. But where? Let's look at the previous group of lines:

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

The problematic attribute num_sids appeared in line 19 of die.py. We wrote self.num_sids, which refers to an attribute that doesn't exist.

The fix

That's all we need to know in order to fix this bug. We can go into die.py, and fix the typo in num_sids:

@dataclass
class Die:
    ...
    
    def roll(self):
        """Roll the die."""
        return random.randint(1, self.num_sides)

Correcting this typo results in a successful run of dice_battle.py:

(.venv)$ python dice_battle.py
Player A: 2
Player B: 3
Player B won!
...

Summary:
  Player A won 5 battles.
  Player B won 5 battles.
  There were 0 tied battles.

Clearly, player A and player B are equals.

If you understand the structure of a traceback, you can fix many bugs without studying the entire traceback that's generated when a bug appears in a larger project.

Reading through a whole traceback

If it's a good idea to read backwards through a traceback, and you can often fix an issue by just reading the last few parts, why are they so long? Let's read the previous traceback through from beginning to end, and see what else it shows:

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

All tracebacks include a reminder that the most recent call is at the end.

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

The first line in the highlighted section here tells us that an issue came up when running dice_battle.py. Specifically, an error was generating when attempting to run line 19. That line involves a call to utils.battle(), which ultimately led to the problem. Again, newer versions of Python don't just show you the problematic line of code, they also point out the specific section of code that led to an error. Note that there isn't necessarily an error in line 19 of dice_battle.py. All we know right now is that this line was part of the execution path when the error occurred.

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

Next we see a reference to line 10 in utils.py, inside the battle() function. Again, we're pointed to the specific part of the line in that function that caused an issue. Here's, it's a call to die.roll().

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

Next, we see that line 19 of die.py, which is in the roll() method, is involved in the issue. This is the line we looked at earlier, which contains the typo num_sids.

Traceback (most recent call last):
  File "dice_battle.py", line 19, in <module>
    a_result, b_result = utils.battle()
                         ^^^^^^^^^^^^^^
  File "utils.py", line 10, in battle
    a_result = die.roll()
               ^^^^^^^^^^
  File "die.py", line 19, in roll
    return random.randint(1, self.num_sids)
                             ^^^^^^^^^^^^^
AttributeError: 'Die' object has no attribute 'num_sids'.
  Did you mean: 'num_sides'?

Finally, we see the specific exception that was raised. The AttributeError exception includes a templated message, "____ object has no attribute ____". Python fills in those blanks, to make it easier to resolve this specific bug. It also notices an actual attribute that looks similar to the one we requested, and makes a helpful suggestion based on that similarity.

The overall traceback shows you the full execution path that led to the error. This gives you all the code-specific information you need to find the issue. You may need more contextual understanding of the project you're working on to resolve the bug, and you almost certainly need to look at more code while debugging, but this is a listing of all the specific lines involved in the execution path when the problem occurred.

Understanding how to skim through a full traceback will be helpful when debugging more complex bugs, such as bugs that arise from within a project's dependencies. You'll rarely need to read every line of a traceback closely. But you'll often need to skim through the overall structure of the traceback, and read multiple sections more carefully based on your understanding of the project, and recent changes that may have been made.

As a side note, this also shows how much work the Python interpreter does every time you run a program. It doesn't just run each line of code it comes to. It has to keep track of what information might be needed if an exception is raised. If you're curious to hear more about this, check out episode 6 of the core.py podcast, An Exceptional Episode.

Bugs don't always cause immediate failure

In Python, a bug doesn't always cause an immediate failure. For example, consider this output when running dice_battle.py:

(.venv)$ python dice_battle.py      
Player A: 4
Player B: 6
Player B won!
...

Player A: 2
Player B: 5
Player B won!
Traceback (most recent call last):
  File "dice_battle.py", line 25, in <module>
    utils.show_sumary(results)
    ^^^^^^^^^^^^^^^^^
AttributeError: module 'utils' has no attribute 'show_sumary'.
  Did you mean: 'show_summary'?

Here there's a typo in the call to show_summary() near the end of the program. This bug doesn't affect the initial execution, so you see some successful output before the traceback. Python will carry out your program's execution as far as it can, until it runs into a specific line that causes an exception.

Some bugs don't cause any failure

Sometimes a bug doesn't cause any failure at all. This happens when the current execution path doesn't hit the buggy code.

For example, I ran py-bugger and it inserted a bug. But then the program ran successfully:

(.venv)$ python dice_battle.py
Player A: 2
Player B: 3
Player B won!
...

Summary:
  Player A won 5 battles.
  Player B won 5 battles.
  There were 0 tied battles.

Clearly, player A and player B are equals.

However, when I ran the tests there was a failure:

(.venv)$ pytest
...
tests/e2e_tests/test_basic_behavior.py:29: AssertionError

---------- Captured stdout call ----------------
Traceback (most recent call last):
  ...
  File "die.py", line 8, in <module>
    random.seedd(int(seed))
    ^^^^^^^^^^^^
AttributeError: module 'random' has no attribute 'seedd'.
  Did you mean: 'seed'?

========== short test summary info =============
FAILED test_basic_behavior
========== 1 failed in 0.04s ===================

In this case, the bug was added to a conditional block that only runs during testing:

# Set a random seed when testing.
if seed := os.environ.get("DICE_BATTLE_RANDOM_SEED"):
    random.seedd(int(seed))

Since the line with the bug in it only runs during testing, you'll only see an error when you run tests.

Most projects have a significant number of possible execution paths, depending on the current context. It's quite common to have bugs that only show up when specific conditions are present, and specific execution paths are followed.

Conclusions

Most real-world tracebacks are pretty long, because most real-world projects are made up of many .py files nested in multiple directory levels. Learning how to read a traceback, both backwards and forwards, goes a long way toward building an effective debugging process.

In the next post we'll look at what happens when there are multiple bugs in the same project. We'll look at the situation where fixing one bug just leads to a different error.

Resources

Instructions for setting up the version of Dice Battle used in this post can be found here.

Notes

When you run py-bugger, it will let you know if it was able to generate the kind of bug you requested. If the bug is not in the current execution path, you may not see an error the first time you run the program.

If this happens, try running the test suite to see if it picks up the bug. Or, if you started with a clean Git status, you can run git checkout . to remove the bug. py-bugger identifies a number of possible ways to generate the kind of bug you requested, and then chooses one randomly. This means it's likely to generate a bug that crashes your program within a couple tries.

If py-bugger reports that it inserted a bug and that's not accurate, please consider filing a report using the issue tracker.