警告はエラーより先に来る

一言でいうと

エラーが出た時刻は、出来事の始まりではなく、すでに進んでいた劣化がしきい値を超えた時刻であり、本当の始まりは、その前の警告区間にあります。

なぜ必要なのか

障害を調査するとき、大半の人はエラーログから見ます。自然ですが、エラーは物語の途中からです。

典型的な劣化は、次のように進みます。何かの変更があり → 一部のリクエストが遅くなり始め(警告) → 遅いリクエストが増えてリソースを握り → タイムアウトが出て(エラー) → しきい値を超えてアラートが鳴ります。エラーログだけを見ると、最後の2つの段階しか見えません。

そのため、調査で投げるべき質問は「いつエラーが始まったか」ではなく、「いつ正常でなくなったか」です。警告レベルのログの初出時刻が、その答えであることが多いです。

どう動くのか

複数のログを重ねて因果を作る手順は、次のとおりです。

1. 各ログが何を知っているかを決める。アクセスログは、ユーザーが何を経験したかを知っています。アプリケーションログは、なぜ失敗したかを知っています。スロークエリログは、どこで時間がかかったかを知っています。デプロイ履歴は、何が変わったかを知っています。1つのログがすべての質問に答えるわけではありません。

2. 時間軸をそろえる。これが、実務で最もよく足を引っ張ります。あるサービスはUTCで、別のサービスはオフセットのないローカル時間で記録していると、同じ出来事が9時間の差で見え、並べ替える方法がありません。そのため、構造化ログでは、タイムスタンプにオフセットを入れるのがルールです。すでに作られたログを扱うときは、各ファイルの時刻の表記方式を最初に確認してから始めます。

3. レベルごとに初出の時刻を抜き出す。warnの最初の時刻と、errorの最初の時刻。この2つの間隔が、そのまま「見逃した時間」です。

4. 原因の候補と時刻を突き合わせる。デプロイ履歴、設定変更、トラフィックの変化。時刻が重なれば強い手がかりで、重ならなければ、その候補は消えます。

5. 方向を確認する。相関は因果ではありません。AがBより先に起きたということは、必要条件であって、十分条件ではありません。デプロイが03:19でエラーが03:27なら、順序は合いますが、そのデプロイが本当に原因かどうかは、ロールバック後に症状が消えるかで確認する必要があります。

現場での姿

ここで、構造化ログの価値が表に出ます。ログの1行にservice.versionが入っていれば、「デプロイのせいか」という質問に、ログだけで答えられます。なければ、別にデプロイ履歴を入手して時刻を合わせる必要があり、その履歴がどこにあるかを知っている人を探すのに、30分かかります。

同じ理由で、request_idが重要です。それがなければ、1つのリクエストがどのサービスでどのように処理されたかを、時刻で推測してペアにしなければならず、毎秒数十件が入ってくるシステムで、その推測はほとんど常に外れます。

最後に、実務の感覚を1つ。エラーメッセージの中に答えが入っていることが、驚くほど多いです。db query timeout: table=paymentsという1行があれば、すでに層(データ)、症状(タイムアウト)、対象(paymentsテーブル)がすべて出ています。ログを数える前に、1行をきちんと読むことが先です。

ないものもシグナル

ログを重ねて見るとき、人々は記録されたものだけを見ます。ところが、調査で決定的な手がかりになるのは、あるべき場所にない項目であることが、よくあります。

定期ジョブがその日だけない。毎時間動くバッチのログが、事故の時刻の近くでだけ空いているなら、そのバッチが動けなかったか、非常に長くかかったという意味です。動いているものを数えるより、動いていないものを探すほうが難しいので、定期的なジョブは成功したときにも1行を残すようにする必要があります。失敗したときだけログを残す設計だと、「何も起きなかったこと」と「死んで何もできなかったこと」を区別できなくなります。

あるサービスのログだけが、その区間にない。ほかのサービスは記録され続けているのに、1つだけ静かなら、そのサービスが止まったか、ログの送信が途切れたのです。どちらなのかは、そのサービスの上流からリクエストが送られ続けていたかで分かれます。

リクエストはあるのに、応答の記録がない。アクセスログにリクエストが残っているのに、アプリケーションログにその処理結果がないなら、処理の途中でプロセスが消えたのです。このときは、その時刻の終了原因を見る必要があります。

そのため、時間軸を描くときは、各ログの件数を分単位で一緒に描くことが役に立ちます。エラー件数だけを描くと、上の3つはすべて見えませんが、全体の件数を一緒に描けば、「この区間でこのログだけがぷつりと途切れた」が一目で現れます。調査時間の大半が、どこを見るかを決めることに使われることを考えると、この1枚が与える価値は大きいです。

そして、この観察は、次回のための提案につながります。調査で「これがなくて確認できなかった」と書いた項目が、そのまま来四半期に追加すべきログの一覧です。報告書にその文を残さなければ、次の障害でも同じように行き詰まります。

この一覧は、たいてい短いものです。リクエスト識別子、デプロイバージョン、処理にかかった時間、そして失敗したときの対象名くらいです。4つをログの1行に入れておけば、次の調査で重ねて見るものが、ほとんどなくなります。

次のラボですること

JSON Linesのアプリケーションログ、スロークエリログ、デプロイ履歴をそれぞれ集計して、警告とエラーの時刻の間隔を測り、3つのログが指す1つの原因を、ドキュメントにまとめます。