Debugging and Logging 🔦

The method, restated

A bug is always the same thing: a gap between what you believe and what is true. The whole job is finding which belief is wrong, and the fastest route is not to stare harder, it is to make beliefs visible and test them one at a time.

1. Reproduce it reliably. A bug you cannot trigger on demand cannot be fixed, only guessed at. Get it down to the smallest input that shows the problem.
2. State the belief. "At line 14, total should be 47."
3. Check it. Print it, or stop there with a debugger.
4. Halve the search space. If the belief was right, the bug is downstream. If it was wrong, it is upstream. Repeat.
5. Fix, then prove. Write a test that fails before your fix and passes after (Lesson 29). Otherwise it will come back.

Level 1: better prints

def parse_row(row):
    parts = row.split(",")
    print(f"{row=}")
    print(f"{parts=}")
    print(f"{len(parts)=}")
    return {"name": parts[0], "pay": int(parts[1])}


print(parse_row("Guybrush, 100"))

row='Guybrush, 100'
parts=['Guybrush', ' 100']
len(parts)=2
{'name': 'Guybrush', 'pay': 100}

That {variable=} form inside an f-string is the fastest debugging tool Python has. It prints the name, the value, and (because it uses repr) the quotes and escapes that reveal stray whitespace. Three keystrokes, and it has ended more mysteries than any debugger.

Two other print upgrades worth knowing:

import sys

print("this goes to stderr, so it does not pollute piped output", file=sys.stderr)
print("flushed immediately, useful when a program is about to crash", flush=True)

this goes to stderr, so it does not pollute piped output
flushed immediately, useful when a program is about to crash

Level 2: the built-in debugger

def calculate_total(prices, discount):
    total = sum(prices)
    # breakpoint()          # uncomment and run this in a terminal
    final = total * (1 - discount)
    return round(final, 2)


print(calculate_total([10.00, 24.99, 5.50], 0.1))

36.44

Put breakpoint() on a line and run the program in a terminal. Execution stops there and hands you a prompt where you can inspect anything:

(Pdb) total
40.49
(Pdb) discount
0.1
(Pdb) total * (1 - discount)
36.441
(Pdb) prices
[10.0, 24.99, 5.5]
(Pdb) n          # run the next line
(Pdb) c          # continue to the end
(Pdb) q          # quit

breakpoint() has been built in since Python 3.7 and needs no import. Your editor has a graphical version of the same thing, and in VS Code it is the F5 key. Both beat printing when the state is complicated, because you can ask questions you did not think of in advance.

Level 3: logging, for programs that outlive the terminal

import logging

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

log = logging.getLogger("crew")

log.debug("this will not appear, the level is INFO")
log.info("loaded 3 crew members")
log.warning("no ship assigned")
log.error("could not open manifest")
log.critical("hull breach")

INFO     loaded 3 crew members
WARNING  no ship assigned
ERROR    could not open manifest
CRITICAL hull breach

Why this beats print for anything real:

• Levels. Turn detail up or down without editing code. Run at DEBUG while investigating, WARNING in production.
• Destinations. The same calls can go to the screen, a file, a rotating set of files, or a central log service, decided by configuration.
• Context for free. Timestamps, module names, line numbers, process ids.
• It can be left in. Debug prints get deleted, then re-added the next time. Log lines stay, and are there at 3am when the thing breaks and you cannot reproduce it.

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s %(name)-8s %(levelname)-8s %(message)s",
    datefmt="%H:%M:%S",
)

log = logging.getLogger("ship")


def load_crew(names):
    log.debug("loading %d names", len(names))
    for name in names:
        if not name.strip():
            log.warning("skipping an empty name")
            continue
        log.info("added %s", name)
    return [n for n in names if n.strip()]


crew = load_crew(["Guybrush", "", "Elaine"])
log.info("finished with %d crew", len(crew))

Logging exceptions properly

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s")
log = logging.getLogger("vault")


def open_vault(combination):
    try:
        return 100 / combination
    except ZeroDivisionError:
        log.exception("could not open the vault")
        return None


print(open_vault(0))

log.exception(...) inside an except block records your message and the full traceback. It is the single most useful logging call there is, and it is why "an error occurred" appears in so many useless log files: somebody used log.error and threw the traceback away.

Bugs that are not in your code

def divide_treasure(total, crew):
    share = total // len(crew)
    remainder = total - share * len(crew)
    payouts = {}
    for member in crew:
        payouts[member] = share
    payouts[crew[0]] = remainder
    return payouts


print(divide_treasure(100, ["Guybrush", "Elaine", "Otis"]))

def divide_treasure(total, crew):
    """Split total evenly, with any remainder going to crew[0]."""
    share = total // len(crew)
    remainder = total - share * len(crew)
    payouts = {member: share for member in crew}
    payouts[crew[0]] += remainder
    return payouts


result = divide_treasure(100, ["Guybrush", "Elaine", "Otis"])
print(result)
print("total paid out:", sum(result.values()))

{'Guybrush': 34, 'Elaine': 33, 'Otis': 33}
total paid out: 100

def process(orders):
    print("starting")
    for order in orders:
        print("processing", order)
        if order["total"] < 0:
            print("BAD ORDER!", order)
            continue
        print("ok")
    print("done")

import logging

log = logging.getLogger(__name__)


def process(orders):
    """Process each order, skipping any with a negative total."""
    log.info("processing %d orders", len(orders))
    processed = 0

    for order in orders:
        log.debug("order %s", order)
        if order["total"] < 0:
            log.warning("skipping order %s: negative total %s", order["id"], order["total"])
            continue
        processed += 1

    log.info("finished: %d of %d processed", processed, len(orders))
    return processed


logging.basicConfig(level=logging.INFO, format="%(levelname)-8s %(message)s")
process([{"id": 1, "total": 10}, {"id": 2, "total": -5}])

INFO     processing 2 orders
WARNING  skipping order 2: negative total -5
INFO     finished: 1 of 2 processed

def average(numbers):
    total = 0
    for n in numbers:
        total += n
    breakpoint()
    return total / len(numbers) - 1


print(average([10, 20, 30]))