エラーメッセージとスタックトレースの読み方入門

シリーズ：テスト・デバッグ講座 1/6（初級）。 赤い文字の壁が出た瞬間に手が止まってしまう新人エンジニア向けです。読み終えると、Python、PHP、JavaScript、Java、Dart、Swift、C のエラー報告から「見るべき1行」を見つけ、答えが見つかる形で検索できるようになります。

新人研修の課題で「動きません」と先輩に聞きに行く前に、身につけておきたいのがこの技術です。コードレビューで「テストは？」と聞かれるより前に、まずエラーを自分で読めることが求められます。スタックトレースはノイズではなく、プログラムが諦めた瞬間に「どこにいたか」を正確に教えてくれる記録です。厄介なのは、言語ごとに表示の順番も、「この例外はあの例外が原因」という言い方も違い、しかも自分のコードと関係ない行が大量に混ざることです。

以下はすべて Apple Silicon Mac（M1 Pro）で実際に実行しました。Python 3.9.6、PHP 8.5.6、JavaScriptCore（macOS 付属の jsc）、OpenJDK 26、Dart 3.11.5、Swift 6.4.2、Apple clang 21 です。ホームディレクトリのパスは ~/demo/ に短縮し、それ以外に手を入れた箇所は … で示しています。

5分で読む最初のトレースバック

スタックトレース（Python ではトレースバック）は、エラーが起きた瞬間に実行中だった関数呼び出しの一覧です。1つ1つをフレームと呼び、1関数・1ファイル・1行に対応します。main が order_total を呼び、それが line_total を呼んで落ちたなら、フレームは3つです。

次を orders.py として保存し、2つ目の商品に qty（数量）がない order.json を隣に置きます。

import json
import sys


def load(path):
    with open(path) as f:
        return json.load(f)


def line_total(item):
    return item["price"] * item["qty"]


def order_total(order):
    return sum(line_total(item) for item in order["items"])


def main(path):
    order = load(path)
    print(order["id"], order_total(order))


main(sys.argv[1])

{"id": "S-2001", "items": [{"name": "ボールペン", "price": 120, "qty": 3}, {"name": "ノート", "price": 300}]}

$ python3 orders.py order.json
Traceback (most recent call last):
  File "~/demo/orders.py", line 23, in <module>
    main(sys.argv[1])
  File "~/demo/orders.py", line 20, in main
    print(order["id"], order_total(order))
  File "~/demo/orders.py", line 15, in order_total
    return sum(line_total(item) for item in order["items"])
  File "~/demo/orders.py", line 15, in <genexpr>
    return sum(line_total(item) for item in order["items"])
  File "~/demo/orders.py", line 11, in line_total
    return item["price"] * item["qty"]
KeyError: 'qty'

読む順番はこうです。

1. 最後の行がエラーの型とメッセージです。KeyError: 'qty'。KeyError は「辞書にそのキーがない」、メッセージは足りないキーの名前です。
2. 見出しに most recent call last（一番新しい呼び出しが最後）とあります。なのでエラーのすぐ上のフレーム、line_total の11行目が失敗した場所です。
3. 上にさかのぼるのは「どうやってそこに来たか」を知りたいときだけです。order_total がジェネレータ式（<genexpr>）から呼び、それを main が呼びました。

直す場所は line_total ではありません。正しい注文ならこのコードは動きます。おかしいのはデータです。注文を弾くか、qty を1とみなすか、JSON を作った側を直すかは仕様の判断です。トレースバックの仕事は正しい行と正しいキーを指すことで、それは果たしています。

落ちたフレームが自分のコードでないとき

今度は JSON を壊します（最後の要素の後ろに余計なカンマ）。トレースバックが長くなります。

$ python3 orders.py bad.json
Traceback (most recent call last):
  File "~/demo/orders.py", line 23, in <module>
    main(sys.argv[1])
  File "~/demo/orders.py", line 19, in main
    order = load(path)
  File "~/demo/orders.py", line 7, in load
    return json.load(f)
  File "…/lib/python3.9/json/__init__.py", line 293, in load
    return loads(fp.read(),
  File "…/lib/python3.9/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "…/lib/python3.9/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "…/lib/python3.9/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 70 (char 69)

下の4フレームは標準ライブラリの中です。ここが間違っていることはまずありません。見るべきは自分のファイルにある一番新しいフレーム、orders.py の7行目 json.load(f) です。そしてメッセージが入力のどこを見ればいいかを教えてくれます。

ここで日本語ならではの発見がありました。英語版の同じデータ（商品名が pen）では column 68 でしたが、ボールペン にすると column 70 になりました。Python の列番号はバイトではなく文字数で数えるので、5文字の ボールペン は3文字の pen より2つ後ろにずれます。エディタの列表示と同じ単位なので、そのままジャンプして構いません。

どの言語でも通じるルールは「標準ライブラリ、フレームワーク、ランタイムのフレームは飛ばし、自分が書いたパスが出てくるまで進む」です。Django や Laravel のアプリなら30フレーム飛ばすこともあります。エラーが起きたのは向こうのコードでも、原因はたいてい自分のコードが渡したものです。

連鎖する例外：「caused by」「During handling」「Next」

実際のコードでは低レベルの例外を捕まえて、文脈を付けて投げ直します。すると1つの報告に2つのトレースが並び、順番が重要になります。

def parse_order(text):
    try:
        data = json.loads(text)
        return data["id"], data["items"][0]["qty"]
    except KeyError as e:
        raise OrderError("order S-2001 is missing a field") from e

Traceback (most recent call last):
  File "~/demo/chained.py", line 12, in parse_order
    return data["id"], data["items"][0]["qty"]
KeyError: 'qty'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "~/demo/chained.py", line 27, in <module>
    parse_order(text)
  File "~/demo/chained.py", line 14, in parse_order
    raise OrderError("order S-2001 is missing a field") from e
__main__.OrderError: order S-2001 is missing a field

raise … from e は意図的な連鎖です。元の KeyError が先、包んだ側が後に出ます。これと、except ブロックの中にバグがある場合を比べてください。

Traceback (most recent call last):
  File "~/demo/chained.py", line 20, in parse_order_sloppy
    return data["id"], data["items"][0]["qty"]
KeyError: 'qty'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "~/demo/chained.py", line 29, in <module>
    parse_order_sloppy(text)
  File "~/demo/chained.py", line 22, in parse_order_sloppy
    log.warning("bad order: %s", text)   # bug: 'log' was never defined
NameError: name 'log' is not defined

「During handling」はバグが2つあるという意味です。データの問題と、壊れたエラーハンドラ（log が未定義）です。障害対応でよく見る形で、エラー報告の経路はどのシステムでも一番テストされていないコードです。

Java は包んだ側を先に、元の例外を Caused by: の後に出します。

$ java Orders.java
Exception in thread "main" java.lang.IllegalArgumentException: bad qty in order S-2001
    at Orders.loadQty(Orders.java:19)
    at Orders.main(Orders.java:28)
Caused by: java.lang.NumberFormatException: For input string: "3 "
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
    at java.base/java.lang.Integer.parseInt(Integer.java:527)
    at java.base/java.lang.Integer.parseInt(Integer.java:624)
    at Orders.loadQty(Orders.java:17)
    at Orders.main(Orders.java:28)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    … ランチャーのフレーム4行を省略

答えは引用符の中にあります。"3 " の末尾に空白があり、Integer.parseInt は空白を取り除きません。CSV や Excel から来た値でよくあります。長い Java のトレースでは最後の Caused by: までスクロールするのが鉄則です。

PHP は Next という語を使い、元の例外が先に出ます。

$ php -d display_errors=0 orders.php bad
PHP Fatal error:  Uncaught JsonException: Syntax error in ~/demo/orders.php:18
Stack trace:
#0 ~/demo/orders.php(18): json_decode('{"id":"S-2002",...', true, 512, 4194304)
#1 ~/demo/orders.php(28): loadOrder('{"id":"S-2002",...')
#2 {main}

Next RuntimeException: cannot parse order in ~/demo/orders.php:20
Stack trace:
#0 ~/demo/orders.php(28): loadOrder('{"id":"S-2002",...')
#1 {main}
  thrown in ~/demo/orders.php on line 20

PHP は各呼び出しの引数を15文字で切って表示します。デバッガなしで悪い入力に気づけることがよくあります。-d display_errors=0 を付けたのは、PHP CLI が既定ではログ経由の stderr と stdout の両方に同じエラーを2回出すためです。

同じバグを7つのランタイムで

「qty がない」バグが他の言語でどう見えるかを並べます。そもそも落ちないものに注目してください。

PHP 8.5 は存在しない配列キーを警告として扱い、null のまま進みます。

$ php -d display_errors=0 orders.php missing
PHP Warning:  Undefined array key "qty" in ~/demo/orders.php on line 5
0

合計は 0、終了コードも 0。このままリリースされます。開発中は PHP の警告をエラー扱いにしましょう。

JavaScript（jsc）は欠けたフィールドで黙って NaN を出し、オブジェクトそのものがないときに初めて落ちます。

$ jsc orders.js
S-2001 total: NaN
Exception: TypeError: undefined is not an object (evaluating 'order.items.reduce')
orderTotal@orders.js:5:21
global code@orders.js:10:34

形式は 関数名@ファイル:行:列 で、新しいものが上です。undefined is not an object は JavaScriptCore（Safari）の言い回しで、Chrome や Node の V8 では同じバグが Cannot read properties of undefined (reading 'reduce') になります（ここでは未実行）。new Error("…", { cause: e }) で投げた場合、jsc の未捕捉エラー出力には cause が表示されませんでした。e.cause を自分で出力する必要があります。

Java 26 はどの値が null だったかをメッセージに書いてくれます（helpful NullPointerException）。

Exception in thread "main" java.lang.NullPointerException: Cannot invoke "java.lang.Integer.intValue()" because the return value of "java.util.Map.get(Object)" is null
    at Orders.lineTotal(Orders.java:6)
    at Orders.orderTotal(Orders.java:11)
    at Orders.main(Orders.java:26)

Dart は番号付きのフレームを新しい順に出し、ランタイム自身のフレームが下に来ます。

Unhandled exception:
type 'Null' is not a subtype of type 'int' in type cast
#0      lineTotal (file://~/demo/orders.dart:4:48)
#1      orderTotal (file://~/demo/orders.dart:10:12)
#2      main (file://~/demo/orders.dart:17:9)
#3      _delayEntrypointInvocation.<anonymous closure> (dart:isolate-patch/isolate_patch.dart:314:19)
#4      _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:193:12)

「Null は int のサブタイプではない」は「ない値を int にキャストした」という Dart 流の言い方です。Flutter で API の JSON を扱っていると毎日のように出会います。

Swift は1行だけ出して、終了コード133（トラップ）で終わります。

$ ./orders_swift
orders_swift/orders.swift:4: Fatal error: Unexpectedly found nil while unwrapping an Optional value

スタックを見るには lldb の下で動かして bt（backtrace）と打ちます。フレーム0〜3は Swift ランタイムがエラーを報告している部分で、フレーム4が自分のコードです。壊れた引数まで表示されます。日本語の商品名もそのまま出ています。

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = Fatal error: Unexpectedly found nil while unwrapping an Optional value
     frame #0: … libswiftCore.dylib`_swift_runtime_on_report
     frame #1: … libswiftCore.dylib`_swift_stdlib_reportFatalErrorInFile + 204
     frame #2: … libswiftCore.dylib`closure #1 in closure #1 in _assertionFailure(_:_:file:line:flags:) + 400
     frame #3: … libswiftCore.dylib`_assertionFailure(_:_:file:line:flags:) + 276
   * frame #4: 0x0000000100000dc8 orders_swift`lineTotal(name="ノート", qty=1) at orders.swift:4:24
     frame #5: 0x0000000100000ac8 orders_swift`orderTotal(items=2 values) at orders.swift:9:39
     frame #6: 0x0000000100000824 orders_swift`main at orders.swift:13:7
     frame #7: … dyld`start + 6992

一番怖いのは C です。i <= n_items のループが、malloc した3要素の配列の1つ先を読みます。普通にビルドすると 500 と表示して終了コード0。余分に読んだ場所がたまたま0だっただけです。AddressSanitizer（-fsanitize=address -g）でビルドすると、最初の不正な読み取りで止まります。

==36607==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x6020000000fc at pc 0x0001029f0a8c bp 0x00016d40e320 sp 0x00016d40e318
READ of size 4 at 0x6020000000fc thread T0
    #0 0x0001029f0a88 in line_total orders.c:5
    #1 0x0001029f09dc in order_total orders.c:11
    #2 0x0001029f0964 in main orders.c:18
    #3 0x000188a244e0 in start+0x1b4c (dyld:arm64e+0x204e0)

0x6020000000fc is located 0 bytes after 12-byte region [0x6020000000f0,0x6020000000fc)
allocated by thread T0 here:
    #0 0x0001033ad274 in malloc+0x78 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x41274)
    #1 0x0001029f082c in main orders.c:16
    #2 0x000188a244e0 in start+0x1b4c (dyld:arm64e+0x204e0)

SUMMARY: AddressSanitizer: heap-buffer-overflow orders.c:5 in line_total
… シャドウバイトの表 30行

報告全体は47行ありますが、必要なのは3つだけです。エラーの種類（heap-buffer-overflow）、最初のスタックの #0（orders.c:5）、そして「0 bytes after 12-byte region」。これは「int 3個の配列の、終わりのすぐ次の要素を読んだ」という意味です。2つ目のスタックはその配列を確保した場所です。下のシャドウバイトの表はサニタイザ開発者向けなので飛ばして構いません。

早見表：どちらが新しいか、連鎖を示す語は何か

研修の最初の週に出会うエラーも、実際の出力から集めました。

よくある間違い：メッセージだけを表示する

間違い。 例外を捕まえて、そのまま表示します。

try:
    total = order["items"][0]["price"] * order["items"][0]["qty"]
except Exception as e:
    print("error:", e)                 # 初心者が書きがちな形
    print("repr: ", repr(e))           # 型が分かるだけまし
    traceback.print_exc()              # 一番よい：全部が分かる

実際に起きること。

error: 'qty'
repr:  KeyError('qty')
Traceback (most recent call last):
  File "~/demo/swallow.py", line 5, in <module>
    total = order["items"][0]["price"] * order["items"][0]["qty"]
KeyError: 'qty'

KeyError の str(e) はただの 'qty' です。障害対応中に error: 'qty' だらけのログを渡されても、何の例外で、どこから来たのか誰にも分かりません。直し方は、型とスタックを残すことです。traceback.print_exc()、実際のコードなら logger.exception(...)（第2回で実演します）。どの言語でも同じで、Java は e.printStackTrace() か例外を最後の引数に渡したロガー、PHP は (string) $e、JavaScript は e.stack です。

もう1つの定番は、json/decoder.py を開いて標準ライブラリを直そうとすることです。一番新しいフレームが自分の書いていないコードなら、自分が書いた一番新しいフレームまで上がってください。

エラーメッセージの上手な検索のしかた

検索エンジンも課題管理システムも単語で照合します。エラー行には、他の誰も持っていない単語が入っています。ホームディレクトリ、注文番号、メモリアドレス、プロセス ID です。これを取り除きます。上の例には次の小さなフィルタで足ります。

import re
import sys

RULES = [
    (r"(?:[A-Za-z]:)?(?:/[\w.@~-]+)+/", ""),        # directories -> keep file name only
    (r"0x[0-9a-fA-F]+", ""),                          # addresses
    (r"==\d+==", ""),                                 # sanitizer PIDs
    (r"'[^']{12,}'|\"[^\"]{12,}\"", "'…'"),          # long quoted user data
    (r"\b[A-Z]-\d+\b|\b\d{4,}\b", ""),                # ids, big numbers
    (r"\s+", " "),
]


def error_key(line):
    for pattern, repl in RULES:
        line = re.sub(pattern, repl, line)
    return line.strip()


for raw in sys.stdin:
    if raw.strip():
        print(error_key(raw))

$ python3 errkey.py < samples.txt
FileNotFoundError: [Errno 2] No such file or directory: '…'
PHP Fatal error: Uncaught JsonException: Syntax error in orders.php:18
java.lang.IllegalArgumentException: bad qty in order
ERROR: AddressSanitizer: heap-buffer-overflow on address at pc bp sp

残った固定部分を引用符で囲み、言語名やライブラリ名、最近挙動が変わったならそのバージョンを足して検索します。例："Unexpectedly found nil while unwrapping an Optional value" swift dictionary。英語のメッセージは英語のまま検索した方が答えが多く見つかります。自分たちのコードが出したメッセージ（bad qty in order）なら、Web 検索は無意味です。自分のリポジトリをその文字列で検索すれば、throw している行に直行できます。

正直な限界とバージョンの注意

• Python 3.9 はこの Mac の Xcode コマンドラインツールに付属するものです。Python 3.11 では失敗した部分式の下に ^^^^ が付き、3.10 では NameError や AttributeError に「Did you mean …?」の候補が出ます。どちらもここでは未実行です。
• Java の詳しい NullPointerException メッセージは JDK 14（JEP 358）で入り、JDK 15 で既定で有効になりました。確認したのは 26 です。Caused by にランチャーのフレームが出たのは単一ファイル実行（java Orders.java）のためで、コンパイルしたアプリでは ... N more と省略されます。
• JavaScript の Error の cause オプションは ES2022 です。Node やブラウザは cause の表示が jsc と違います。実行したのは jsc だけです。
• Swift 組み込みのクラッシュ時バックトレースは、この環境では「backtrace-on-crash is not supported for privileged executables」と表示されて動かなかったため、lldb を使いました。Linux では既定で有効です。
• ASan の行数やアドレスは実行ごとに変わりますが、フレームは変わりません。

練習問題

1. Python のトレースバックが ValueError: invalid literal for int() with base 10: '3 a' で終わり、最後の3フレームが ~/project/app.py、…/site-packages/pandas/…、…/site-packages/pandas/… です。まずどこを見ますか？
2. Java のログに IllegalStateException: checkout failed があり、Caused by: が2つ続きます。SQLException、その次に SocketTimeoutException。調べるのはどれですか？
3. 次を良い検索語にしてください。PHP Warning: Undefined array key "qty" in /var/www/shop/src/orders.php on line 5

解答

1. app.py の一番新しいフレームです。そこが '3 a' を pandas に渡した行です。pandas は自分のバグではなく、あなたのデータを報告しています。
2. 最後の SocketTimeoutException です。DB 呼び出しがタイムアウトし、上はすべて包み直しです。次に、ネットワークか DB がなぜ遅かったかを調べます。
3. "Undefined array key" php、必要なら PHP のバージョンを足します。パス、行番号、qty は消します。とはいえ先に5行目を読むのが一番です。メッセージがすでに「キーがない」と言っています。

---

次回：第2回 print・ログ・デバッガの使い分け · このシリーズの続き：初めての単体テスト、モックとフィクスチャ、不安定なテスト、git bisect。サニタイザと lldb をさらに知りたい人は C の未定義動作 へ。プログラミング学習ロードマップに戻る。