Read a Traceback From the Bottom Up

One-line summary

In a traceback, it is the bottom line that tells you the cause, and the stack above it tells you how it got there.

Why this is needed

When you first look at a traceback, your eyes go to the top. That is because people are trained to read from top to bottom. But the structure of a Python traceback is exactly the opposite.

Traceback (most recent call last):
  File "report.py", line 34, in <module>      ← 가장 바깥 호출
    sys.exit(main(*sys.argv[1:]))
  File "report.py", line 26, in main          ← 실제로 터진 자리
    amount = int(parts[2])
ValueError: invalid literal for int() with base 10: 'abc'   ← 무엇이 왜

The bottom line tells you the exception type and the reason. Right above it is the line of code that actually blew up. The upper part is the path of how it got there.

So in practice there are three things to look at first: the exception name, the actual value included in the exception message, and the file and line number of the frame right above. These three usually settle the cause. ValueError: ... 'abc' means "abc came in where a number should be," and then there is only one next question — which row has that 'abc'.

How it works

There is one common mistake here. It is when you saved the output to a file but the traceback is not in it.

python3 report.py > out.txt        # 트레이스백이 안 담긴다
python3 report.py > out.txt 2>&1   # 담긴다

A traceback goes out not to standard output but to standard error. When you hear "there's nothing in the log" from a customer, this is the first thing to check. You often run into cases where 2>&1 is missing from a batch job's cron setup, so for months the cause of the failure has been recorded nowhere.

The fix itself is usually simple. The hard part is what comes after.

What you see in the field

When you fix a script that dies because of one malformed row, there are two ways.

The first is to make it skip that row. The script runs, and today's problem is over.

The second is to make it skip while recording what was skipped and why. If the same thing happens next week, opening the log file once settles it in a minute.

The second is planting instrumentation. It is also the standard approach for problems that cannot be reproduced. If you make reproduction your goal, you spend days and end up unable to produce it, but if you shift the goal to the next observation, something is left even if you fail. The instrumentation you plant is used for the next bug, even if it is not this one.

There is one caution. For problems caused by timing and contention, the very act of adding instrumentation changes the timing and hides the symptom. In such cases you must choose observation that does not intrude on the execution path. That means lining up the timestamps of logs that are already being produced, reducing overhead with sampling, or dumping state after the fact.

Finally, you are done only when you confirm that the fixed code is right for other inputs too. A fix tuned only to today's data is not a fix but a coincidence.

The reading direction differs by language

The order of a traceback is reversed depending on the language. If you do not know this, you look at the wrong line.

Language	Top	Bottom
Python	The outermost (entry point)	Where the error occurred
Java	Where the error occurred	The outermost
Go (panic)	Where the error occurred	The outermost
JavaScript	Where the error occurred	The outermost

Only Python is reversed, which is what makes it confusing. Python kindly writes Traceback (most recent call last), and that sentence means "the bottom is the latest."

Following a wrapped error to the end

Frameworks usually wrap the original exception. The real cause is at the end of the chain.

Traceback (most recent call last):
  ...
psycopg.OperationalError: connection failed

The above exception was the direct cause of the following exception:   ← __cause__
Traceback (most recent call last):
  ...
app.errors.StorageUnavailable: 저장소에 닿을 수 없습니다

Python labels it "direct cause" for raise ... from e, and if another exception occurs while handling one, it labels it "During handling of the above exception." The second is usually a signal of a bug in the error handling code itself — it died again while trying to deal with the cause.

Java appends Caused by: further down, and Go unwraps with errors.Unwrap. Either way, the message of the innermost exception is the starting point of the investigation.

How to narrow down to your own code

When the framework frames run to dozens of lines, your eyes slide. Filter for only your own code.

# 스택에서 우리 패키지만
grep -E 'File "/app/' traceback.txt

# pytest — 우리 코드 프레임만 보여 준다
pytest --tb=short -p no:cacheprovider

And the lowest frame of your own code (by Python's ordering) is usually the real spot. Anything deeper than that is a library, and it is rare for the library to be wrong. The value we passed in was wrong.

What to leave when you cannot reproduce it

For errors that occur only in production, the stack alone is not enough. At the place where you catch the exception, leave the input at that time as well.

except Exception:
    log.exception("주문 처리 실패", extra={
        "order_id": order.id,
        "payload_hash": hashlib.sha256(raw).hexdigest()[:12],   # 원문은 남기지 않는다
        "trace_id": current_trace_id(),
    })
    raise

The point is to leave a hash instead of the raw text. You do not put personal data in the log, yet you can still tell whether the same input came again.

What you will do in the next lab

You capture the traceback of a batch script that fails from a certain day, identify the exception type and the first failing row, fix it according to the spec, plant instrumentation that records the skipped rows, and finally run it on a completely different input file to confirm that it generalizes.