Debugging Python With print, logging and pdb

Debugging is finding the difference between what you think the code does and what it actually does. Staring at the code doesn't show you that. Looking at the values while it runs does. There are three common ways to look: print, the logging module, and the pdb debugger. Each one fits a different situation.

The bug

This function should return the average order value, but the number is too low:

# report.py
def average_order(orders):
    total = 0
    count = 0
    for order in orders:
        if order["status"] == "paid":
            total += order["amount"]
        count += 1
    return total / count


orders = [
    {"id": 1, "amount": 1000, "status": "paid"},
    {"id": 2, "amount": 3000, "status": "paid"},
    {"id": 3, "amount": 500, "status": "cancelled"},
]

if __name__ == "__main__":
    print(average_order(orders))

python3 report.py

1333.3333333333333

Two paid orders, 1,000 and 3,000. The average should be 2,000. Before touching anything, write down what you expect each variable to be. Debugging is checking those expectations one by one.

Tool 1: print

Fast and fine for a quick look. Print the values you are unsure about, with labels:

from report import orders

total = count = 0
for order in orders:
    if order["status"] == "paid":
        total += order["amount"]
    count += 1
    print(f"id={order['id']} status={order['status']} total={total} count={count}")

id=1 status=paid total=1000 count=1
id=2 status=paid total=4000 count=2
id=3 status=cancelled total=4000 count=3

Read across the lines and compare them with what you expected. total is 4000 after order 2 and stays 4000 after the cancelled order. Correct. count goes to 3 even for the cancelled order. Not correct. That is the bug: count += 1 is outside the if, so cancelled orders are counted but not added.

The downside of print: you have to remember to remove it. Forgotten debug prints end up in production output, in emails, and in CSV files other programs read. For a two-minute check, print is fine. For anything you might want again later, use logging.

Tool 2: logging

logging is print with a volume knob. Each message has a level, and you decide which levels are shown, without deleting any lines:

# report_log.py
import logging

log = logging.getLogger(__name__)


def average_order(orders):
    total = 0
    count = 0
    for order in orders:
        if order["status"] == "paid":
            total += order["amount"]
            count += 1
        else:
            log.debug("skipping order %s (%s)", order["id"], order["status"])
    if count == 0:
        log.warning("no paid orders, returning 0")
        return 0
    return total / count


if __name__ == "__main__":
    from report import orders
    logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s: %(message)s")
    print(average_order(orders))
    print(average_order([]))

python3 report_log.py

DEBUG __main__: skipping order 3 (cancelled)
2000.0
WARNING __main__: no paid orders, returning 0
0

The bug is fixed (count += 1 moved inside the if), and the function also handles an empty list instead of crashing with ZeroDivisionError. Change level=logging.DEBUG to level=logging.WARNING and the debug line disappears while the warning stays. The code doesn't change. Only the setting does.

The levels, from quietest to loudest: DEBUG (details for you while fixing something), INFO (normal events worth recording), WARNING (something unexpected, but the program continues), ERROR and CRITICAL. Use log.exception("...") inside an except block to log the error with its full traceback.

Tool 3: pdb, the debugger

Sometimes you don't know which values to print. A debugger pauses the program at a line, and you look around: check any variable, run one line at a time, try expressions. Put breakpoint() where you want to stop:

# report_pdb.py
from report import orders


def average_order(orders):
    total = 0
    count = 0
    for order in orders:
        breakpoint()
        if order["status"] == "paid":
            total += order["amount"]
        count += 1
    return total / count


print(average_order(orders))

Run it, and Python stops at the breakpoint and waits at the (Pdb) prompt. To show a real session here, the commands are piped in with printf. Normally you just run python report_pdb.py and type them:

printf 'p order\nc\nc\np order["status"], total, count\nn\nn\np count\nc\n' | python3 report_pdb.py

> .../report_pdb.py(9)average_order()
-> breakpoint()
(Pdb) {'id': 1, 'amount': 1000, 'status': 'paid'}
(Pdb) > .../report_pdb.py(9)average_order()
-> breakpoint()
(Pdb) > .../report_pdb.py(9)average_order()
-> breakpoint()
(Pdb) ('cancelled', 4000, 2)
(Pdb) > .../report_pdb.py(10)average_order()
-> if order["status"] == "paid":
(Pdb) > .../report_pdb.py(12)average_order()
-> count += 1
(Pdb) 2
(Pdb) 1333.3333333333333

What happened, command by command:

• p order printed the current order (order 1).
• c (continue) ran until the breakpoint was hit again: once for order 2, once for order 3.
• p order["status"], total, count showed the cancelled order with total 4000 and count 2. So far, correct.
• n (next) ran one line at a time. Look at the line numbers: from line 10, the if, it jumped straight to line 12, count += 1, skipping the addition, which is right for a cancelled order. But line 12 still runs.
• That line hasn't run yet when it is shown, so p count still says 2. One more step and it becomes 3. That is the bug, seen directly.
• The final c let the program finish.

Other useful commands: l lists the code around the current line, s steps into a function call, w shows where you are in the call stack, and q quits. Editors like VS Code and PyCharm have the same debugger with buttons and a variables panel, if you prefer clicking.

Which one to use

• print: a quick look at one or two values, removed within minutes.
• logging: anything you might want to see again, and anything that runs unattended. When a scheduled script fails at 3 AM, the log is all you have.
• pdb: when you don't know where the problem is, or when the values you need depend on what you see first.

And when you have found the bug, write a test that fails because of it before you fix it, like in the previous lesson. Then it stays fixed.

Common mistakes

• Changing code before checking values. Trying random fixes until the number looks right often hides the bug instead of fixing it.
• Debugging with the wrong data. If the bug only happens with the real file, test with a copy of the real file, not with your three neat test rows.
• Using logging.basicConfig inside a module. Configure logging once, in the main script. Modules should only call logging.getLogger(__name__).

What happens if you skip this step

You fix bugs by guessing. Sometimes the guess works, and you don't know why, so you can't tell if it is really fixed. Sometimes the guess makes the symptom disappear and moves the bug somewhere else. Looking at the actual values turns a guessing game into a checklist.

A scheduled script gave a wrong total last night and nobody was watching. With your current code, what record would you have of what it actually did?