25Debugging — the traceback is the unwound stack

In Chapter 24 a green test bar certified that our code did exactly what we predicted. This chapter is about the other moment. The one where it doesn't, and the terminal fills with red. We take it slowly, because there's a question most tutorials sprint straight past. When Python prints a traceback, is it printing a message about the crash, or the crash itself? Here's the plan. First we read a traceback as what it physically is: the call stack you built in Volume 1, unwound and printed one frame at a time. Then we watch an exception stop being an instant. It becomes a process that climbs the stack, popping frame after frame, asking each one whether it has a rescuer. Then we meet pdb. Not some external program reaching in from outside, but ordinary Python the interpreter itself calls on every single line, through a hook that was in the language the whole time. And we turn debugging from panicked flailing into a binary search. It converges in about log₂(N) steps on the one line where your prediction and reality first split. By the end, the scariest wall of red in Python reads like a map.

01A traceback is the call stack, printed

Let's start with the thing everyone flinches at. You pressed Enter, and the terminal answered with a wall of red. Fifteen lines of File this and line that, arrows and indentation, and a word you half-recognise at the very bottom. The reflex is to flinch, scan for a keyword, and paste the whole thing into a search box. Kill that reflex now. That wall is not the machine yelling at you. It is the machine handing you its own X-ray: a traceback, already developed, free of charge. Every line in it is a hard fact about where your program was standing at the instant it fell over. Learn to read it and you diagnose in two seconds what print-debugging takes twenty minutes to chase.

To read it you need exactly one thing you already own. In Volume 1 you built the call stack. Every time one function calls another, Python pushes a frame: a small workspace holding that call's local variables and its place in the code. It pops that frame when the call returns. Now watch the reframe. A traceback is that stack. Not a description of it, not a summary, but the stack itself, unwound and printed one frame per block. That single sentence is the whole chapter. Everything else is consequence.

Here is the machinery, exactly. CPython keeps a per-thread record, the PyThreadState, holding a pointer to the frame currently running. Each frame carries a field f_back pointing at the frame that called it. So the frames form a singly-linked chain from the innermost call all the way back to the module that started everything. (Since 3.11 the hot per-call data lives in a lean _PyInterpreterFrame on the interpreter's own data stack. The heavier PyFrameObject you can poke at from Python is materialised lazily, only when something needs to hold onto it. A crash is exactly such a something.) When an exception reaches a frame that does not catch it, the interpreter calls a C function named PyTraceBack_Here. It allocates one PyTracebackObject recording three fields. tb_frame is a pointer to that very frame. tb_lineno is the line number. And tb_next is a link to the traceback node already built for the frame inside this one. The result is a second linked list running parallel to the f_back chain: a faithful shadow of the stack that was open at the moment raise fired.

Where does that line number come from? The frame never stored "I am on line 12." It stored f_lasti: the byte offset of the last bytecode instruction it ran. Python recovers the source line by looking that offset up in a compact table the compiler baked into the code object, co_linetable. In 3.11+, co_positions() adds exact column spans, which is how modern Python underlines the precise sub-expression that failed. The filename and function name in each block come straight off the frame's code object, co_filename and co_name. Nothing in a traceback is invented. Every field is copied or decoded from a frame that genuinely existed.

Now watch a three-deep chain fall over. Four calls are open: module, then load_config, then read_field, then to_int. So four frames are on the stack when int("x") refuses:

def to_int(raw):
    return int(raw)             # line 2 — int() raises here on 'x'

def read_field(row, key):
    return to_int(row[key])     # line 5

def load_config(rows):
    return read_field(rows[0], "port")   # line 8

load_config([{"port": "x"}])           # line 10

Traceback (most recent call last):
  File "config.py", line 10, in <module>
    load_config([{"port": "x"}])
  File "config.py", line 8, in load_config
    return read_field(rows[0], "port")
  File "config.py", line 5, in read_field
    return to_int(row[key])
  File "config.py", line 2, in to_int
    return int(raw)
ValueError: invalid literal for int() with base 10: 'x'

Count them. Four calls were open, so four frames were on the stack, so the traceback has exactly four blocks. They appear outermost-first, innermost-last, in the same order as the f_back chain read from the module end. Block one is the <module> frame, since co_name is literally "<module>" for top-level code. Block four is to_int, the crash site, its line 2 decoded from that frame's f_lasti. There is no fifth block for int itself, because int is C code with no Python frame to capture. The mapping is total and mechanical. Frame N of the stack becomes block N of the text.

Step back, because this is the whole volume in miniature. The call stack is a graph of live objects: frames pointing at frames, each holding real Python values at real RAM addresses. To get it out of the process and onto your screen, Python had to flatten that graph into a flat stream of characters. That means one File …, line …, in … block per frame, in order. That is a serialization, the exact move this whole volume studies, whether the far side is a disk file, a socket, or a pickle. A traceback is the call stack serialized to text so it can cross the boundary out of the process. What crosses a boundary is always bytes, never objects. A traceback is the stack, flattened.

You can now map a traceback back to the stack that made it. But that stack didn't just sit there — it unwound, frame by frame, and the exception was moving the whole time. Next: watch it travel. →

02Exceptions unwind the stack

"An exception happened" sounds like a single instant: a switch flips, the program stops. That picture will fail you the moment you try to catch something and it slips past your except anyway. An exception is not an instant. It is a motion. It starts at the frame where raise fired and it travels up the stack, one frame at a time. It stops at each to ask a single question: does anyone here rescue me? If not, that frame is torn down and the exception rises to the caller, and asks again. Understanding this search is what lets you predict, before you run anything, exactly where a try has to sit to catch a given error. It also shows why a finally or a with block still runs on the way out.

The moment raise executes, it does not jump anywhere. It sets the pending exception on the thread state, the exc_info slots, and hands control back to the eval loop, _PyEval_EvalFrameDefault. Now comes the Volume-2 upgrade over the story you may have heard. Since Python 3.11, entering a try block costs nothing at runtime. This is what "zero-cost exceptions" means. There is no SETUP_FINALLY instruction pushing a block onto a runtime block-stack anymore. The happy path executes zero extra instructions. Instead, the compiler bakes a side table into each code object. That table is co_exceptiontable, a compact map from ranges of bytecode offsets to the handler offset that covers them.

So here is what actually happens when the exception is pending. The interpreter takes the current instruction offset in this frame and binary-scans the exception table. There are two outcomes, and only two. Suppose some row covers this offset. That means the failing instruction lies inside the byte-range of a try in this frame. Then the interpreter jumps to that row's handler offset, pushes the exception object, and runs your except or finally or __exit__ logic. The search is over. But suppose no row covers this offset. Then the frame is finalized. Its locals are decref'd, and any pending finally clauses and with-statement __exit__ methods fire as part of the unwind. Then PyTraceBack_Here records this frame into the growing traceback, section 1's list, being built one node per pop. Control returns to the caller frame, where the identical table lookup repeats against that frame's exception table. Pop, search, pop, search, up the f_back chain. This continues until either a frame catches it or the module frame is reached with nothing caught. At that point PyErr_PrintEx hands the finished traceback to sys.excepthook to print. "Zero-cost" means the whole price is paid once, at throw time, as table lookups during unwinding, never on the code that doesn't throw.

Here is the consequence that trips everyone: placement is a range test. A handler catches an exception only if the failing instruction's offset falls inside the byte-range the compiler recorded for that try. Put the try around the wrong line and the offset misses the range. The row doesn't match, and the exception sails straight past a handler that looks like it should apply. Watch it, and watch a with block clean up on the way out:

def parse(raw):
    with open("cache.tmp", "w") as f:   # f.__exit__ will still run on the way out
        f.write(raw)
        n = int(raw)                    # raises ValueError on 'x' — NO try in this frame
        return n * 2                     # never reached

def run():
    try:
        return parse("x")          # the covered range lives HERE, one frame up
    except ValueError:
        return -1                       # the rescuer

print(run())                          # -> -1, and cache.tmp was closed during the unwind

Trace the motion. int("x") raises inside parse. The interpreter scans parse's exception table for a row covering that offset — and there is none, because parse has no try. So parse is finalized: on the way out, the with block's f.__exit__ fires and the file is flushed and closed — cleanup rides the unwind, guaranteed, whether you exit normally or by exception. The frame pops, is recorded into the traceback, and the exception rises into run. Now the scan is against run's table, and the failing call site parse("x") is inside the covered range, so the row matches: jump to the except, bind the exception, return -1. The search stops. Move that try to wrap the wrong line and the offset misses; the handler never fires. Catching is geometry, not magic.

you type
# invariants.py -- a tripwire that names what it caught
def add_track(library, title, secs):
    assert isinstance(secs, int), f"secs must be int, got {type(secs).__name__} {secs!r}"
    assert secs > 0, f"secs must be positive, got {secs}"
    library[title] = secs
    return library


lib = {}
add_track(lib, "Titanium", 245)
print("after one good add :", lib)
add_track(lib, "Levels", "340")          # a string sneaks in from a CSV
print("after one bad add  :", lib)


# ---------- the terminal ----------
$ python invariants.py
$ python -O invariants.py

you see
$ python invariants.py
after one good add : {'Titanium': 245}
Traceback (most recent call last):
  File "C:\tmp\ch25\invariants.py", line 12, in <module>
    add_track(lib, "Levels", "340")          # a string sneaks in from a CSV
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\tmp\ch25\invariants.py", line 3, in add_track
    assert isinstance(secs, int), f"secs must be int, got ...
           ^^^^^^^^^^^^^^^^^^^^^
AssertionError: secs must be int, got str '340'

$ python -O invariants.py
after one good add : {'Titanium': 245}
after one bad add  : {'Titanium': 245, 'Levels': '340'}

The exception has landed and the traceback is printed. Now you have to read it — and the order it prints in is the deliberate reverse of the order it searched. Next: the one habit that turns forty lines of red into a two-second diagnosis. →

03Read it bottom-up

The instinct is to read a traceback like English, top to bottom, first line first. Follow that instinct and you march straight into someone else's framework, three libraries deep, past files you have never opened. You give up before you reach the part that concerns you. Reverse it. Go to the bottom first. The last line tells you what broke and why. The block directly above it tells you where. Everything above that is just the road that led there, so skim it only if you need to. This one habit is the single highest-leverage debugging skill there is, and it takes thirty seconds to learn.

The reason it works is structural, not stylistic. In section 1 you saw the traceback printed outermost-frame-first, innermost-frame-last. That print order is the deliberate inverse of the search order. The exception searched from the inside out. The printer lists from the outside in, so that the last block is always the frame nearest the crash. And beneath that final block sits one more line, of the form ExceptionType: message. That line is not a frame at all. It is type(exc).__name__ followed by str(exc): the actual failure, the type of thing that went wrong and the human-readable detail. So bottom-up reading is a fixed three-step protocol. (1) The last line is the diagnosis, what and why. (2) The frame block just above it is the crash site, the exact line of code where raise fired, recovered from that frame's f_lasti. (3) Scan upward only far enough to find the first frame you own rather than library code. Nine times out of ten you never reach step three.

you type
# ---------- drill_name.py ----------
def build_greeting(user):
    return f"Hello, {user['name']}!"

def welcome(users):
    for u in users:
        print(build_greting(u))

welcome([{"name": "Ajai"}])


# ---------- drill_type.py ----------
def total_minutes(tracks):
    total = 0
    for title, secs in tracks:
        total += secs
    return total / 60

LIBRARY = [("Blinding Lights", 200), ("Titanium", "245"), ("Levels", 340)]
print(total_minutes(LIBRARY))


# ---------- drill_index.py ----------
def third_track(titles):
    return titles[2]

def show(titles):
    print("the third track is", third_track(titles))

show(["Blinding Lights", "Titanium"])

you see
$ python drill_name.py
  File "drill_name.py", line 7, in welcome
    print(build_greting(u))
          ^^^^^^^^^^^^^
NameError: name 'build_greting' is not defined. Did you mean: 'build_greeting'?

  -> a NAME that is not bound.  drill_name.py, line 7.  I typed "greting".

$ python drill_type.py
  File "drill_type.py", line 5, in total_minutes
    total += secs
TypeError: unsupported operand type(s) for +=: 'int' and 'str'

  -> right names, WRONG KINDS.  drill_type.py, line 5.  one row holds "245".

$ python drill_index.py
  File "drill_index.py", line 3, in third_track
    return titles[2]
           ~~~~~~^^^
IndexError: list index out of range

  -> index past the end.  drill_index.py, line 3.  only two titles were passed.

There is one structure you must learn to recognise, because it stacks multiple tracebacks in a single dump: chained exceptions. When code raises a new exception while it is already handling one, Python links them so you don't lose the original. There are two flavours, and the wording tells them apart. An implicit chain prints During handling of the above exception, another exception occurred:. Python set this up automatically, storing the first exception in the second one's __context__ attribute the moment a new raise ran inside an except block. An explicit chain prints The above exception was the direct cause of the following exception:. You asked for it with raise NewError(...) from original, which sets __cause__ and signals deliberate intent: "I am translating that low-level error into this meaningful one." Each chained segment is a complete traceback of its own. One rule survives all the structure. The lowest exception line in the entire dump is still the one that ultimately crashed the program, and you read its cause chain by walking upward through the segments.

def get_port(cfg):
    return int(cfg["port"])            # KeyError if 'port' is missing

def start(cfg):
    try:
        return get_port(cfg)
    except KeyError:
        raise RuntimeError("config is missing a port")   # implicit chain via __context__

start({})

Traceback (most recent call last):
  File "chain.py", line 6, in start
    return get_port(cfg)
  File "chain.py", line 2, in get_port
    return int(cfg["port"])
KeyError: 'port'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "chain.py", line 10, in <module>
    start({})
  File "chain.py", line 8, in start
    raise RuntimeError("config is missing a port")
RuntimeError: config is missing a port

Two segments, one story. The bottom line, RuntimeError: config is missing a port, is the exception that actually reached the top and crashed the program. That is your diagnosis. The bridge line tells you it did not appear from nowhere. It was raised while handling the KeyError in the top segment, which is the real root cause: a missing "port" key. The implicit "During handling…" wording is Python's honest confession that the second error happened because the first one did. Suppose get_port had instead written raise RuntimeError("config is missing a port") from err. Then the bridge would read The above exception was the direct cause…: same shape, but now stating that the translation was intentional. And raise ... from None suppresses the chain entirely, hiding the KeyError. That is occasionally kind to a user, often cruel to the next debugger.

# ---------- 1 ----------
# disease : AttributeError -- this object has no member named clock
# file    : ex_a.py
# line    : 12, inside listing()
# the fix : the caller passed a bare string, not a Track.
#           print(listing(["Titanium"]))  ->  print(listing([Track("Titanium", 245)]))
#
# the tell: "'str' object has no attribute" names the type you ACTUALLY had.
#           Whenever the message names a type you did not expect, the bug is
#           upstream -- at the call that built the wrong thing, not at the dot.
#           Here the first block you own, line 16, is where the wrong list was made.


# ---------- 2 ----------
# disease : KeyError -- 'repeat' is not a key in CONFIG
# file    : ex_b.py
# line    : 6, inside setting()
# the fix : either add the key, or ask for it safely.
#           return CONFIG[name]        ->  return CONFIG.get(name, DEFAULTS[name])
#
# the tell: a KeyError's message IS the missing key, with no other text at all.
#           Note that the crash block is setting(), but the DECISION was made in
#           describe(), line 10 -- the caret row there points straight at
#           setting('repeat'). Two frames, one mistake, and the caret names it.


# ---------- 3 ----------
# disease : ZeroDivisionError -- a denominator reached 0
# file    : ex_c.py
# line    : 4, inside average_length()
# the fix : an empty library has no average. Say so instead of dividing.
#           if not tracks: return 0.0
#
# the tell: ZeroDivisionError almost never means "someone typed a zero". It means
#           a COLLECTION WAS EMPTY -- len(tracks) was 0. The first block you own,
#           line 12, shows report([]) and the empty list is right there in the text.


# ---------- the pattern in all three ----------
# Three tracebacks, three diseases, and not once did you need to read the top block.
# Bottom line -> type and detail. Block above it -> file, line, function.
# Then, and only then, walk up to the first frame you own to see who passed the bad value.

Reading a traceback tells you where a crash landed — after the fact. But sometimes you need to stop the machine mid-stride and look around while it's still alive. That means a debugger. And a debugger is not what you think it is. →

04pdb rides the trace hook

The first time you type breakpoint() and the program freezes and a (Pdb) prompt appears, it feels like sorcery. Something reached inside your running code, stopped time, and is now letting you walk around in the frozen machine. It feels like an external program with special powers over the interpreter. It is nothing of the kind. Demystifying it completely is worth more than a hundred pdb commands, because the same trick underneath powers coverage tools, profilers, and line tracers. And you can build a working one yourself in fifteen lines.

The foundation is a hook that has been in the language the whole time. CPython's eval loop can call back into Python between operations. You arm it with sys.settrace(fn), which stores fn as the thread's global trace function. Once tracing is active, _PyEval_EvalFrameDefault invokes that function on four well-defined events. 'call' fires when a frame is entered. 'line' fires when execution crosses into a new source line. 'return' fires when a frame exits. And 'exception' fires when one is raised. The 'line' event is the interesting one. The interpreter detects it by comparing the current instruction offset against the line boundaries decoded from co_linetable, the very same table section 1 used to build the traceback, gated by the frame's f_trace_lines flag. So a debugger does not "watch" your code from outside. It is a function the interpreter calls, from the inside, at every line boundary.

One more piece makes it precise. The trace function returns a value, and that return value becomes the per-frame local trace function. The interpreter stashes it in the new frame's f_trace and calls it for that frame's subsequent line events. Return None and that frame stops being traced. Return the function itself and you keep getting its lines. This is how a debugger follows one specific frame instead of drowning in every line of every library. Prove the whole thing is real and public with a tracer you can write yourself:

import sys

def tracer(frame, event, arg):
    print(f"{event:<9} line {frame.f_lineno:>3}  {frame.f_code.co_name}")
    return tracer          # return per-frame tracer so we keep getting 'line' events

def total(xs):
    s = 0
    for x in xs:
        s += x
    return s

sys.settrace(tracer)
total([1, 2, 3])
sys.settrace(None)

call      line   8  total
line      line   9  total
line      line  10  total
line      line  11  total
line      line  10  total     # loop back — the 'for' line fires again each iteration
line      line  11  total
...
return    line  12  total

There is the machine, exposed. A 'call' at entry, a 'line' for every source line the interpreter crosses, and a 'return' at the end. The loop body reappears once per iteration, because it genuinely re-executes that line. Nothing is hidden. Now the reveal: pdb is just a well-dressed version of exactly this. It is built on the standard library's bdb.Bdb base class, which implements those four callbacks. On each 'line' event, bdb asks a single question: is there a breakpoint here, or am I single-stepping? If yes, it calls user_line, which fires up pdb's Cmd-based interactive prompt via cmdloop(). That prompt is a REPL. It reads commands (n, s, c, p, l…) from stdin, mutates the debugger's stepping state, and then returns so the eval loop continues. The (Pdb) prompt is a Python REPL running inside the interpreter's own per-line callback. Typing next simply tells bdb to stop again at the next line event in this frame.

And breakpoint()? It is the ergonomic front door and nothing more. It calls sys.breakpointhook(), which by default imports pdb and calls pdb.set_trace(), which calls sys.settrace to arm the hook starting at the current frame. Three hops from a builtin to the same primitive you just used by hand.

you type
# five.py -- one stop, five commands
def as_clock(seconds):
    minutes, secs = divmod(seconds, 60)
    return f"{minutes}:{secs:02d}"


def report(tracks):
    total = sum(secs for _title, secs in tracks)
    breakpoint()
    label = as_clock(total)
    return f"{len(tracks)} tracks, {label}"


print(report([("Titanium", 245), ("Levels", 340)]))


# ---------- the terminal ----------
$ python five.py

you see
$ python five.py
> c:\tmp\ch25\five.py(10)report()
-> label = as_clock(total)
(Pdb) p total
585
(Pdb) s
--Call--
> c:\tmp\ch25\five.py(2)as_clock()
-> def as_clock(seconds):
(Pdb) p seconds
585
(Pdb) n
> c:\tmp\ch25\five.py(3)as_clock()
-> minutes, secs = divmod(seconds, 60)
(Pdb) n
> c:\tmp\ch25\five.py(4)as_clock()
-> return f"{minutes}:{secs:02d}"
(Pdb) p minutes, secs
(9, 45)
(Pdb) c
2 tracks, 9:45

# debug_session.py -- which track is the longest? the answer is wrong.
TRACKS = [
    ("Blinding Lights", 200),
    ("Titanium",        245),
    ("Levels",          340),
    ("Clarity",         271),
]


def longest(tracks):
    best_title, best_secs = "", 0
    breakpoint()                       # freeze here and look around
    for title, secs in tracks:
        if secs > best_secs:
            best_title = title
    return best_title, best_secs


if __name__ == "__main__":
    print("longest:", longest(TRACKS))

$ python debug_session.py
> c:\tmp\ch25\debug_session.py(13)longest()
-> for title, secs in tracks:
(Pdb) p best_title, best_secs
('', 0)
(Pdb) n
> c:\tmp\ch25\debug_session.py(14)longest()
-> if secs > best_secs:
(Pdb) p title, secs
('Blinding Lights', 200)
(Pdb) n
> c:\tmp\ch25\debug_session.py(15)longest()
-> best_title = title
(Pdb) n
> c:\tmp\ch25\debug_session.py(13)longest()
-> for title, secs in tracks:
(Pdb) p best_title, best_secs
('Blinding Lights', 0)
(Pdb) c
longest: ('Clarity', 0)


# ---- now delete the breakpoint() and fix line 15 ----
#         best_title = title
#         best_title, best_secs = title, secs

$ python debug_session.py
longest: ('Levels', 340)

Now you can stop the machine anywhere and inspect it. But where should you stop? Poking at random is just slow flailing with a nicer prompt. Next: the method that guarantees progress — treat the bug as an experiment. →

05The scientific loop

Under pressure, almost everyone debugs the same bad way. Change a line that looks suspicious, sprinkle print everywhere, rerun, squint, change something else, rerun again. It feels like work, since you're typing and the program's running. But it converges glacially and teaches you nothing, because none of it is testing a specific idea. There is a method that guarantees progress on every step, and it comes straight out of a first principle you already trust from Volume 1: the machine is deterministic. Identical bytecode, identical inputs, identical starting state produce identical output, every single time.

Sit with what that implies, because it dissolves the whole mystery. A bug is not a spooky, intermittent event. It is a fixed, reproducible divergence between the state you predicted and the state that actually exists. And it first appears at one specific line: the first line where your prediction and reality disagree. Everything before that line is correct by definition. If it weren't, the divergence would have shown up earlier. Everything after it is downstream corruption, wrong values propagating from a fault that already happened. So debugging is not a hunt through a fog. It is a search for a single boundary on the execution timeline: the last known-good point and the first known-bad point, with the bug pinned exactly between them.

And a search for a boundary on an ordered line is the oldest efficient algorithm there is: binary search. If the program runs N steps and you can observe state at any step, checking the midpoint tells you which half holds the first divergence. Is the state still correct at step N/2? Then the bug is in the later half — everything up to the midpoint is exonerated. Is it already wrong there? Then the bug is in the earlier half. Each observation halves the suspect region, so you localise the fault in about log₂(N) checks, not N. A thousand-step program yields to ten well-placed probes. That is the difference between a bug that takes two minutes and one that takes two hours — not talent, just refusing to look anywhere but the midpoint of the current suspect region.

Two preconditions make the experiment valid, and skipping either is why debugging sometimes feels impossible. First, reproduce reliably. A bug that appears "randomly" is lying to you. It means there is a hidden input you have not pinned. The usual culprits are wall-clock time, dict or set ordering under a fresh PYTHONHASHSEED, thread interleaving, an un-seeded RNG, or the classic reused mutable default argument. Pin every input until the failure is deterministic: seed the RNG, fix the hash seed, freeze the clock, force one thread. Determinism is what makes an experiment repeatable, and an experiment you can't repeat can't be halved. Second, every hypothesis must be falsifiable. It must predict a concrete, observable value. "After line 14, total should be 42" can be confirmed or refuted by running line 14. "Something's wrong with the loop" predicts nothing and can't be tested against anything. Vague hunches cannot be binary-searched. Specific predictions can.

you type
# bisect_probe.py -- eight stages, one lies. Three probes, not eight.
STAGES = [
    ("load",      lambda xs: [3, 8, 5, 13]),
    ("scale",     lambda xs: [x * 10 for x in xs]),
    ("shift",     lambda xs: [x - 5 for x in xs]),
    ("normalise", lambda xs: [x // 5 for x in xs]),
    ("trim",      lambda xs: [x - 20 for x in xs]),
    ("smooth",    lambda xs: [x + 1 for x in xs]),
    ("clamp",     lambda xs: [min(x, 99) for x in xs]),
    ("round",     lambda xs: [round(x) for x in xs]),
]


def run_to(n):
    xs = []
    for _name, fn in STAGES[:n]:
        xs = fn(xs)
    return xs


def ok(xs):                       # the invariant: every value stays positive
    return all(x > 0 for x in xs)


print(f"final answer      : {run_to(8)}   invariant holds? {ok(run_to(8))}")
for probe in (4, 6, 5):           # midpoint, then midpoint of the bad half, then...
    xs = run_to(probe)
    print(f"probe after {probe} ({STAGES[probe - 1][0]:>9}): {str(ok(xs)):>5}   {xs}")

you see
$ python bisect_probe.py
final answer      : [-14, -4, -10, 6]   invariant holds? False
probe after 4 (normalise):  True   [5, 15, 9, 25]
probe after 6 (   smooth): False   [-14, -4, -10, 6]
probe after 5 (     trim): False   [-15, -5, -11, 5]

   4 good, 6 bad, 5 bad  ->  the boundary lies between stage 4 and stage 5.
   stage 5 is "trim". three probes over eight stages, and nothing was guessed.

Here is the most infamous "random" bug in Python, and how pinning it reveals the hidden input:

def collect(item, bucket=[]):     # bucket is created ONCE, at def-time — the hidden state
    bucket.append(item)
    return bucket

print(collect("a"))    # ['a']
print(collect("b"))    # ['a', 'b']  — 'randomly' remembers the previous call!

It doesn't remember randomly. It remembers deterministically. The default [] is one list object, created a single time when the def statement ran, and bound to the function forever. Every call that omits bucket shares that same list. So the "randomness" was a hidden input hiding in plain sight: the accumulated state of one object across calls. Predict the value of bucket at the top of the second call ("it should be empty") and reality says ['a']. The prediction and reality diverge right there, at the parameter binding, and the bug is pinned. The fix follows from the diagnosis, not from guessing. Write def collect(item, bucket=None): then bucket = [] if bucket is None else bucket, so a fresh list is born on each call. The lesson generalises past this one trap: reproduce first, and "random" resolves into a variable you forgot to pin.

you type
# print_right.py -- three upgrades that turn a print into evidence
title  = "Titanium "                 # note the trailing space
secs   = 245
tracks = [("Titanium ", 245), ("Levels", 340)]

print(secs)                          # 1. bare -- a number, not WHICH number
print("secs:", secs)                 # 2. hand-labelled -- you type the name twice
print(f"{secs=}")                    # 3. the = suffix writes the label for you

print(f"{len(tracks)=}")
print(f"{tracks[0][1] * 2=}")
print(f"{secs=:>6}")
print(f"{title=!s}")

print(title)                         # str  -- looks fine. it is not.
print(repr(title))                   # repr -- THERE it is.
print([title])                       # a container always shows you reprs

lookup = {"Titanium": 245}
print(f"{title=}  {(title in lookup)=}")
print(type(tracks), len(tracks))     # when a value is huge, print its SHAPE

you see
$ python print_right.py
245
secs: 245
secs=245
len(tracks)=2
tracks[0][1] * 2=490
secs=   245
title=Titanium
Titanium
'Titanium '
['Titanium ']
title='Titanium '  (title in lookup)=False
<class 'list'> 2

# ---------- where to break, and why ----------
# Break on the FIRST line of the loop body, before queue.remove(track).
#
# The reasoning, and it is the only part that matters:
#   played is not a value you can inspect once. It is BUILT, one lap at a time.
#   The only place a built value can go wrong is inside the thing that builds it.
#   And of the two candidates -- the loop, or the return -- the return is a
#   single expression with no arithmetic in it. So the loop is the whole suspect
#   region, and the top of its body is that region's earliest observable point.
#
# Do NOT break on the return. By then the evidence is one number with no history.
# Do NOT break before the for. Nothing has happened yet; you learn only the input.
#
# Print BOTH the loop variable AND the list you are iterating. That pairing is
# the entire trick: a loop bug is almost always a disagreement between the two.


# ---------- mystery.py, with the breakpoint added ----------
QUEUE = ["Blinding Lights", "Titanium", "Levels", "Clarity", "Sunflower"]


def play_all(queue):
    played = 0
    for track in queue:
        breakpoint()
        queue.remove(track)
        played += 1
    return played


print("queued:", len(QUEUE))
print("played:", play_all(QUEUE))


# ---------- the session ----------
$ python mystery.py
queued: 5
> c:\tmp\ch25\mystery.py(9)play_all()
-> queue.remove(track)
(Pdb) p track, played, queue
('Blinding Lights', 0, ['Blinding Lights', 'Titanium', 'Levels', 'Clarity', 'Sunflower'])
(Pdb) c
> c:\tmp\ch25\mystery.py(9)play_all()
-> queue.remove(track)
(Pdb) p track, played, queue
('Levels', 1, ['Titanium', 'Levels', 'Clarity', 'Sunflower'])
(Pdb) c
> c:\tmp\ch25\mystery.py(9)play_all()
-> queue.remove(track)
(Pdb) p track, played, queue
('Sunflower', 2, ['Titanium', 'Clarity', 'Sunflower'])
(Pdb) c
played: 3


# ---------- read the three stops as one sentence ----------
# track goes:  Blinding Lights -> Levels -> Sunflower.
# It skipped Titanium and Clarity -- every second item.
#
# A for loop over a list holds an internal index and walks it forward: 0, 1, 2...
# remove() shifts everything after the removed item DOWN by one. So after lap 1
# the index moves to 1 while the item that used to be at 1 has slid to 0.
# The loop and the list disagree about where "next" is, and half the queue is missed.


# ---------- the fix ----------
    for track in list(queue):        # iterate a COPY; drain the real one

$ python mystery.py
queued: 5
played: 5

# The law behind it: never mutate the collection you are iterating.
# Iterate a copy (list(queue)), or build a new list and rebind at the end.

The scientific loop finds bugs while the program runs. But the best evidence is often at the crash scene itself — and that scene doesn't have to vanish when the program dies. Next: re-enter the dead frames and interrogate the real objects that were alive at the instant of failure. →

06Post-mortem: inspecting the dead frames

Print debugging has a cruel structure. You must decide in advance which variables to print, then rerun, discover you printed the wrong ones, add more prints, rerun again. Each cycle is a guess about which value mattered. And each print shows you only a stringified snapshot frozen at print-time, str(x), not x itself. What you actually want is to arrive at the crash scene with everything still intact. After the program has already died, re-enter the exact frames that unwound and interrogate the real, live objects that existed at the moment raise fired. No rerun. No guessing which value was the one. This is post-mortem debugging, and it works for a reason that ties this whole chapter together.

Normally, frames are freed as the stack unwinds. Section 2 showed each frame being finalized and its locals decref'd on the way out. So how can they still be there after the crash? Because of section 1: the traceback holds strong references to every frame it captured. Each PyTracebackObject.tb_frame keeps its PyFrameObject alive even after the lightweight _PyInterpreterFrame on the C data stack is gone. This is precisely what "frame materialization" was for. The frames are dead in the sense that execution has left them. But they are still sitting on the heap, tethered by the traceback's tb_next chain. And CPython stashes that chain where you can reach it. After an unhandled top-level exception, sys.last_traceback (with sys.last_type and sys.last_value) points straight at it.

That is the entire mechanism behind post-mortem. pdb.pm() reads sys.last_traceback. Then pdb.post_mortem(tb) walks tb_next to the innermost node, the crash site, and opens the interactive prompt positioned in that frame. There frame.f_locals is the actual dict of live objects that existed when the exception fired. From there u and d walk the frame chain (tb_frame's f_back), so you can inspect any caller's real state too. Watch it turn a rerun-and-guess loop into a single shot:

>>> def crunch(rows):
...     total = 0
...     for r in rows:
...         total += int(r["n"])      # ValueError on a bad row
...     return total
...
>>> crunch([{"n": "10"}, {"n": "oops"}])
Traceback (most recent call last):
  ...
ValueError: invalid literal for int() with base 10: 'oops'
>>> import pdb; pdb.pm()          # re-enter the dead innermost frame
> <stdin>(4)crunch()
(Pdb) p r                          # the EXACT row that killed it — a live dict, not a string
{'n': 'oops'}
(Pdb) p total                      # the accumulator, frozen mid-loop at the crash
10
(Pdb) u                            # walk f_back up to the caller frame
(Pdb) p rows                       # the caller's real locals, still alive on the heap
[{'n': '10'}, {'n': 'oops'}]

No rerun, no advance guessing. The malformed row {'n': 'oops'} is right there in frame.f_locals as the actual dict object. And total shows the loop had accumulated 10 before it died: the state of the machine at the instant of failure, preserved. breakpoint() from the last section is the live counterpart. It arms the trace hook to drop you in before the crash, at a line you choose. Same frames, inspected either just before death or just after. Post-mortem is simply the after.

you type
# ---------- logging_taste.py -- before you configure anything ----------
import logging

log = logging.getLogger(__name__)      # a logger named after this module

log.debug("cache miss for track 7")    # invisible -- below the default threshold
log.info("library loaded")             # invisible -- same reason
log.warning("library file is empty")   # VISIBLE
log.error("library file is missing")   # VISIBLE


# ---------- logging_taste2.py -- one line of config changes everything ----------
import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(levelname)-8s %(name)s: %(message)s",
)
log = logging.getLogger(__name__)

log.debug("cache miss for track 7")
log.info("library loaded")
log.warning("library file is empty")
log.error("library file is missing")

you see
$ python logging_taste.py
library file is empty
library file is missing

   two calls vanished, and the two that printed carry no level and no name.
   that bare output is logging's "last resort" handler: WARNING and up, no format.

$ python logging_taste2.py
DEBUG    __main__: cache miss for track 7
INFO     __main__: library loaded
WARNING  __main__: library file is empty
ERROR    __main__: library file is missing

   same four calls. one config line, and every one of them speaks.

There is a sharp corollary hiding in all this, and it is a real memory bug people ship. Tracebacks pin frames, and frames pin their locals. So holding onto a traceback keeps an entire chain of frames — and every object they reference — alive. The most common way to do this by accident is to stash the exception itself. An except Exception as e gives you an e whose e.__traceback__ is the whole chain. Save that e in a list or a module global "for logging later" and you have quietly rooted a graph of dead frames and all their big local objects. That is a leak that grows with every handled error. This is exactly why Python automatically deletes the as e name at the end of an except block. And when you must keep something, the fix is to keep the message or a formatted string, or to call traceback.clear_frames(e.__traceback__), rather than the live exception.

# ---------- jukebox/storage.py ----------
"""storage.py -- save and load the library. Now it reports, instead of shouting."""
import json
import logging
from pathlib import Path

log = logging.getLogger(__name__)          # "jukebox.storage" -- it names itself


def save(tracks, path):
    log.debug("save() called: %d tracks -> %s", len(tracks), path)
    if not tracks:
        log.warning("saving an EMPTY library to %s", path)
    Path(path).write_text(json.dumps(tracks), encoding="utf-8")
    log.info("saved %d tracks to %s", len(tracks), path)


def load(path):
    log.debug("load() reading %s", path)
    if not Path(path).exists():
        log.error("no library at %s -- starting empty", path)
        return []
    tracks = json.loads(Path(path).read_text(encoding="utf-8"))
    log.info("loaded %d tracks from %s", len(tracks), path)
    return tracks


# ---------- logging_upgrade.py  (one level UP from the package) ----------
# logging_upgrade.py -- one switch decides how much the program tells you
import logging
import sys

from jukebox import storage

logging.basicConfig(
    level=logging.DEBUG if "-v" in sys.argv else logging.INFO,
    format="%(levelname)-8s %(name)s: %(message)s",
)
log = logging.getLogger("jukebox.main")

LIB = "library.json"
storage.save([["Titanium", 245], ["Levels", 340]], LIB)
log.info("titles on disk: %s", [t for t, _s in storage.load(LIB)])
storage.save([], LIB)
storage.load("missing.json")
log.debug("run finished")


# ---------- what storage.py used to say ----------
#     print("saving", len(tracks), "tracks to", path)
#     print("saved")
#     print("!!! no library at", path)

$ python logging_upgrade.py
INFO     jukebox.storage: saved 2 tracks to library.json
INFO     jukebox.storage: loaded 2 tracks from library.json
INFO     jukebox.main: titles on disk: ['Titanium', 'Levels']
WARNING  jukebox.storage: saving an EMPTY library to library.json
INFO     jukebox.storage: saved 0 tracks to library.json
ERROR    jukebox.storage: no library at missing.json -- starting empty

$ python logging_upgrade.py -v
DEBUG    jukebox.storage: save() called: 2 tracks -> library.json
INFO     jukebox.storage: saved 2 tracks to library.json
DEBUG    jukebox.storage: load() reading library.json
INFO     jukebox.storage: loaded 2 tracks from library.json
INFO     jukebox.main: titles on disk: ['Titanium', 'Levels']
DEBUG    jukebox.storage: save() called: 0 tracks -> library.json
WARNING  jukebox.storage: saving an EMPTY library to library.json
INFO     jukebox.storage: saved 0 tracks to library.json
DEBUG    jukebox.storage: load() reading missing.json
ERROR    jukebox.storage: no library at missing.json -- starting empty
DEBUG    jukebox.main: run finished

# ---------- sync.py -- converted ----------
import logging
import sys

log = logging.getLogger(__name__)


def sync_library(rows, path):
    log.debug("sync_library(%d rows) -> %s", len(rows), path)
    good = []
    for i, row in enumerate(rows):
        if "title" not in row:
            log.warning("row %d has no title, skipping: %r", i, row)
            continue
        log.debug("  keeping %s", row["title"])
        good.append(row)
    if not good:
        log.error("nothing to write to %s -- refusing to wipe the library", path)
        return good
    log.info("kept %d of %d rows for %s", len(good), len(rows), path)
    return good


if __name__ == "__main__":
    logging.basicConfig(
        level=logging.DEBUG if "-v" in sys.argv else logging.INFO,
        format="%(levelname)-8s %(name)s: %(message)s",
    )
    ROWS = [{"title": "Levels"}, {"secs": 271}, {"title": "Clarity"}]
    sync_library(ROWS, "library.json")
    sync_library([], "library.json")


# ---------- the two runs ----------
$ python sync.py
WARNING  __main__: row 1 has no title, skipping: {'secs': 271}
INFO     __main__: kept 2 of 3 rows for library.json
ERROR    __main__: nothing to write to library.json -- refusing to wipe the library

$ python sync.py -v
DEBUG    __main__: sync_library(3 rows) -> library.json
DEBUG    __main__:   keeping Levels
WARNING  __main__: row 1 has no title, skipping: {'secs': 271}
DEBUG    __main__:   keeping Clarity
INFO     __main__: kept 2 of 3 rows for library.json
DEBUG    __main__: sync_library(0 rows) -> library.json
ERROR    __main__: nothing to write to library.json -- refusing to wipe the library


# ---------- the level for each print, and the reason ----------
# "starting sync -> path"   -> DEBUG    tracing. nobody needs it on a good day.
# "rows in: N"              -> DEBUG    same. it folds into the DEBUG entry line.
# "  keeping TITLE"         -> DEBUG    one line PER ROW. never INFO: it would
#                                       bury the real events under a thousand
#                                       lines the moment the input grows.
# "BAD ROW at index i"      -> WARNING  odd input, but we carried on. This is the
#                                       textbook WARNING: a decision was made to
#                                       skip something, and someone should know.
# "!!! nothing to write"    -> ERROR    this operation FAILED. The caller's
#                                       intent -- sync the library -- did not happen.
# "done: N rows kept"       -> INFO     the normal, successful outcome. One line
#                                       per call, and it is the line you want in
#                                       production when everything is fine.
#
# Two changes beyond level-mapping, and both are the point of the exercise:
#
#   1. %r for the bad row.  log.warning("... %r", row) shows {'secs': 271} with
#      its quotes and braces intact. %s would flatten it and hide the types.
#
#   2. return early on the error.  The print version reported the disaster and
#      then cheerfully carried on to "done: 0 rows kept". A log level is not just
#      a label -- deciding something is an ERROR usually changes the control flow.
#
# And note what did NOT change: sync_library() never calls basicConfig. Only the
# __main__ block does. A function that configures logging steals that choice from
# whoever imports it.

You began this chapter flinching at a wall of red. You end it able to read that wall as the unwound stack, watch an exception travel and clean up as it goes, ride the interpreter's own hook into a frozen machine, binary-search to the first divergence, and re-enter the dead frames to read the truth. The traceback was never noise. It was Volume 1's stack, handing you the answer. →