TT Lab
はじめる
学ぶ 学習パス コース

ログから原因を見つける

オフセットのない時刻は時刻ではない

TT Labで続きを見る

一言でいうと

ログに書かれた時刻は主張であって、事実ではありません。オフセットがなければ、どの地域の時計なのかわからず、オフセットが正確でも、そのホストの時計自体が数秒ずれていれば、原因が結果より後ろに並びます。

なぜ必要なのか

形式をどれだけうまく正規化しても、時刻が偽りなら、その上に積み上げた結論はすべて偽りです。障害調査で最初にすることは「何が先に起きたか」であり、その順序を決める根拠が、まさにこれらの数字です。

現場で受け取る束には、3つのものが一緒に入っています。1つ目、オフセットがまったくないローカル時刻。アプリケーションのロガーのデフォルトが2026-03-08 15:04:57.200である場合が、今でもよくあります。RFC 3339は4.4節で、これを明記しています。オフセットのないローカル時刻は、解釈が地球のおよそ23/24で失敗するので、インターネットでは相互運用性の問題として受け入れられないと書いています。その行がソウルで記録されたのか、フランクフルトで記録されたのかは、行の中にありません。

2つ目、意味が微妙に違うオフセット。同じ文書の4.3節は、-00:00を別に規定しています。UTC時刻はわかるが、その記録を残した場所のローカルオフセットがわからないときに使う表記で、Zや+00:00とは意味が違います。後の2つは、UTCがその時刻の基準点だという意味です。数字としてはどちらも0なので計算結果は同じですが、読む人に与える情報が違います。

3つ目、時計自体の誤差。NTPに接続されていないホストは、1日に数秒ずつずれます。オフセットを正確に付けていても、時計が7秒進んでいれば、そのホストが記録したすべての時刻が7秒進みます。応答が1秒で終わるリクエストなら、原因が結果より6秒後に記録されます。ログだけを見ると、データベースがリクエストを受け取る前に答えたように見えます。

どう動くのか

信頼できない時刻を信頼できるようにする方法は、基準を1つ決めて、それに合わせて測ることです。

基準イベントを探す。複数のホストに同時に痕跡を残すものなら、何でも構いません。デプロイのマーカー、設定の再読み込み、運用スケジューラーが配信するプローブ信号。同じマーカーが3つのファイルすべてにあれば、その3行の時刻の差が、そのまま3つの時計の差です。この方法の精度は、その信号が3つのホストに到達する時間のばらつきを超えられません。その事実も一緒に書いておかなければ、推定値が誇張されます。

差を2つの取り分に分ける。基準との差の中には、ローカルのオフセットと時計のずれが混ざっています。IANAのタイムゾーンオフセットは15分の倍数なので、差を最も近い15分に丸めればタイムゾーンオフセットが出て、余った秒が時計のずれです。8時間59分57秒は、「9時間のオフセット + 3秒遅れた時計」と読みます。この3秒を四捨五入して捨ててはいけません。因果の順序をひっくり返すのが、まさにその3秒だからです。

地域名はオフセットではありません。地域は、IANAタイムゾーンデータベースが管理するルールの束であり、同じ地域のオフセットも季節ごとに変わります。Pythonはzoneinfoで、このルールをそのまま読みます。夏時間がある地域では、オフセットのないローカル時刻は2度危険になります。春には存在しない時刻が生まれ(America/New_Yorkの2026-03-08 02:30)、秋には2度来る時刻が生まれます。datetimeのfoldが、後ろのほうを指すノブです。

最後に1つの表記に固定する。RFC 3339の5.1節が書いている性質のとおり、オフセット表記と小数の桁数が同じなら、文字列のソートがそのまま時間順のソートになります。syslogを扱うなら、RFC 5424の6.2.3節がさらに絞り込んでいます。TとZは必ず大文字でなければならず、うるう秒は使えず、秒の小数は6桁を超えられません。

現場での姿

元の時計と観測側の時計を、両方残します。OpenTelemetryのログデータモデルが、TimestampとObservedTimestampを分けている理由が、まさにこれです。前者は、出来事が起きた元の時計の時刻で、ないこともあります。後者は、収集器がその出来事を見た時刻です。2つを一緒に持っていれば、元の時計が疑わしいときに、突き合わせる物差しができます。1つしか受け取らないシステムに渡すときは、Timestampがあればそれを、なければObservedTimestampを使うよう、仕様が勧めています。

補正値はデータではなく、仮定です。「このホストは+09:00で、3秒遅れている」は、あなたが基準イベントで推定した値です。元の行を上書きせず、補正した時刻と元の文字列を並べて残してください。あとで基準を変えたら、最初から計算し直せる必要があります。

本当の解決策は、顧客側にあります。推定は、今回の束を生かすための応急処置です。次の束からは、すべてのホストにNTPを接続し、ロガーがオフセットを必ず付けるようにし、できればUTCで記録してもらうよう求めることが、本当の解決策です。その要求をする根拠が、まさにあなたが測った数字です。

次のラボですること

3つのホストのログを再現して表記を調べ、夏時間がある地域のローカル時刻が、どのように消え、どのように2度来るのかを、自分で試します。そのあと、3つのファイルに一緒に記録されたプローブ信号で、ホストごとのタイムゾーンオフセットと時計のずれを分けて推定し、すべての行を補正して、1つのタイムラインに並べます。最後に、補正前に原因が結果より後ろに記録されていたリクエストが何件だったかを数え、何をどのような根拠で直したかを、報告書として残します。