Debugging: Tracebacks, pdb and Strategy

Read the traceback first

def parse(raw):
    return int(raw)


def load(values):
    return [parse(v) for v in values]


def main():
    return load(["1", "2", "x"])


main()

Traceback (most recent call last):
  File "app.py", line 13, in <module>
    main()
  File "app.py", line 10, in main
    return load(["1", "2", "x"])
  File "app.py", line 6, in load
    return [parse(v) for v in values]
  File "app.py", line 2, in parse
    return int(raw)
ValueError: invalid literal for int() with base 10: 'x'

1. Read the last line. The exception type and message usually name the problem: a ValueError, and the offending value was 'x'.
2. Read the frame above it. That is where it happened: parse, line 2.
3. Walk upward only if needed. Those frames explain how you got there.

"Most recent call last" is literal: the deepest and most relevant frame sits at the bottom, immediately above the message.

Print debugging, done properly

def net_total(items, tax_rate):
    subtotal = sum(price * qty for price, qty in items)
    print(f"{items=}")
    print(f"{subtotal=} {tax_rate=}")
    total = subtotal * (1 + tax_rate)
    print(f"{total=}")
    return round(total, 2)


net_total([(100, 2), (50, 3)], 0.18)

The f-string = form prints the expression as well as the value, so a line can never be mislabelled. It is the fastest debugging tool in Python and needs no imports.

import sys

print("state:", value, file=sys.stderr)     # keep it out of piped output


def trace(**values):
    """Print several named values at once."""
    print("  " + "  ".join(f"{k}={v!r}" for k, v in values.items()), file=sys.stderr)


trace(user="meera", count=3, active=True)

Use !r when whitespace or type matters. value=5 and value='5' look identical without it, and that distinction is very often the bug.

The debugger

def net_total(items, tax_rate):
    subtotal = sum(price * qty for price, qty in items)
    breakpoint()                     # Python 3.7+; equivalent to pdb.set_trace()
    total = subtotal * (1 + tax_rate)
    return round(total, 2)


net_total([(100, 2)], 0.18)

> app.py(4)net_total()
-> total = subtotal * (1 + tax_rate)
(Pdb)

(Pdb) p subtotal
200
(Pdb) p tax_rate
0.18
(Pdb) p subtotal * (1 + tax_rate)
236.0
(Pdb) a
items = [(100, 2)]
tax_rate = 0.18
(Pdb) w
(Pdb) c

Inside the debugger you can evaluate any expression, including calling functions. It is a Python prompt with your program's state loaded into it.

Post mortem debugging

$ python -m pdb app.py            run under the debugger from the start
$ python -m pdb -c continue app.py    run normally, drop into pdb on a crash

import pdb
import sys

try:
    result = 1 / 0
except Exception:
    pdb.post_mortem(sys.exc_info()[2])       # inspect the state at the crash

Conditional breakpoints

for index, record in enumerate(records):
    if record.get("status") == "unexpected":
        breakpoint()                          # stop only on the interesting case
    process(record)

(Pdb) b app.py:42, count > 100        break at line 42 only when the condition holds

$ PYTHONBREAKPOINT=0 python app.py         disable every breakpoint() call

Logging instead of printing

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(levelname)-8s %(funcName)s:%(lineno)d  %(message)s",
)

logger = logging.getLogger(__name__)


def process(records):
    logger.info("processing %d records", len(records))
    for index, record in enumerate(records):
        logger.debug("record %d: %r", index, record)
        try:
            handle(record)
        except Exception:
            logger.exception("record %d failed", index)      # includes the traceback


def handle(record):
    if not record:
        raise ValueError("empty record")


process([{"a": 1}, {}, {"b": 2}])

Unlike print, logging can be turned down to WARNING without editing code, records where the message came from, and logger.exception captures the full traceback inside an except block.

A method for finding bugs

1. Reproduce it reliably. A bug you cannot repeat cannot be verified as fixed.
2. Reduce it. Cut the input and the code until the smallest thing that still fails remains.
3. Form one hypothesis. "The list is empty by the time it reaches here."
4. Test that hypothesis. Print it, assert it, or inspect it in the debugger.
5. Change one thing. Then re-check. Two changes at once tell you nothing.
6. Write a test that fails, then fix the code, then watch it pass.

def process(records):
    assert isinstance(records, list), f"expected a list, got {type(records)}"
    assert records, "records must not be empty"
    result = [transform(r) for r in records]
    assert len(result) == len(records), "transform dropped records"
    return result

An assertion states an assumption. When it fails, the program stops at the moment the assumption broke rather than several functions later, where the symptom appears.

Bisecting

def find_bad_record(records, process):
    """Narrow a failing batch down to the single record responsible."""
    if len(records) == 1:
        return records[0]

    middle = len(records) // 2
    first, second = records[:middle], records[middle:]

    try:
        process(first)
    except Exception:
        return find_bad_record(first, process)

    return find_bad_record(second, process)

Halving the input each time finds the culprit among a million records in about twenty steps. The same idea applied to commits is what git bisect does.

Common bugs and how they look

def add_item(item, basket=[]):        # the classic
    basket.append(item)
    return basket


print(add_item("a"))       # ['a']
print(add_item("b"))       # ['a', 'b']  <- the bug reveals itself on the SECOND call

Inspecting at runtime

import inspect


def investigate(obj):
    print("type:      ", type(obj).__name__)
    print("attributes:", [a for a in dir(obj) if not a.startswith("_")][:10])
    if hasattr(obj, "__dict__"):
        print("state:     ", vars(obj))
    if callable(obj):
        print("signature: ", inspect.signature(obj))
    print("doc:       ", (inspect.getdoc(obj) or "")[:60])


investigate(sorted)

import traceback


def where_am_i():
    for line in traceback.format_stack()[:-1]:
        print(line.strip().splitlines()[0])


def a():
    b()


def b():
    where_am_i()


a()

Warnings that catch bugs early

python -W error app.py           turn warnings into exceptions
python -X dev app.py             development mode: extra checks
python -X tracemalloc app.py     include allocation tracebacks

Common mistakes

• Reading the traceback from the top and fixing the wrong function.
• Changing several things at once and losing track of what fixed it.
• Leaving print statements in committed code.
• Guessing instead of checking a specific hypothesis.
• Fixing the symptom rather than the cause.
• Not writing a test after the fix, so the bug can return.
• Debugging on the full input when a smaller case would fail just as well.

Best practices

• Read the last line of the traceback first, then the frame above it.
• Use f"{value=}" for quick checks and logging for anything that stays.
• Use breakpoint() when you need to explore state rather than confirm one value.
• Reduce the failing case before investigating it.
• Change one thing at a time.
• End every bug hunt with a test.

Practice

1. Take a three level traceback and identify the failing line, the cause and the call path.
2. Use breakpoint() to inspect the state of a function midway through.
3. Add assertions to a function so a wrong assumption fails immediately.
4. Write a bisecting helper that finds the one bad record in a list of a thousand.
5. Convert a set of print debug statements into proper logging with levels.

Conclusion

Debugging is a method, not a tool: reproduce, reduce, hypothesise, check, change one thing, then write the test. The traceback tells you where; f"{x=}" and breakpoint() tell you what; only you can work out why.