Testing and debugging · about 50 min

Debugging: tracebacks, print and logging

Why this matters

Every programmer writes bugs; what separates beginners from experienced engineers is how quickly and calmly they find them. Debugging is not staring at code hoping the mistake jumps out. It is a method, much like a scientific experiment: observe, form a hypothesis, test it, repeat. This lesson gives you that method and three everyday tools: reading tracebacks properly, printing the right things, and the logging module, which is what real programs use instead of scattered prints.

The method

When a program misbehaves:

Reproduce the problem reliably. Find the exact input that triggers it and a single command that shows it. A bug you cannot reproduce, you cannot confirm fixed.
Read the evidence. If there is a traceback, read all of it (below). If there is wrong output, write down exactly how it differs from what you expected.
Isolate. Shrink the input and the code until the bug is in a small region. Cut the 10,000-line input in half: does it still fail? Keep the failing half. Comment out steps. Call the suspicious function directly with one value.
Hypothesize, then test the hypothesis. "I think scores holds strings, so max compares text." Check it with one targeted print or one experiment in the REPL. If wrong, discard the idea and form another; do not change code at random.
Fix the cause, not the symptom, and add a test that would have caught it (a regression test, from the first lesson of this module).

The most common debugging failure is skipping steps 2-4: changing things until the output looks right, without understanding why. That hides bugs instead of fixing them.

Reading a traceback

A traceback is a snapshot of the call stack at the moment an exception escaped: which function called which, down to the line that failed.

Traceback (most recent call last):
  File "report.py", line 22, in <module>
    main()
  File "report.py", line 18, in main
    print(format_row(row))
  File "report.py", line 11, in format_row
    return f"{row['name']:<10} {unit_price(row):>8.2f}"
  File "report.py", line 6, in unit_price
    return row["total"] / row["qty"]
           ~~~~~~~~~~~~~^~~~~~~~~~~~
ZeroDivisionError: division by zero

Read the last line first: the exception type and message say what went wrong.
The frame just above it is where: file, line number, function, and the source line, with ~~~^~~~ markers pointing at the exact sub-expression (here the division).
The frames above that say how the program got there, outermost first: module-level code called main, which called format_row, which called unit_price. Each frame is a function call that was in progress, with its own local variables.
Frames from the standard library or other packages often appear in the middle. Look for the last frame in your own code: that is usually where your mistake is, even if the exception was raised deeper inside a library you called with bad arguments.

Here the arithmetic is fine; the data is not. The useful question is "which row has qty 0, and should it have been filtered out earlier?", which leads you back up the stack to where rows are read.

If an exception happens while handling another one, you see two tracebacks joined by During handling of the above exception, another exception occurred:. The last one is what finally stopped the program; the first one is often the real cause.

Print debugging, done well

Adding print calls is a perfectly respectable technique. Make them informative:

print("DEBUG scores:", repr(scores), type(scores[0]))

DEBUG scores: ['9', '10', '8'] <class 'str'>

Use repr (or the f-string = specifier). print(x) hides the difference between 10 and "10", and between "ada" and "ada\n"; repr shows quotes, escapes and trailing whitespace.
The = specifier prints the expression and its value: print(f"{total=} {count=}") gives total=27 count=3.
Label each print so you know which line produced it, and print at the boundaries: what a function receives and what it returns.
Print to stderr when stdout is the program's real output: print("DEBUG", x, file=sys.stderr). Then debugging output does not corrupt the results (or break an exercise's expected output).
Remove them afterwards. Debug prints left in code are noise at best and leak data at worst.

In the exercise with three bugs, print(repr(scores)) immediately shows the scores are strings, and string comparison is alphabetical: "9" > "10" is True, because "9" sorts after "1".

logging: prints that grew up

For anything bigger than a throwaway script, use the standard logging module. Every log message has a level:

Level	Use for
`DEBUG`	detailed internals, only useful while diagnosing
`INFO`	normal milestones: "loaded 1,200 records"
`WARNING`	something unexpected but handled: "skipping malformed line 7"
`ERROR`	an operation failed
`CRITICAL`	the program cannot continue

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")

logging.debug("raw input: %r", "x")      # below INFO: not shown
logging.info("loaded %d records", 1200)
logging.warning("skipping line %d: %r", 7, "n/a")

INFO: loaded 1200 records
WARNING: skipping line 7: 'n/a'

What is happening:

basicConfig configures the root logger once, at program start: the minimum level to show, the format of each line, and the destination. By default the destination is stderr, keeping stdout clean for real output. Pass filename="app.log" to log to a file instead.
Messages below the level are discarded cheaply. Turning on detail is a one-word change (level=logging.DEBUG), with no need to add or remove prints throughout the code. Without any basicConfig, the threshold is WARNING and the format is WARNING:root:message.
Pass arguments separately ("loaded %d records", n) rather than pre-formatting with an f-string. The string is only formatted if the message will actually be shown, and log-collection tools can group messages by their template. %d is an integer, %s uses str, %r uses repr.
Format fields include %(asctime)s (timestamp), %(name)s (logger name), %(levelname)s, %(funcName)s and %(lineno)d.

In larger programs, each module creates its own named logger with log = logging.getLogger(__name__) and calls log.info(...). The names form a hierarchy (shop, shop.cart), so you can turn on DEBUG for one part of the program only. Library code should never call basicConfig; configuring output is the application's job.

Inside an except block, logging.exception("could not parse %s", path) logs at ERROR level and includes the full traceback, which is ideal for long-running programs that must report a failure and carry on.

Common mistakes

Reading only the last line of a traceback, or only the first. The last line says what, the last frame of your code says where, the rest says how.
Debug prints corrupting output. They go to stdout by default; use stderr or logging.
print(x) hiding types. 5 and '5' print identically; use repr.
Calling basicConfig after logging has started. The first logging.info(...) call (with no configuration) configures the root logger with defaults, and later basicConfig calls are then ignored. Configure once, at the very start of main.
f-strings in log calls: logging.debug(f"{huge_object}") formats the string even when DEBUG is off.
Changing several things at once while debugging. If the bug disappears, you do not know which change fixed it, or whether one of them introduced a new bug.

Recap

Debug methodically: reproduce, read the evidence, isolate, test one hypothesis at a time, fix the cause, add a regression test.
A traceback lists the call stack outermost first; the last line says what failed and the frame above it says where.
Print debugging works: use repr or f"{x=}", label your prints, send them to stderr, remove them afterwards.
logging has levels (DEBUG to CRITICAL), is configured once with basicConfig, writes to stderr by default, and takes arguments separately from the format string.

Going further: read the "Logging HOWTO" in the Python documentation (the basic tutorial section), and try python3 -X faulthandler plus python3 -X importtime -c "import json" to see two more built-in diagnostic switches.

Exercises

Exercise 1 · quiz

Where did it break?

Traceback (most recent call last):
  File "report.py", line 22, in <module>
    main()
  File "report.py", line 18, in main
    print(format_row(row))
  File "report.py", line 11, in format_row
    return f"{row['name']:<10} {unit_price(row):>8.2f}"
  File "report.py", line 6, in unit_price
    return row["total"] / row["qty"]
           ~~~~~~~~~~~~~^~~~~~~~~~~~
ZeroDivisionError: division by zero

Which function was executing when the exception was raised, and what is the most useful first question to ask?

main; why was main called?
format_row; is the f-string format wrong?
unit_price; why does this row have qty equal to 0, and where did that row come from?
<module>; is line 22 a syntax error?

Answer

unit_price; why does this row have qty equal to 0, and where did that row come from?

A traceback lists frames from the outermost call (top) to the innermost (bottom); the last frame, just above the error line, is where the exception was raised: unit_price, line 6. The division itself is correct code; the data is surprising. So the useful question is where a row with qty == 0 came from (walk back up the frames to main, which supplied row) and what the program should do with such rows.

Exercise 2 · quiz

Which messages appear?

A program does not call logging.basicConfig and runs:

import logging
logging.debug("connecting")
logging.info("connected")
logging.warning("slow response")
logging.error("request failed")

Which messages are printed (to stderr)? Select all that apply.

connecting
connected
slow response
request failed

Answer

slow response
request failed

The root logger's default threshold is WARNING: messages below it (DEBUG, INFO) are dropped, and WARNING, ERROR and CRITICAL are shown, in the default format WARNING:root:slow response. Call logging.basicConfig(level=logging.DEBUG) (or INFO) to see the quieter messages; that one line is how you turn on detail while debugging without editing every log call.

Exercise 3 · write code

Find and fix three bugs

This program reads lines of the form name score (score is a whole number) from stdin and should print:

students: <count>
average: <mean score, rounded to 1 decimal place>
top: <name of the student with the highest score>

For the input

ada 9
grace 10
alan 8

it should print students: 3, average: 9.0, top: grace. Instead it prints wrong answers. The starter contains three bugs. Run it, compare with the expected output, add temporary print(repr(...)) lines to see what the variables really hold, and fix each bug. Remove your debugging prints before checking. If several students share the highest score, the first one listed wins.

File: main.py

Starting point

import sys

names = []
scores = []
for line in sys.stdin:
    name, score = line.split()
    names.append(name)
    scores.append(score)

count = len(names)
total = 0
for i in range(1, count):
    total += int(scores[i])
average = total / count

best = 0
for i in range(count):
    if scores[i] > scores[best]:
        best = i

print("students:", count)
print("average:", round(average, 1))
print("top:", names[best])

Example

input

ada 9
grace 10
alan 8

expected output

students: 3
average: 9.0
top: grace

Example

input

linus 95
guido 87
barbara 90
ken 59

expected output

students: 4
average: 82.8
top: linus

Hint 1

Print repr(scores) after the reading loop. Are those numbers or strings? How does "9" > "10" compare?

Hint 2

Which index does range(1, count) start at? Is the first student's score included in the total?

Hint 3

The third bug shows up with a blank line in the input: line.split() on an empty line gives [], and unpacking it fails. Skip lines that are blank.

Reference solution

import sys

names = []
scores = []
for line in sys.stdin:
    if not line.strip():
        continue
    name, score = line.split()
    names.append(name)
    scores.append(int(score))

count = len(names)
total = 0
for i in range(count):
    total += scores[i]
average = total / count

best = 0
for i in range(count):
    if scores[i] > scores[best]:
        best = i

print("students:", count)
print("average:", round(average, 1))
print("top:", names[best])

Exercise 4 · write code

Logging to stderr, results to stdout

Write a program that reads lines from stdin, each supposed to contain one integer, and prints the sum of the valid integers to stdout as total: <sum>.

It must also log, using the logging module configured with

logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")

for each line that is not a valid integer, a WARNING: skipping line <n>: <repr of the stripped line> (lines are numbered from 1; blank lines are skipped too);
at the end, an INFO message: summed <k> numbers.

basicConfig sends log output to stderr, so stdout contains only the total. For the input

10
ten
-3

5

stdout is total: 12 and stderr is exactly:

WARNING: skipping line 2: 'ten'
WARNING: skipping line 4: ''
INFO: summed 3 numbers

File: main.py

Starting point

import logging
import sys

total = 0
for line in sys.stdin:
    total += int(line)
print("total:", total)

Example

input

10
ten
-3

5

expected output

total: 12

Example

input

1
2
3

expected output

total: 6

Hint 1

enumerate(sys.stdin, start=1) gives you line numbers.

Hint 2

Catch ValueError from int(text); int("") raises it too, which handles blank lines.

Hint 3

logging.warning("skipping line %d: %r", n, text) formats with %r, which is the repr: quotes included.

Reference solution

import logging
import sys

logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")

total = 0
count = 0
for n, line in enumerate(sys.stdin, start=1):
    text = line.strip()
    try:
        value = int(text)
    except ValueError:
        logging.warning("skipping line %d: %r", n, text)
        continue
    total += value
    count += 1

logging.info("summed %d numbers", count)
print("total:", total)