タイムラインの再構成

一行まとめ

タイムラインは記憶ではなく証拠で組み立てます。異なるタイムゾーンとずれた時計を1つの基準時計にそろえて初めて「何が先だったか」を語れます。また、同じ症状が異なる原因から生じうることを知っていなければ、見当違いのものをロールバックしてしまいます。

なぜこれが必要だったか

インシデントが終わると、誰もが「デプロイ直後からエラーが出た」と記憶しています。しかしその「直後」は、サーバーの時計で記録されたログを人が目で突き合わせた結果です。あるサーバーの時計が3分遅れていれば、そのサーバーのエラーはデプロイより先に起きたように見えます。別のサーバーはKST、デプロイ記録はコミットした人のタイムゾーン(+0900と-0800が混在)、フラグ記録はさらに別のタイムゾーンです。この状態で順序を決めると、正常なデプロイを犯人にしてしまったり、本当の原因をウィンドウの外へ押し出してしまったりします。

そして「デプロイの頃からエラー」という同じ症状は、異なる原因から生じます。新バージョンのバグ、同じ頃に入った設定変更、依存先サービスの遅延 — 3つともグラフ上では同じように5xxが跳ね上がります。しかし正しい対応はそれぞれ、アプリのロールバック、設定のロールバック、何もロールバックしないこと、です。

どのように動くか

第一に、基準時計を1つ選びます。NTPで同期したロードバランサーやメトリクスシステムが通常の基準です。同じリクエストが基準とサーバーの両方に記録されていれば(リクエストid)、2つの時刻の差がそのサーバーの時刻のずれ(clock skew)です。1組ではなく複数組の中央値を使えば、処理遅延に左右されません。タイムゾーンはずれではありません — タイムゾーン表記を読んで同じ瞬間に変換するのが先です。

第二に、変更を1本の線に並べます。デプロイ・設定・フラグをすべてUTCの瞬間に変換して並べ替え、そろえた時計での最初のエラーの前の一定のウィンドウ (例: 30分)内の変更を疑わしい変更とします。

第三に、パターンで原因を切り分けます。ローリングデプロイのバグでは、新バージョンが入ったサーバーから順にエラーが始まります。設定は通常すべてのサーバーに一斉に入るため、エラーも同時に始まります。依存先サービスの問題では、そのサービスのレイテンシのメトリクスが先に跳ね上がり、エラーの形 (タイムアウトのコード、数秒かかったレスポンス)が異なります。

第四に、区間に名前を付けます。検知遅延(最初のエラー → アラート)、緩和時刻(エラー率が基準を下回り、そのまま維持された最初の時点)をデータ上の定義として決めておけば、人によって異なる数字が出ることはありません。

ずれを測る計算はこのようになります。同じリクエストが両側に記録されていれば、差を複数集めて中央値を使います。

req=r0700123  기준(LB) 05:21:40.112Z   web-2 가 찍은 시각 05:18:12.125Z   차이 -207.987
req=r0700131  기준(LB) 05:21:44.530Z   web-2 가 찍은 시각 05:18:16.541Z   차이 -207.989
…                                                         가운데 값 ≈ -208초 (web-2 가 208초 뒤처짐)
맞춘 시각 = 서버가 찍은 시각 − 어긋남  →  05:18:12 − (−208) = 05:21:40

そして、同じ症状の3つの原因は、シグナルも対応も異なります。

原因	エラーの始まり方	一緒に見えるシグナル	やること
新しいアプリバージョンの欠陥	新バージョンが入ったサーバーから順に	ローリング間隔の分だけサーバーごとの開始がずれる	アプリを直前のバージョンへ
設定デプロイ	すべてのサーバーが同じ秒に	設定デプロイの直後で、アプリデプロイより先	設定を直前のリビジョンへ
依存先サービスの遅延	すべてのサーバーが一斉に、タイムアウトのコード	依存先サービスのp99が先に跳ね上がる	ロールバックせず依存先側で対応

現場でよく見る光景

よくある場面は「3つともデプロイのせいだから全部ロールバックしよう」です。しかし依存先サービスが原因のエラーはロールバックしても変わらず、ロールバック自体がもう1つの変更なので新たなリスクを持ち込みます。もう1つのよくある場面は、時計がずれたサーバー1台が「デプロイ前からエラーがあった」という錯覚を生み、デプロイを無罪にしてしまうことです。どちらも時計をそろえてパターンを見れば、数分で切り分けられます。

gitの記録も落とし穴です。デフォルトの git log はコミットした人のタイムゾーンで日付を表示し、最新のものが上に来ます。アメリカで夜9時にしたコミットは Tue Nov 3 21:14 -0800 と表示されますが、UTCでは11月4日の早朝です。日付の文字列で並べ替えると、このデプロイが1日前のものとして押し出され、「インシデント直前30分以内の変更」リストから漏れます。変更記録を集めるときは、常に瞬間(UTC)に変換してから並べ替えます。

検知遅延はアラートルールが決めます。「1分あたりのエラー率5%超過が3分連続」というルールは、どれだけ早くても3分目が終わらないと鳴らず、エラーがゆっくり上がればそれより遅くなります。タイムラインから検知遅延を数字として取り出しておけば、ポストモーテムで「アラートが遅かった」という感覚が「ルールのせいで最低3分、実際は4分12秒」という事実に変わり、直すべき場所(ルールのしきい値や持続時間)が明確になります。

次のラボでやること

2つのサーバーログ(タイムゾーンと時計が異なる)、ロードバランサーのサンプル、gitのデプロイ記録、フラグ記録、アラート・メトリクスを突き合わせて時刻のずれを測り、基準時計での最初のエラーと疑わしい変更、検知遅延と緩和時刻を求めます。最後に、3つのサービスの同じ症状を原因ごとに切り分け、ロールバックすべきものだけをロールバックします。