The Logs Came From the Future — Five Incidents a Clock Made

The clock casebook — reading nine records

Goal

You read a bundle of records left with off clocks, measure in numbers what is off, and write functions that handle time correctly yourself. This is a 60-minute investigation for intermediate learners who can read JSON and CSV with Python.

Why it matters

In this incident the service was healthy throughout. What broke was not a process but the paper on which the times were written. Yet people read that paper to decide the cause, so off records turn a healthy system into the culprit and hide the real cause. What you learn here is not how to set a clock — setting clocks is usually done by someone else, and this lab Pod has no permission to do it anyway. What you learn is how to read off records and how to write code that does not collapse even when records are off.

Incident background

On the evening of November 1, 2025, the responses of one payment API instance (api-2) began to be stamped as 4 minutes 37 seconds. At the same time, the log of the worker (worker-1) contained a record of processing a request it never received. That night, when a new certificate was deployed, the handshake failed for a few seconds on just one machine and then healed itself, and the next day, notifications to US customers went out twice, four of them each time. And a few days later, the settlement aggregate was counted double for just one day. They are five branches that all come from the same cause.

Materials

They are under /opt/fixtures/clocklab/. Read them only and do not modify them.

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       유효 구간이 못박힌 인증서

Incident code table (names to use in the last step)

For each incident there is a pair: "what was wrongly believed" and "so what will be changed."

unsynced-clock / monitor-offset — Believed the machine's clock was right. Measure the error and monitor it.
merge-by-timestamp / order-by-causal-chain — Believed time order is causal order. Keep the causal chain as well.
stored-local-time / store-utc-display-local — Believed local time points to an instant. Store in UTC.
wall-clock-elapsed / use-monotonic-clock — Believed subtracting wall-clock times gives elapsed time. Measure elapsed time with the monotonic clock.
clock-outside-validity / renew-with-margin — Judged someone else's deadline with my own clock. Renew early with margin.
local-time-period-label / idempotent-run-key — Believed a local-time label uniquely identifies a period. Use an idempotent run key.

Steps

Read the four logs in /opt/fixtures/clocklab/logs/ (api-1 · api-2 · cache-1 · worker-1) and write an overview in /root/clock-lab/survey.json. For each host, put host, the line count lines, the number of distinct requests requests, and the timestamps of the file's first and last lines first_ts and last_ts in the hosts list, and write the sum of the four files' line counts in total_lines. Copy the timestamps exactly as the strings written in the file.
One request leaves four lines — api-1's send, the peer's recv, the peer's reply, and api-1's ack. Find the requests in which either of the two pairs (a recv earlier than the send, an ack earlier than the reply) is out of order and write them in /root/clock-lab/inversions.json. Include the number of inverted requests inverted_requests, the number of inverted pairs per peer host by_peer (write 0 for a peer with no inverted pairs), and the most strongly inverted request worst_request and its size worst_gap_ms (milliseconds, cause time minus effect time).
Only api-1 is the reference whose time synchronization is confirmed. For each peer host, compute theta = 1/2 * [(T2-T1) + (T3-T4)] from the four round-trip timestamps, take the median of it, round it to one decimal place in seconds, and write it in /root/clock-lab/skew.json. For each host, put host, the number of samples used samples, offset_sec, and the spread of the samples spread_ms (maximum minus minimum, in milliseconds) in hosts, and write the reference host in reference and rfc5905-theta in method.
Write realign(records, offsets) in /root/clock-lab/clocklab.py. records is a list of dictionaries with host and ts_ms (epoch milliseconds by that host's clock), and offsets is 호스트 → 오차 밀리초 (host → error in milliseconds). Add true_ms = ts_ms - 오차 (using that host's error from the offsets) to a copy of each record and return a new list sorted in ascending order of true_ms. Do not touch the input, treat a host missing from the error list as 0, and keep the incoming order when the corrected times are equal. Use that function to correct the 480 lines of the four logs and write records, the number of pairs still inverted after correction inverted_after, first_true_ms, and last_true_ms in /root/clock-lab/aligned.json.
/opt/fixtures/clocklab/alerts-local.csv is a record of notification sends kept only in US Eastern (America/New_York) local time. This rule sends 96 times a day, at 15-minute intervals starting at 00:00. Build the grid for the days that appear in the file, make the judgment, and write it in /root/clock-lab/dst.json. Include zone, the line count rows, the nonexistent local times nonexistent_locals, the local times that occur twice ambiguous_locals (both are lists of YYYY-MM-DD HH:MM:SS strings), the resulting number of missing sends missing_rows, the number of overlapping sends duplicate_rows, and the offsets before and after the transition where daylight saving time ends fallback_offset_before and fallback_offset_after (in the form -04:00).
/opt/fixtures/clocklab/timers.jsonl records the start and end of jobs that ran on one host, with both the wall clock and the monotonic clock. Add elapsed_ms(record) to /root/clock-lab/clocklab.py — it returns elapsed milliseconds from the monotonic clock values, and returns None if start_mono_ms or end_mono_ms is missing. And in /root/clock-lab/monotonic.json, write host, total_ops, the names of jobs whose wall-clock elapsed time is negative negative_ops and their count negative_count, the size of the wall-clock jump step_seconds (seconds, negative if it went backward), and the largest absolute difference between wall-clock and monotonic-clock elapsed time max_error_ms.
Read the validity period of /opt/fixtures/clocklab/certs/edge-1.pem and, together with the error measured in step 3, write it in /root/clock-lab/deadline.json. Include cert_not_before and cert_not_after (YYYY-MM-DDTHH:MM:SSZ), the host that briefly rejected the new certificate not_yet_valid_host and its duration not_yet_valid_sec, the number of handshakes actually rejected in /opt/fixtures/clocklab/tls-handshakes.jsonl handshake_rejects, the host that will see expiry earlier than others expires_early_host and its size expires_early_sec, the token lifetime read from /opt/fixtures/clocklab/tokens.jsonl token_ttl_sec, the time actually usable on the ahead clock token_usable_sec, and the numbers of tokens that will be rejected on the verifying side and on the issuing side tokens_rejected_on_verifier and tokens_rejected_on_issuer.
/opt/fixtures/clocklab/cron-runs.csv is the run history of a settlement job that runs at 5 minutes past every hour. period is the label of the period that run handled. Build all the hourly periods for the days that appear in the history, cross-check, and write it in /root/clock-lab/recurring.json. Include expected_periods, actual_runs, missing_periods that were never processed, duplicate_periods that were processed twice, overlapping_runs that started before the previous run finished (a list of run_id) and the largest overlap in seconds among them max_overlap_sec, and the number of rows the second run rewrote in the duplicated period double_counted_rows. And add run_key(record) to /root/clock-lab/clocklab.py — a rerun of the same period must yield the same value, and different work must yield a different value.
Leaving the outputs of the previous eight steps as they are, connect the six incidents (skew · causality · dst · monotonic · deadline · recurring) with cause, prevention, and evidence in /root/clock-lab/report.json. The cause and prevention codes are in the notes below, and evidence is the file name of the output holding the evidence for that incident. The final grading does not look only at the report — it also checks that the earlier steps' records still match the materials, and that the three functions in /root/clock-lab/clocklab.py are still intact.

Notes

Create all outputs under /root/clock-lab/. They disappear when the session ends, so keep a separate copy if you need one.
This lab is set at 60 minutes, the same as the default session length. Extend the time in advance when you start.
The Python standard library is enough. You use json, csv, datetime, zoneinfo, and subprocess.
Timestamps in the logs are in the form 2025-11-01T18:30:00.694+09:00, so datetime.fromisoformat reads them as is.
The grader recomputes the numbers you wrote from the materials and compares them. If you make up plausible-looking numbers, you will be caught.
The grader calls the functions in clocklab.py directly. It gives inputs that are not in the materials, so you cannot just match the results.
Skimming first with jq gives you a feel quickly. For example: jq -r .event logs/api-2.log | sort | uniq -c.
Two common mistakes — writing the sign of the error the wrong way around, and trying to find a nonexistent time in the file (it is not in the file).

Lay out the logs of four machines

Read the four logs in /opt/fixtures/clocklab/logs/ (api-1 · api-2 · cache-1 · worker-1) and write an overview in /root/clock-lab/survey.json. For each host, put host, the line count lines, the number of distinct requests requests, and the timestamps of the file's first and last lines first_ts and last_ts in the hosts list, and write the sum of the four files' line counts in total_lines. Copy the timestamps exactly as the strings written in the file.

Each log is JSON Lines. One line is one event, and req is the request ID. The file is sorted in that host's clock order, so you can use the first and last lines as they are. Put the time ranges of the four files side by side and first look with your own eyes at what is odd.

Find the effect that happened before its cause

One request leaves four lines — api-1's send, the peer's recv, the peer's reply, and api-1's ack. Find the requests in which either of the two pairs (a recv earlier than the send, an ack earlier than the reply) is out of order and write them in /root/clock-lab/inversions.json. Include the number of inverted requests inverted_requests, the number of inverted pairs per peer host by_peer (write 0 for a peer with no inverted pairs), and the most strongly inverted request worst_request and its size worst_gap_ms (milliseconds, cause time minus effect time).

Group the four lines by request ID and look at them. The peer host is in the peer of the line api-1 left. Which pair shows the inversion differs from peer to peer, and that difference is the clue for the next step. One peer has no problem at all.

Re-measure the size of the skew with four timestamps

Only api-1 is the reference whose time synchronization is confirmed. For each peer host, compute theta = 1/2 * [(T2-T1) + (T3-T4)] from the four round-trip timestamps, take the median of it, round it to one decimal place in seconds, and write it in /root/clock-lab/skew.json. For each host, put host, the number of samples used samples, offset_sec, and the spread of the samples spread_ms (maximum minus minimum, in milliseconds) in hosts, and write the reference host in reference and rfc5905-theta in method.

T1 is api-1's send, T2 is the peer's recv, T3 is the peer's reply, and T4 is api-1's ack. Check in the reading why the two terms are added and halved. Why you must not decide from a single sample shows up directly in spread_ms. A positive value means that host is ahead.

Correct it and line it up again, and the order comes back

Write realign(records, offsets) in /root/clock-lab/clocklab.py. records is a list of dictionaries with host and ts_ms (epoch milliseconds by that host's clock), and offsets is 호스트 → 오차 밀리초 (host → error in milliseconds). Add true_ms = ts_ms - 오차 (using that host's error from the offsets) to a copy of each record and return a new list sorted in ascending order of true_ms. Do not touch the input, treat a host missing from the error list as 0, and keep the incoming order when the corrected times are equal. Use that function to correct the 480 lines of the four logs and write records, the number of pairs still inverted after correction inverted_after, first_true_ms, and last_true_ms in /root/clock-lab/aligned.json.

The grader calls this function directly with inputs that are not from the materials. Just matching the results will not pass. For the error, convert the value you wrote in step 3 to milliseconds and use it. Be careful: sorting in place changes the input.

The day 1 a.m. came twice

/opt/fixtures/clocklab/alerts-local.csv is a record of notification sends kept only in US Eastern (America/New_York) local time. This rule sends 96 times a day, at 15-minute intervals starting at 00:00. Build the grid for the days that appear in the file, make the judgment, and write it in /root/clock-lab/dst.json. Include zone, the line count rows, the nonexistent local times nonexistent_locals, the local times that occur twice ambiguous_locals (both are lists of YYYY-MM-DD HH:MM:SS strings), the resulting number of missing sends missing_rows, the number of overlapping sends duplicate_rows, and the offsets before and after the transition where daylight saving time ends fallback_offset_before and fallback_offset_after (in the form -04:00).

Judge with zoneinfo and fold. The fact that the two candidates' offsets differ does not separate a nonexistent time from a time that occurs twice — try a round trip. The lines for nonexistent times are not in the file at all, so you cannot find them just by skimming the file; you have to build the grid yourself.

Jobs whose elapsed time was stamped negative

/opt/fixtures/clocklab/timers.jsonl records the start and end of jobs that ran on one host, with both the wall clock and the monotonic clock. Add elapsed_ms(record) to /root/clock-lab/clocklab.py — it returns elapsed milliseconds from the monotonic clock values, and returns None if start_mono_ms or end_mono_ms is missing. And in /root/clock-lab/monotonic.json, write host, total_ops, the names of jobs whose wall-clock elapsed time is negative negative_ops and their count negative_count, the size of the wall-clock jump step_seconds (seconds, negative if it went backward), and the largest absolute difference between wall-clock and monotonic-clock elapsed time max_error_ms.

Do not memorize the jump size; work it out from the materials — the jobs where the wall-clock elapsed time minus the monotonic-clock elapsed time is not 0 hold the answer. The grader also calls elapsed_ms with records where the wall clock went backward and records without monotonic clock values.

The 12 seconds a perfectly good certificate was rejected

Read the validity period of /opt/fixtures/clocklab/certs/edge-1.pem and, together with the error measured in step 3, write it in /root/clock-lab/deadline.json. Include cert_not_before and cert_not_after (YYYY-MM-DDTHH:MM:SSZ), the host that briefly rejected the new certificate not_yet_valid_host and its duration not_yet_valid_sec, the number of handshakes actually rejected in /opt/fixtures/clocklab/tls-handshakes.jsonl handshake_rejects, the host that will see expiry earlier than others expires_early_host and its size expires_early_sec, the token lifetime read from /opt/fixtures/clocklab/tokens.jsonl token_ttl_sec, the time actually usable on the ahead clock token_usable_sec, and the numbers of tokens that will be rejected on the verifying side and on the issuing side tokens_rejected_on_verifier and tokens_rejected_on_issuer.

Read the validity period with openssl x509 -noout -startdate -enddate. A clock that is behind gets caught at the front end of the period, and a clock that is ahead at the back end. For a token, the verifying side uses its own clock to see whether now is earlier than exp — if that clock is ahead, the amount of the error is lost from the lifetime.

The count is right, but one run was skipped and one ran twice

/opt/fixtures/clocklab/cron-runs.csv is the run history of a settlement job that runs at 5 minutes past every hour. period is the label of the period that run handled. Build all the hourly periods for the days that appear in the history, cross-check, and write it in /root/clock-lab/recurring.json. Include expected_periods, actual_runs, missing_periods that were never processed, duplicate_periods that were processed twice, overlapping_runs that started before the previous run finished (a list of run_id) and the largest overlap in seconds among them max_overlap_sec, and the number of rows the second run rewrote in the duplicated period double_counted_rows. And add run_key(record) to /root/clock-lab/clocklab.py — a rerun of the same period must yield the same value, and different work must yield a different value.

First compare the total number of runs with the number of expected periods. That the two numbers are equal does not mean it is normal. If you put run_id or started_utc in the key, both of the two runs are seen as new work — the grader applies it to the whole history and counts how many keys overlap.

Close the six incidents with cause and prevention

Leaving the outputs of the previous eight steps as they are, connect the six incidents (skew · causality · dst · monotonic · deadline · recurring) with cause, prevention, and evidence in /root/clock-lab/report.json. The cause and prevention codes are in the notes below, and evidence is the file name of the output holding the evidence for that incident. The final grading does not look only at the report — it also checks that the earlier steps' records still match the materials, and that the three functions in /root/clock-lab/clocklab.py are still intact.

The criterion for telling the six incidents apart without mixing them up is "what was wrongly believed." An off clock itself, deciding the order by those times, and storing in local time are different mistakes. A newly written report alone will not pass, so do not delete the earlier outputs.