ログが未来から来た

一言でいうと

タイムスタンプは事実ではなく、そのマシンがそのとき自分の時計を見て行った主張です。主張を複数集めて時間順に並べると、出来事の順序が黙ってひっくり返ります。

なぜ必要なのか

障害の振り返りで最もよく使う道具は、ログを時間順にマージすることです。サーバー4台のログを1つの画面に集め、上から読みながら「ここから始まったな」を探します。この方法は、ほとんどの日にはうまくいきます。そのため、うまくいかない日に気づくのが、特に難しいのです。

うまくいかない日は、このような姿をしています。ワーカーの「リクエストを受け取った」が、APIの「リクエストを送った」より上にあります。受け取っていないものを処理したことになります。この画面を見て人が下す結論は、ほぼ決まっています。「ワーカーが重複リクエストを再生したようだ」「メッセージキューが順序を壊した」「誰かがリトライを誤って設定した」。3つの仮説はどれももっともらしく、3つとも間違いです。ワーカーの時計が12秒遅れていただけです。

逆の方向は、もっと厄介です。時計が進んでいるマシンの行は、未来から飛んできたように見えます。ラウンドトリップの応答時間が4分37秒と記録され、ダッシュボードのレイテンシグラフがその時刻に跳ね上がります。遅くなったことはないのに、遅くなった証拠が残ります。そして、その証拠は消えません。

どう動くのか

ここで重要なのは、ずれが1行にだけ生じるのではないという点です。時計がずれたマシンは、そのマシンのすべての行が、同じ大きさでずれます。そのため、1行だけがおかしいなら、それは時計の問題ではなく別の問題であり、1つのホストの行がまるごと一定に押されているなら、それはほぼ時計です。この区別が、調査の最初の分かれ道です。

ずれの大きさは、推測せずに測ります。測れる理由は、1つのリクエストが4つの時刻を残すからです。送る側が送った時刻(T1)、受け取る側が受け取った時刻(T2)、受け取る側が応答した時刻(T3)、送る側が応答を受け取った時刻(T4)。NTPが30年間使っている計算がまさにこれで、RFC 5905の8節に、次のように書かれています。

theta = T(B) - T(A) = 1/2 * [(T2-T1) + (T3-T4)]      두 시계의 차이
delta = T(ABA)      = (T4-T1) - (T3-T2)              왕복에 걸린 시간

なぜ2つの項を足して半分にするのかが、この式のすべてです。(T2-T1)の中には2つのものが混ざっています。本当の時計の差と、行きの側のネットワーク遅延です。(T3-T4)の中にも時計の差が入っていますが、今度は帰りの側の遅延が反対の符号で入っています。2つを足すと、遅延が互いに相殺されて、時計の差だけが2倍で残ります。そのため、半分にします。

相殺は、行きと帰りの遅延が同じときだけ完璧です。実際のネットワークでは同じではないので、1回測って出た値は、(行きの遅延 - 帰りの遅延)の半分だけ間違います。そのため、1つのサンプルではなく、複数のサンプルの中央値を使います。サンプルの散らばる幅も一緒に見れば、この推定をどれだけ信じてよいかが、一緒に出ます。幅が数十ミリ秒なのにずれが277秒なら、結論が揺らぐ余地はありません。

実務で時計を合わせるのは、chronyのようなデーモンの仕事です。デーモンは、ずれが小さければ、時計の速度を微調整して徐々に追いつき(slew)、ずれが大きければ、時刻を一度に飛ばします(step)。2つの方式の違いが、次の話につながります。

現場での姿

コンテナ環境で、この問題に特によく出会います。コンテナは自分の時計を持たず、ホストカーネルの時計をそのまま見ます。そのため、ノード1台のNTPが死ぬと、そのノードで動くPodがすべて一緒にずれ、別のノードのPodは無事です。症状は「特定のサービスがおかしい」ではなく「特定のノードで動いているものだけがおかしい」として現れますが、サービス名でログを集めて見る習慣のせいで、そのパターンが見えにくくなります。

記録を残すときに守ることが、2つあります。1つは、時刻を常にオフセットと一緒に書くことです。RFC 3339の形式が役に立つ理由です。2025-11-01T18:30:00.694+09:00は、どのマシンで読んでも同じ瞬間を指しますが、2025-11-01 18:30:00は、読む人の推測に頼ります。もう1つは、順序を時刻だけに任せないことです。リクエストIDと因果の連鎖(何が何を生んだか)を一緒に残せば、時計がずれても、順序は復元されます。分散トレーシングがしていることが、まさにこれです。

そして、調査するときの順序があります。時計がずれていることがわかったら、ログを消したり、記録し直したりせず、ずれを記録しておいて、読むときに補正します。原本は、そのマシンがそのとき何を信じていたかの証拠であり、その信念が事故の原因かもしれません。

次のクイズで確認すること

1行の異常とホスト全体のずれをどう区別するか、4つの時刻でずれを測る式がなぜ遅延を相殺するのか、サンプル1つではなく複数の中央値を使う理由は何かを確認します。