トレースバックは下から上へ読む

一言でいうと

トレースバックで原因を語っているのは最下行で、その上のスタックは、どうやってそこまで至ったかを語っています。

なぜ必要なのか

トレースバックを初めて見ると、目は一番上に行きます。人は上から下へ読むよう訓練されているからです。しかし、Pythonのトレースバックの構造は、まったく逆です。

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'   ← 무엇이 왜

最下行が例外の種類と理由を語ります。そのすぐ上が実際に落ちたコード行です。上のほうは、そこまでどうやって到達したかの経路です。

そのため、実務でまず見るものは3つです。例外の名前、例外メッセージに含まれる実際の値、そしてすぐ上のフレームのファイルと行番号。この3つで、たいてい原因が確定します。ValueError: ... 'abc'は「数値であるはずの場所にabcが入ってきた」という意味で、そうなると次の問いは1つだけです。どの行がその'abc'を持っているのか。

どう動くのか

ここでよくあるミスが1つあります。出力をファイルに保存したのに、トレースバックが入っていない場合です。

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

トレースバックは標準出力ではなく標準エラー出力に出ます。顧客企業で「ログに何もない」と言われたとき、最初に確認すべきものがこれです。バッチジョブのcron設定に2>&1が抜けていて、何か月も失敗の原因がどこにも残っていないケースによく出会います。

修正そのものは、たいてい簡単です。難しいのはその次です。

現場での姿

壊れた行1つのせいで落ちるスクリプトを直すとき、2つの方法があります。

1つ目は、その行を読み飛ばすようにすることです。スクリプトが動き、今日の問題は終わります。

2つ目は、読み飛ばしながら何をなぜ読み飛ばしたかを残すようにすることです。来週同じことが起きても、ログファイルを1回開けば1分で終わります。

2つ目が計装の埋め込みです。再現しない問題を扱う正攻法でもあります。再現を目標にすると、何日も費やして作れずに終わりますが、目標を次回の観測に移せば、失敗しても残るものがあります。埋め込んでおいた計装は、このバグでなくても次のバグで使えます。

注意点も1つあります。タイミングや競合が原因の問題では、計装を入れる行為そのものがタイミングを変えて症状を隠してしまいます。そのようなときは、実行経路に割り込まない観測を選ぶ必要があります。すでに残っているログの時刻を突き合わせる、サンプリングで負荷を減らす、事後に状態をダンプする、といった方法です。

最後に、直したコードが別の入力でも正しいことを確認して初めて終わりです。今日のデータにだけ合わせた修正は、修正ではなく偶然です。

言語ごとに読む方向が違う

トレースバックは、言語ごとに順序が逆です。これを知らないと、見当違いの行を見ることになります。

言語	一番上	一番下
Python	一番外側(エントリーポイント)	エラーが起きた場所
Java	エラーが起きた場所	一番外側
Go (panic)	エラーが起きた場所	一番外側
JavaScript	エラーが起きた場所	一番外側

Pythonだけが逆なので混乱します。PythonはTraceback (most recent call last)と親切に書いてくれますが、その一文がそのまま「下が最新」という意味です。

ラップされたエラーを最後までたどる

フレームワークは、たいてい元の例外をラップします。本当の原因は連鎖の末端にあります。

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は、raise ... from eなら「direct cause」、例外処理中にさらに例外が起きたなら「During handling of the above exception」で区別します。後者はたいてい、エラー処理コード自体のバグというサインです。原因に対処しようとして、また落ちたのです。

JavaはCaused by:を後ろにつなげ、Goはerrors.Unwrapでほどきます。どちらの場合も、最も内側の例外のメッセージが調査の出発点です。

自分のコードに絞る方法

フレームワークのフレームが数十行もあると、目が滑ります。自分のコードだけを絞り出します。

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

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

そして、一番下(Pythonの場合)にある自分たちのコードのフレームが、たいてい本当の場所です。それより内側はライブラリで、ライブラリが間違っていることはまれです。こちらが渡した値が間違っているのです。

再現できないときに残すもの

本番でだけ起きるエラーは、スタックだけでは足りません。例外を捕まえる場所で、そのときの入力も一緒に残します。

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

原文の代わりにハッシュを残すのが要点です。個人情報をログに入れずに、同じ入力が再び来たかはわかります。

次のラボですること

ある日から失敗するバッチスクリプトのトレースバックを確保し、例外の種類と最初に失敗した行を特定し、仕様どおりに直したうえで、読み飛ばした行を記録する計装を埋め込み、最後にまったく別の入力ファイルで実行して、一般化できたことを確認します。