ERRORは見つけた、原因が見つからない — ログの因果を遡る4つの技法

grep ERROR は通った。赤い行は目の前にある。それでも報告書の「原因」欄が埋まらない。

障害調査でいちばん時間を食うのは、エラーを見つける工程ではありません。見つけたエラーから、その手前にある因果へ遡る工程です。ERROR行は結果の記録であって、原因の記録ではない。原因は、その少し前・別のスレッド・別のレイヤに、たいてい違う顔をして書かれています。

この記事では、遡り方の型を4つ並べます。時間軸で遡る、例外の連鎖で遡る、途切れた末尾から遡る、繰り返しの分布で遡る。どれも手持ちのコマンドで試す前提で書き、そのうえで、その手がどこで止まるかまで踏み込みます。

1. 「直前の行」が原因とは限らない — 出力順と発生順のズレ

状況

ERRORの1行上を見た。無関係なアクセスログだった。もう1行上も、その上も関係ない。定石どおり手前を読んでいるのに、因果らしきものが出てこない。（基本の追い方そのものは ERRORは見つかった。原因は「その前」にある で扱いました。ここではその定石が成立しない条件を見ます。）

なぜ起きるか

ログファイルの行の並びは、イベントが起きた順ではなく、書き込まれた順です。この2つがズレる要因は珍しくありません。

バッファリングと非同期ロギング。 多くのロガーは書き込みを溜めてまとめて出し、キューを挟んで別スレッドが書き出す構成も一般的です。ERRORだけ即時フラッシュする設定はERRORが手前に飛び出すズレを生み、キューの詰まりは順序を入れ替えます。負荷が高い瞬間ほどキューは詰まる——つまり、いちばん知りたい障害の瞬間ほど順序が信用できないという、質の悪い性質があります。

行の割り込み。 複数スレッド・複数プロセスが同じファイルに書けば、1つの処理の記録は連続しません。10行のスタックトレースの途中に、別スレッドのINFOが挟まる。目で追っている「直前の行」は、別の物語の1行です。

汎用ツールでの対処と限界

まずやることは、時刻ではなく識別子で束ねることです。リクエストID・トレースID・スレッドIDのいずれかが出ていれば、grep 'req-8f3a' で1本の処理だけを抜き出せます。その中の順序は、少なくとも同一スレッド内では信用できます。

限界は2つ。ひとつは、識別子で抜くと文脈が消えること。その処理だけの記録は綺麗ですが、「同じ瞬間に別スレッドで何が起きていたか」が落ちます。共有リソースの枯渇やロック競合は、抜き出した1本の中には書かれていません。

もうひとつは、抜いたものが原本と切り離されること。grep -n で行番号を付けても、そこから原本の該当位置に戻って周囲を広く見る往復は手作業になります。障害調査は、この往復の回数で時間が決まります。

2. Caused by の連鎖 — 「1個目の例外」を探す

状況

スタックトレースは出ている。しかし先頭に書かれているのは ServiceException: request failed のような、何も言っていない例外です。本当の原因は Caused by: の下、さらにその下の Caused by: の、もっと下にある。

なぜ起きるか

例外のラップは、レイヤ境界での正しい作法です。DAOが投げた SQLException をサービス層が DataAccessException で包み、コントローラが ApiException で包む。各層は自分の言葉で語り直し、元の例外を cause として保持します。

結果として、ログに落ちるトレースは外側から内側へ書かれます。人が読みたい順序（根本原因＝最内側）とは逆です。しかも各例外が数十行のフレームを連れているので、3段ラップされたトレースは軽く100行を超えます。

さらに厄介なのが ... 47 more です。共通フレームは省略されるため、省略された中に手がかりがある場合、そのトレースだけでは追えません。そしてスタックトレースは複数行で1つの意味を持ちます。行単位で切り出す道具とは、そもそも相性が悪い。

汎用ツールでの対処と限界

Caused by: の位置を並べ、トレース1件を行数決め打ちで切り出すところまではすぐできます。

grep -n "Caused by:" app.log | tail -20  # 連鎖の位置を並べる
sed -n '1043210,1043400p' app.log        # その位置から190行を切り出す

限界は、190行が足りるかどうかが、切り出してみるまで分からないことです。足りなければ数字を増やして再実行。多すぎれば次のトレースが混ざる。ラップの段数はエラーの種類ごとに違うので、決め打ちの幅は毎回外れます。

この「切り出して、足りなくて、やり直す」を数十件のトレースに繰り返すことになる。閲覧の問題を、切り出しの繰り返しで解こうとしている構図です。加えて sed -n の行番号指定は先頭から数えるため、数億行のファイルの後半を切り出すには待ちが入ります。

3. コアダンプは無い — ログの「途切れ方」からクラッシュ位置を読む

状況

プロセスが落ちた。コアダンプは設定されていない、あるいは ulimit -c 0 で採られていない。手元にあるのは、途中でぷつりと終わっているログファイルだけ。

なぜ起きるか

クラッシュ時のログには、通常の障害とは違う特徴が出ます。

末尾が不完全になる。 バッファに残っていた分が書かれずに落ちるため、最後の行が途中で切れていることがあります。改行で終わっていないファイル末尾は、それ自体が「正常な終了処理を通っていない」という情報です。

最後の記録は原因の少し後ろ。 バッファリングのぶん、ログに残った最終行より少し先まで処理は進んでいます。末尾の行は「ここで落ちた」ではなく「ここまでは確実に到達した」と読むのが正しい。犯人はその先にいます。

そもそもアプリログに書かれない死に方がある。 OOM Killer による強制終了は dmesg や /var/log/messages 側に出ます。シグナルでの即死も、ハンドラが無ければアプリログには1行も残りません。「原因不明の突然死」に見える現象の相当数がこれです。

汎用ツールでの対処と限界

末尾の状態を確かめるのは簡単です。

tail -c 1 app.log | xxd          # 末尾1バイトが 0a か
tail -50 app.log                 # 最後の記録

あとは直近の正常終了時のログと比べます。前回まで毎回出ていた「シャットダウン開始」が今回は無い、といった差分そのものが証拠になります。

限界は、この調査が本質的に「末尾と、過去の似た箇所を、行ったり来たりする」作業だという点です。tail は末尾しか見せません。過去の正常時のパターンを探すには全体の検索が要り、見つけた位置の周囲を読むにはまた別の操作が要る。しかもクラッシュ調査では原本に触れないことが重要で、読むために編集ツールを開くという選択自体がリスクになります。

4. 「何回出たか」を数えると、文脈が消える

状況

同じERRORが延々と出ている。まず件数を知りたくて grep ERROR app.log | wc -l を叩いた。「1,847件」と出た。それで、次に何をすればいいのか分からなくなった。

なぜ起きるか

件数は、それ単体ではほとんど何も語らない数字だからです。

時間分布。 1,847件が24時間に均等に散っているなら平常運転の既知のノイズかもしれず、3分間に集中しているならそれは事故です。同じ数字が、意味としては正反対になる。「いつから出始めたか」も件数からは出てきません。

内訳。 全部同じメッセージなのか、5種類が混ざっているのか。混ざっている場合、量が多いものが原因とは限りません。1件だけ出ている例外が引き金で、残り1,846件がその後始末の連鎖、という形はよくあります。そして最終的には、その1件を前後ごと読む必要がある。件数を数える操作は、その1件をむしろ視界から消してしまう。

汎用ツールでの対処と限界

分布と内訳までは、パイプで出せます。

grep ERROR app.log | cut -c1-16 | uniq -c    # 分単位のヒストグラム
grep ERROR app.log | sed 's/[0-9]\+/N/g' | sort | uniq -c | sort -rn | head  # 種別の内訳

急増した分と種別ごとの多寡が一度に見えるので、ここまではかなり有効です。

限界は、ここから先に進めないことです。ヒストグラムが 10:23 の急増を示したとして、次にやりたいのは「10:23台の最初の1件を、前後100行つきで読む」こと。ところが手元にあるのは集計結果で、原本の該当位置ではありません。もう一度 grep -n で行番号を出し、sed -n で切り出し、足りなければやり直す——2章と同じ往復に戻ってきます。

4つに共通していたもの

遡り方は違っても、止まる場所は同じでした。

4つとも、「一覧」から「現場」へ戻る往復で詰まっています。

grep も awk も sort も、テキストを別のテキストに変換する道具です。変換した先には、元のファイルのどこから来たかという情報が（行番号を付けても、位置としては）残りません。因果を遡る作業は、まさにその「元のどこ」を何度も行き来する作業なので、変換の道具とは目的がずれています。

裏を返せば、この工程に必要なのは原本を原本のまま開いたまま、一覧と現場を往復できることです。検索結果から該当行へ飛べて、そこから上下に好きなだけスクロールでき、また一覧に戻れる。切り出しの幅を事前に決めなくてよく、足りなければその場でスクロールを続ければいい。

問題は、その往復を数GB〜数十GBのログで成立させるには、ファイル全体を読み終える前から見られることが前提になる点です。開くのに数分待つ道具では往復1回のコストが高すぎて、遡る前に心が折れる。前回扱ったツールの限界は、そのまま因果を遡る工程にも効いてきます。

使っている道具

私が開発している UwView（無料）は、この往復のために作ったビューアです。巨大なログでも開いた瞬間から全体を表示・スクロール・検索でき、索引はバックグラウンドで作られて、完成すると行番号が付きます（他のビューアの多くは索引が終わるまで先頭しか見えません）。検索結果は独立したポップアップに一覧され、行をダブルクリックすると本文が該当位置へ飛び、そこから上下に好きなだけ遡れます。切り出さないので、原本は1本のまま・無改変のまま扱えます。そして、ストレージを専有している巨大ログを圧縮して保管し、さらに高速に検索したいなら UwView Pro をどうぞ。永続索引・圧縮キャッシュ検索・約1/9保管で、開き直しも検索も一段速くなります（2回目以降は行番号付きで瞬時に開けます。全OS対応・買い切り／月額プランあり）。

リンク

• 前回: 巨大ファイルに沈む4つの定番ツールと、その先: https://uvp.y42u.net/blog/uwview-ps01-huge-file-tool-limits/
• ERRORの前後を遡る基本の手順: https://uvp.y42u.net/blog/uwview-error-context-cause/
• 検索一覧と現場を行き来する仕組み: https://uvp.y42u.net/blog/uwview-filter-popup-jump-save-context/
• ソースコード（GitHub）: https://github.com/amru195704/UwView

開発者より: アプリ・Kindle本・オープンソースの一覧は GitHub: amru195704 にまとめています。

お願い
本記事の情報は参考目的で掲載しており、正確性・完全性を保証するものではありません。ログの出力順序・バッファリングの挙動はロガーの実装や設定により異なります。コマンド例は環境（GNU/BSD の差異等）により調整が必要な場合があります。誤記・不正確な情報がございましたら、コメント欄よりご指摘いただければ、確認のうえ修正いたします。