時計事件ノート — 九つの記録を読む

目標

時計がずれたまま残った記録の束を読み、何がずれたのかを数字で測り、時刻を正しく扱う関数を自分で書きます。JSONとCSVをPythonで読める中級の学習者向けの、60分の調査です。

なぜ重要なのか

この事件で、サービスは最初から最後まで正常でした。壊れていたのは、プロセスではなく、時刻を書き留めた紙です。ところが、人はその紙を読んで原因を決めるので、ずれた記録は、正常なシステムを犯人に仕立て、本当の原因を隠します。ここで学ぶのは、時計を合わせる方法ではありません。時計を合わせる作業は、たいてい他人が行い、このラボのPodには、その権限もありません。学ぶのは、ずれた記録を読む方法と、ずれても崩れないコードを書く方法です。

事件の背景

2025年11月1日の夕方、決済API 1台(api-2)の応答が、4分37秒と記録され始めました。同じ時刻に、ワーカー(worker-1)のログには、受け取っていないリクエストを処理した記録が残りました。その夜、新しい証明書をデプロイしたところ、1台だけで数秒間handshakeが失敗して、自然に直り、翌日、アメリカの顧客へのアラートが、4件ずつ2回送信されました。そして数日後、精算の集計が、1日分だけ2倍に計上されました。すべて同じ原因から出た、5つの枝です。

用意するもの

/opt/fixtures/clocklab/の下にあります。読むだけで、直さないでください。

logs/api-1.log  logs/api-2.log  logs/worker-1.log  logs/cache-1.log
    네 대가 각자 자기 시계로 찍은 왕복 기록. 한 왕복에 네 줄(send·recv·reply·ack).
tls-handshakes.jsonl   새 인증서를 배포한 뒤 2초마다 시도한 handshake 결과
timers.jsonl           작업들의 시작·끝. 벽시계와 단조 시계를 함께 남겼다
tokens.jsonl           발급한 쪽과 검증한 쪽이 다른 토큰 60개
alerts-local.csv       지역 시각(America/New_York)으로만 남은 알림 발송 기록
cron-runs.csv          매시 5분에 도는 정산 작업의 실행 이력
certs/edge-1.pem       유효 구간이 못박힌 인증서

このコードブロックの韓国語の説明は、順に、4台がそれぞれ自分の時計で記録した往復の記録で1往復に4行(send・recv・reply・ack)、新しい証明書をデプロイしたあと2秒ごとに試行したhandshakeの結果、作業の開始・終了を壁時計と単調時計で一緒に残したもの、発行した側と検証した側が違うトークン60個、ローカル時刻(America/New_York)だけで残った通知の送信記録、毎時5分に動く精算ジョブの実行履歴、有効期間が明記された証明書、という意味です。

事件コード表(最後のステップで使う名前)

事件ごとに、「何を誤って信じていたか」と「では何を変えるか」を、ペアにして置きます。

unsynced-clock / monitor-offset: マシンの時計が合っていると信じていました。ずれを測って監視します。
merge-by-timestamp / order-by-causal-chain: 時刻順がそのまま因果順だと信じていました。因果の連鎖を一緒に残します。
stored-local-time / store-utc-display-local: ローカル時刻が瞬間を指すと信じていました。保存はUTCで行います。
wall-clock-elapsed / use-monotonic-clock: 壁時計の引き算が経過だと信じていました。経過は単調時計で測ります。
clock-outside-validity / renew-with-margin: 自分の時計で、他者の期限を判定しました。余裕を持って早めに更新します。
local-time-period-label / idempotent-run-key: ローカル時刻のラベルが期間を一意に指すと信じていました。冪等な実行キーを使います。

ステップ

/opt/fixtures/clocklab/logs/の4つのログ(api-1・api-2・cache-1・worker-1)を読み、/root/clock-lab/survey.jsonに概要を書いてください。ホストごとに、host・行数lines・異なるリクエスト数requests・ファイルの最初の行と最後の行の時刻first_tsとlast_tsを、hostsのリストに入れ、4つのファイルの行数の合計をtotal_linesに書きます。時刻は、ファイルに書かれた文字列のまま写してください。
1つのリクエストは4行を残します。api-1のsend、相手のrecv、相手のreply、api-1のackです。2つのペア(sendより早いrecv、replyより早いack)のうち、どちらか1つでもずれているリクエストを探して、/root/clock-lab/inversions.jsonに書いてください。逆転したリクエスト数inverted_requests、相手ホストごとの逆転したペアの数by_peer(逆転したペアがない相手も0と書きます)、最も大きく逆転したリクエストworst_requestとその幅worst_gap_ms(ミリ秒、原因の時刻から結果の時刻を引いた値)を入れます。
api-1だけが、時刻の同期が確認された基準です。相手ホストごとに、往復の4つの時刻でtheta = 1/2 * [(T2-T1) + (T3-T4)]を求め、その中央値を、秒単位で小数第1位まで四捨五入して、/root/clock-lab/skew.jsonに書いてください。ホストごとに、host・使ったサンプル数samples・offset_sec・サンプルが散らばった幅spread_ms(最大値から最小値を引いたもの、ミリ秒)をhostsに入れ、referenceに基準ホストを、methodにrfc5905-thetaを書きます。
/root/clock-lab/clocklab.pyにrealign(records, offsets)を書いてください。recordsはhostとts_ms(そのホストの時計基準のepochミリ秒)を持つ辞書のリストで、offsetsは호스트 → 오차 밀리초(韓国語は「ホスト → ずれ(ミリ秒)」という意味です)です。各レコードのコピーに、true_ms = ts_ms - 오차(プレースホルダーはずれです)を加えて、true_msの昇順に並べた新しいリストを返します。入力には手を触れず、ずれの一覧にないホストは0と見なし、補正時刻が同じなら、入ってきた順序を守ります。その関数で4つのログの480行を補正し、/root/clock-lab/aligned.jsonに、records・補正後も逆転しているペアの数inverted_after・first_true_ms・last_true_msを書いてください。
/opt/fixtures/clocklab/alerts-local.csvは、アメリカ東部(America/New_York)のローカル時刻だけで残った、通知の送信記録です。このルールは、1日96回、00:00から15分間隔で送られます。ファイルに登場する日のグリッドを作って判定し、/root/clock-lab/dst.jsonに書いてください。zone・行数rows・存在しないローカル時刻nonexistent_locals・2度来るローカル時刻ambiguous_locals(どちらもYYYY-MM-DD HH:MM:SSの文字列のリスト)・そのために欠けた送信数missing_rows・重複した送信数duplicate_rows・夏時間が終わる切り替えの前後のオフセットfallback_offset_beforeとfallback_offset_after(-04:00の形)。
/opt/fixtures/clocklab/timers.jsonlは、1つのホストで動いていた作業の開始・終了を、壁時計と単調時計の両方で残したものです。/root/clock-lab/clocklab.pyにelapsed_ms(record)を追加してください。単調時計の値で経過ミリ秒を返し、start_mono_msかend_mono_msがなければ、Noneを返します。そして、/root/clock-lab/monotonic.jsonに、host・total_ops・壁時計の経過がマイナスの作業名negative_opsとその数negative_count・壁時計がジャンプした幅step_seconds(秒、後ろへ行ったならマイナス)・壁時計と単調時計の経過の差のうち最も大きい絶対値max_error_msを書いてください。
/opt/fixtures/clocklab/certs/edge-1.pemの有効期間を読み、ステップ3で測ったずれとつなげて、/root/clock-lab/deadline.jsonに書いてください。cert_not_beforeとcert_not_after(YYYY-MM-DDTHH:MM:SSZ)・新しい証明書をしばらく拒否したホストnot_yet_valid_hostとその長さnot_yet_valid_sec・/opt/fixtures/clocklab/tls-handshakes.jsonlで実際に拒否された回数handshake_rejects・他より先に期限切れと見るホストexpires_early_hostとその幅expires_early_sec・/opt/fixtures/clocklab/tokens.jsonlから読んだトークンの寿命token_ttl_sec・進んだ時計で実際に使える時間token_usable_sec・検証する側と発行する側でそれぞれ拒否されるトークンの数tokens_rejected_on_verifierとtokens_rejected_on_issuer。
/opt/fixtures/clocklab/cron-runs.csvは、毎時5分に動く精算ジョブの実行履歴です。periodは、その実行が処理した期間のラベルです。履歴に出てくる日の毎時の期間をすべて作って突き合わせ、/root/clock-lab/recurring.jsonに書いてください。expected_periods・actual_runs・一度も処理されなかったmissing_periods・2度処理されたduplicate_periods・前の実行が終わる前に開始したoverlapping_runs(run_idのリスト)とそのうち最も大きく重なった秒max_overlap_sec・重複した期間で2回目の実行が書き直した行数double_counted_rows。そして、/root/clock-lab/clocklab.pyにrun_key(record)を追加してください。同じ期間の再実行なら同じ値、別の仕事なら別の値が出る必要があります。
前の8つのステップの成果物をそのままにして、/root/clock-lab/report.jsonに、6件の事件(skew・causality・dst・monotonic・deadline・recurring)を、cause・prevention・evidenceでつないでください。原因と予防のコードは下の参考にあり、evidenceは、その事件の根拠が入った成果物のファイル名です。最後の採点は、報告書だけを見ません。前のステップの記録が今も材料と合っているか、/root/clock-lab/clocklab.pyの3つの関数がそのまま生きているかも、一緒に確認します。

参考

成果物はすべて/root/clock-lab/の下に作ります。セッションが終わると消えるので、必要なら別に保管してください。
このラボは60分に設定されていて、基本セッションの長さと同じです。開始するときに、あらかじめ時間を延長しておいてください。
Pythonの標準ライブラリだけで十分です。json・csv・datetime・zoneinfo・subprocessを使います。
ログの時刻は2025-11-01T18:30:00.694+09:00の形なので、datetime.fromisoformatがそのまま読めます。
採点ツールは、あなたが書いた数字を材料から再計算して突き合わせます。もっともらしい数字をでっち上げると、見つかります。
採点ツールは、clocklab.pyの関数を直接呼び出します。材料ではない入力を与えるので、結果だけを合わせておくことはできません。
jqでまず一覧すると、感覚がすぐにつかめます。例: jq -r .event logs/api-2.log | sort | uniq -c。
よくあるミスは2つです。ずれの符号を逆に書くことと、存在しない時刻をファイルから探そうとすること(ファイルにはありません)。

4台のログを広げる

/opt/fixtures/clocklab/logs/の4つのログ(api-1・api-2・cache-1・worker-1)を読み、/root/clock-lab/survey.jsonに概要を書いてください。ホストごとに、host・行数lines・異なるリクエスト数requests・ファイルの最初の行と最後の行の時刻first_tsとlast_tsを、hostsのリストに入れ、4つのファイルの行数の合計をtotal_linesに書きます。時刻は、ファイルに書かれた文字列のまま写してください。

各ログはJSON Linesです。1行が1つの出来事で、reqがリクエストIDです。ファイルは、そのホストの時計の順序で並んでいるので、最初の行と最後の行をそのまま使えばよいです。4つのファイルの時刻範囲を並べて、何がおかしいかを、まず目で見てください。

原因より先に起きた結果を探す

1つのリクエストは4行を残します。api-1のsend、相手のrecv、相手のreply、api-1のackです。2つのペア(sendより早いrecv、replyより早いack)のうち、どちらか1つでもずれているリクエストを探して、/root/clock-lab/inversions.jsonに書いてください。逆転したリクエスト数inverted_requests、相手ホストごとの逆転したペアの数by_peer(逆転したペアがない相手も0と書きます)、最も大きく逆転したリクエストworst_requestとその幅worst_gap_ms(ミリ秒、原因の時刻から結果の時刻を引いた値)を入れます。

4行をリクエストIDでまとめて見てください。相手ホストは、api-1が残した行のpeerにあります。逆転がどのペアで現れるかが、相手ごとに違い、その違いが次のステップの手がかりです。相手の1つは、何の問題もありません。

ずれの大きさを4つの時刻で測り直す

api-1だけが、時刻の同期が確認された基準です。相手ホストごとに、往復の4つの時刻でtheta = 1/2 * [(T2-T1) + (T3-T4)]を求め、その中央値を、秒単位で小数第1位まで四捨五入して、/root/clock-lab/skew.jsonに書いてください。ホストごとに、host・使ったサンプル数samples・offset_sec・サンプルが散らばった幅spread_ms(最大値から最小値を引いたもの、ミリ秒)をhostsに入れ、referenceに基準ホストを、methodにrfc5905-thetaを書きます。

T1はapi-1のsend、T2は相手のrecv、T3は相手のreply、T4はapi-1のackです。なぜ2つの項を足して半分にするのかは、読み物の教材で確認してください。サンプル1つで決めてはいけない理由が、spread_msにそのまま表れます。正の値は、そのホストが進んでいるということです。

補正して並べ直すと順序が戻る

/root/clock-lab/clocklab.pyにrealign(records, offsets)を書いてください。recordsはhostとts_ms(そのホストの時計基準のepochミリ秒)を持つ辞書のリストで、offsetsは호스트 → 오차 밀리초(韓国語は「ホスト → ずれ(ミリ秒)」という意味です)です。各レコードのコピーに、true_ms = ts_ms - 오차(プレースホルダーはずれです)を加えて、true_msの昇順に並べた新しいリストを返します。入力には手を触れず、ずれの一覧にないホストは0と見なし、補正時刻が同じなら、入ってきた順序を守ります。その関数で4つのログの480行を補正し、/root/clock-lab/aligned.jsonに、records・補正後も逆転しているペアの数inverted_after・first_true_ms・last_true_msを書いてください。

採点ツールが、この関数を、材料ではない入力で直接呼び出します。結果だけを合わせても通りません。ずれは、ステップ3で書いた値を、ミリ秒に換えて使えばよいです。ソートをその場で行うと、入力が変わるので注意してください。

午前1時が2度来た日

/opt/fixtures/clocklab/alerts-local.csvは、アメリカ東部(America/New_York)のローカル時刻だけで残った、通知の送信記録です。このルールは、1日96回、00:00から15分間隔で送られます。ファイルに登場する日のグリッドを作って判定し、/root/clock-lab/dst.jsonに書いてください。zone・行数rows・存在しないローカル時刻nonexistent_locals・2度来るローカル時刻ambiguous_locals(どちらもYYYY-MM-DD HH:MM:SSの文字列のリスト)・そのために欠けた送信数missing_rows・重複した送信数duplicate_rows・夏時間が終わる切り替えの前後のオフセットfallback_offset_beforeとfallback_offset_after(-04:00の形)。

zoneinfoとfoldで判定します。2つの候補のオフセットが分かれるというだけでは、存在しない時刻と2度来る時刻を区別できません。往復させてみてください。存在しない時刻の行は、ファイルにそもそもないので、ファイルを走査するだけでは見つけられず、グリッドを自分で作る必要があります。

経過時間がマイナスで記録された作業

/opt/fixtures/clocklab/timers.jsonlは、1つのホストで動いていた作業の開始・終了を、壁時計と単調時計の両方で残したものです。/root/clock-lab/clocklab.pyにelapsed_ms(record)を追加してください。単調時計の値で経過ミリ秒を返し、start_mono_msかend_mono_msがなければ、Noneを返します。そして、/root/clock-lab/monotonic.jsonに、host・total_ops・壁時計の経過がマイナスの作業名negative_opsとその数negative_count・壁時計がジャンプした幅step_seconds(秒、後ろへ行ったならマイナス)・壁時計と単調時計の経過の差のうち最も大きい絶対値max_error_msを書いてください。

ジャンプの幅は、暗記せずに材料から求めてください。壁時計の経過から単調時計の経過を引いた値が0でない作業が、答えを持っています。採点ツールは、elapsed_msを、壁時計が後ろへ行ったレコードと、単調時計の値がないレコードでも呼んでみます。

正常な証明書が拒否された12秒

/opt/fixtures/clocklab/certs/edge-1.pemの有効期間を読み、ステップ3で測ったずれとつなげて、/root/clock-lab/deadline.jsonに書いてください。cert_not_beforeとcert_not_after(YYYY-MM-DDTHH:MM:SSZ)・新しい証明書をしばらく拒否したホストnot_yet_valid_hostとその長さnot_yet_valid_sec・/opt/fixtures/clocklab/tls-handshakes.jsonlで実際に拒否された回数handshake_rejects・他より先に期限切れと見るホストexpires_early_hostとその幅expires_early_sec・/opt/fixtures/clocklab/tokens.jsonlから読んだトークンの寿命token_ttl_sec・進んだ時計で実際に使える時間token_usable_sec・検証する側と発行する側でそれぞれ拒否されるトークンの数tokens_rejected_on_verifierとtokens_rejected_on_issuer。

openssl x509 -noout -startdate -enddateで有効期間を読みます。遅れた時計は期間の前側の端に、進んだ時計は後ろ側の端に引っかかります。トークンは、検証する側の時計で、今がexpより早いかを見ます。その時計が進んでいれば、寿命からずれの分が消えます。

個数は合っているのに、1回は抜けて1回は2度動いた

/opt/fixtures/clocklab/cron-runs.csvは、毎時5分に動く精算ジョブの実行履歴です。periodは、その実行が処理した期間のラベルです。履歴に出てくる日の毎時の期間をすべて作って突き合わせ、/root/clock-lab/recurring.jsonに書いてください。expected_periods・actual_runs・一度も処理されなかったmissing_periods・2度処理されたduplicate_periods・前の実行が終わる前に開始したoverlapping_runs(run_idのリスト)とそのうち最も大きく重なった秒max_overlap_sec・重複した期間で2回目の実行が書き直した行数double_counted_rows。そして、/root/clock-lab/clocklab.pyにrun_key(record)を追加してください。同じ期間の再実行なら同じ値、別の仕事なら別の値が出る必要があります。

総実行回数と、期待される期間の数を、まず比べてみてください。2つの数字が同じだからといって、正常ではありません。キーにrun_idやstarted_utcを入れると、2度動いたものを、2回とも新しい仕事と見ます。採点ツールが履歴全体に適用して、重なるキーがいくつあるかを数えます。

6つの事件を原因と予防で閉じる

前の8つのステップの成果物をそのままにして、/root/clock-lab/report.jsonに、6件の事件(skew・causality・dst・monotonic・deadline・recurring)を、cause・prevention・evidenceでつないでください。原因と予防のコードは下の参考にあり、evidenceは、その事件の根拠が入った成果物のファイル名です。最後の採点は、報告書だけを見ません。前のステップの記録が今も材料と合っているか、/root/clock-lab/clocklab.pyの3つの関数がそのまま生きているかも、一緒に確認します。

6つの事件を混同せずに分ける基準は、「何を誤って信じていたか」です。ずれた時計そのものと、その時刻で順序を決めたことと、ローカル時刻で保存したことは、それぞれ別の誤りです。報告書だけを新しく書いても通らないので、前の成果物を消さないでください。