Reading a Traceback From the Bottom Up

Part I · Module 14 · Chapter 14.2 · Reading a Traceback From the Bottom Up

1. The Header Is an Instruction

Every runtime failure in Chapter 14.1 began with the same line:

Traceback (most recent call last):

That parenthesis is not decoration. It says the frames below are printed in call order — oldest first, newest last — so the most recent call, the one that actually failed, is at the bottom.

The error itself is on the very last line, below every frame.

So the document is organised with the conclusion at the end, and almost everyone reads it from the top, where the least useful information lives.

2. Three Questions

A traceback answers three questions, and they live in three different places:

Traceback (most recent call last):
  File "check.py", line 9, in <module>
    n = count(path)
FileNotFoundError: [Errno 2] No such file or directory: 'sim.log'

1. What went wrong? — the last line. A type (FileNotFoundError) and a message ('sim.log' does not exist).
2. Where, in code I own? — the lowest File line naming a file you wrote. Here there is only one: check.py, line 9.
3. How did we get there? — the frames above it, read upward.

Question 1 is free. Question 2 is where you put the cursor. Question 3 is what you need when the answer to question 2 looks perfectly correct.

3. A Real One

This script summarises test results. One of the dictionaries is missing a key:

def count_errors(text):
    return len(text["errors"])


def summarise(result):
    return f"{result['test']}: {count_errors(result)} errors"


def main():
    results = [
        {"test": "smoke", "errors": ["E1", "E2"]},
        {"test": "cdc"},
    ]
    for r in results:
        print(summarise(r))


main()

smoke: 2 errors
Traceback (most recent call last):
  File "check.py", line 18, in <module>
    main()
    ~~~~^^
  File "check.py", line 15, in main
    print(summarise(r))
          ~~~~~~~~~^^^
  File "check.py", line 6, in summarise
    return f"{result['test']}: {count_errors(result)} errors"
                                ~~~~~~~~~~~~^^^^^^^^
  File "check.py", line 2, in count_errors
    return len(text["errors"])
               ~~~~^^^^^^^^^^
KeyError: 'errors'

Before reading further: note smoke: 2 errors at the top. One result was summarised successfully. This is the Chapter 14.1 signature of a runtime error, and it is already a clue — whatever is wrong is specific to the second result, not to the code in general.

4. Answering the Three Questions

Question 1 — what went wrong? Last line: KeyError: 'errors'. Chapter 14.3 catalogues the types; for now, a KeyError means a dictionary was asked for a key it does not have, and the message names the key: 'errors'.

Question 2 — where? The lowest frame is check.py, line 2, inside count_errors. That is the line that failed:

  File "check.py", line 2, in count_errors
    return len(text["errors"])

Question 3 — how did we get here? Reading upward from there:

• line 2, in count_errors ← called from
• line 6, in summarise ← called from
• line 15, in main ← called from
• line 18, at module level

So main looped, handed a result to summarise, which handed it to count_errors, which asked for "errors" and did not find it.

5. The Bug Is Usually Not Where the Error Is

Look at line 2 on its own:

return len(text["errors"])

There is nothing wrong with it. It is exactly what count_errors should do. The mistake is on line 12 — a result dictionary written without an "errors" key:

{"test": "cdc"},

This is the single most useful thing to internalise about tracebacks. The lowest frame is where the program noticed, not necessarily where you went wrong. The error surfaces at the first instruction that cannot cope with the bad value; the bad value was created somewhere above, possibly several frames up, possibly in data that was written by hand.

The frames between are how you walk back from the symptom to the cause, which is why question 3 exists at all.

6. When the Deepest Frame Is Not Yours

Split that work across two files, exactly as Chapter 13.5 taught:

def runtime_of(line):
    """The runtime is the third whitespace-separated field."""
    return float(line.split()[2])

from parse import runtime_of

LINES = [
    "smoke  PASS  182.4",
    "cdc    PASS  204.1",
    "reset  FAIL",
]


def total():
    seconds = 0.0
    for line in LINES:
        seconds += runtime_of(line)
    return seconds


print(f"total runtime: {total():.1f}s")

Traceback (most recent call last):
  File "report.py", line 17, in <module>
    print(f"total runtime: {total():.1f}s")
                            ~~~~~^^
  File "report.py", line 13, in total
    seconds += runtime_of(line)
               ~~~~~~~~~~^^^^^^
  File "parse.py", line 3, in runtime_of
    return float(line.split()[2])
                 ~~~~~~~~~~~~^^^
IndexError: list index out of range

Now the frames name two different files, and that is the common shape in real work — except that the deepest file is usually not one of yours at all, but something inside the standard library or a package you installed.

The rule that keeps you out of other people's source code:

Find the lowest frame whose file you wrote. Start there.

Here that is report.py line 13, which is passing "reset FAIL" — a line with only two fields — into a function that requires three. The failure is reported in parse.py, the decision that caused it is in report.py, and the actual defect is arguably in neither: the data has a shape the code never considered.

7. The Caret Lines Narrow It Further

Those ~~~~^^^ lines under each frame are not underlines for the whole statement. They mark the exact subexpression that failed:

  File "check.py", line 6, in summarise
    return f"{result['test']}: {count_errors(result)} errors"
                                ~~~~~~~~~~~~^^^^^^^^

The ^^^^ sits under (result) and the ~~~~ under count_errors — the call that raised. On a line with one operation this is redundant. On a line with three, it is the difference between reading and guessing:

    seconds += runtime_of(line)
               ~~~~~~~~~~^^^^^^

and

    return float(line.split()[2])
                 ~~~~~~~~~~~~^^^

That second one is precise in a way worth pausing on. The carets are under [2], not under float(...). So the subscript failed, not the conversion — line.split() returned a list too short to have an index 2. Without the carets you would have to work out which of the two calls on that line was responsible.

8. What <module> Means

Every traceback in this chapter ends its topmost frame with in <module>:

  File "check.py", line 18, in <module>
    main()

<module> is the name Python uses for code at the top level of a file — code that is not inside any function. It is the same __name__-related machinery Chapter 13.6 used: the top-level code of the file you ran.

So a frame reading in <module> means "this happened at the outermost level of this file", and a frame reading in main means "inside the function main". When you see <module> at the bottom rather than the top, your failure happened before any function was entered — often an import or a constant definition.

9. Predict, Run, Observe

def depth_three(d):
    return d["c"]


def depth_two(d):
    return depth_three(d)


def depth_one(d):
    return depth_two(d)


print("A:", depth_one({"c": 1}))
print("B:", depth_one({"x": 1}))

A: 1
Traceback (most recent call last):
  File "layers.py", line 14, in <module>
    print("B:", depth_one({"x": 1}))
                ~~~~~~~~~^^^^^^^^^^
  File "layers.py", line 10, in depth_one
    return depth_two(d)
  File "layers.py", line 6, in depth_two
    return depth_three(d)
  File "layers.py", line 2, in depth_three
    return d["c"]
           ~^^^^^
KeyError: 'c'

A: 1 printed. The first call worked all the way down and back.

Four frames, one per call. The stack is three functions deep plus the module level, and the traceback has exactly four File lines. A traceback's height is the call depth, not a measure of how bad the problem is.

The lowest frame is depth_three, but nothing there is wrong — it is the only place that reads "c", so it is the first place that could notice.

The cause is on line 14, the topmost frame: a dictionary built without "c". Symptom at the bottom, cause at the top, and in this file they are twelve lines apart.

Two frames have no caret lines at all. return depth_two(d) and return depth_three(d) are printed bare, while the other two frames are annotated. Python only draws the anchors when they narrow something: on a line whose entire expression is the failing call, there is nothing to point at that the line does not already say. Their absence is information — it means the whole line is the call.

10. Exercises

Exercise 1 — the three facts. Take the check.py traceback in Section 3 and write down, in three short sentences, the answers to the three questions in Section 2 without re-reading the prose.

Exercise 2 — build a deep one. Write four functions that call each other in a chain, the deepest raising IndexError. Count the File lines and confirm the count equals your call depth plus one.

Exercise 3 — symptom versus cause. Modify check.py so the missing key is created by a typo in a different function rather than in a literal. Confirm the traceback is unchanged and say why that makes question 3 necessary.

Exercise 4 — two files. Reproduce Section 6 as two real files. Then add a third file in the chain and confirm the new frame appears in the expected place.

Exercise 5 — read the carets. Write a line containing three calls, where the middle one fails. Run it and confirm the carets sit under the middle call only.

Exercise 6 — <module>. Produce a traceback whose only frame says in <module>. Say what that tells you about when the failure happened.

Exercise 7 — partial output. Write a loop that prints two successful lines before failing on the third item. Explain what those two lines tell you before you have read a single frame.

Exercise 8 — the lowest frame you own. Call a standard-library function with an argument it rejects — for example int("x") — so the deepest frame is not your file. Identify the lowest frame you own and say what you would change.

11. Summary

• (most recent call last) is an instruction: the newest frame is at the bottom, so read upward.
• The last line is the error — a type and a message, and the message usually names the offending value.
• The lowest frame you own is where to start looking, not necessarily where the bug is.
• The frames above are the call chain, and they are how you walk from symptom to cause.
• The error surfaces where the bad value is first used, which can be several frames below where it was created.
• A library frame at the bottom almost always means you passed it something it does not accept.
• The caret lines narrow a failure to a subexpression, which matters on any line with more than one call.
• in <module> means top-level code of that file, outside any function.
• A traceback's height is the call depth, not a measure of severity.

The next chapter names the error types you will meet at the bottom of these, and the one mistake each usually indicates.