时钟事件笔记 — 读九份记录

目标

阅读时钟错位的一批记录，用数字测量出究竟是什么错了，并亲手编写能正确处理时间的函数。这是一项 60 分钟的排查，面向能用 Python 读取 JSON 和 CSV 的中级学习者。

为什么重要

在这起事件中，服务自始至终都是正常的。出故障的不是进程，而是记录时间的那张纸。可人是读着这张纸来确定原因的，所以错位的记录会把正常的系统当成元凶，同时把真正的原因藏起来。这里要学的不是如何校准时钟——校准时钟通常由别人来做，这个实验的 Pod 也没有这个权限。要学的是如何阅读错位的记录，以及如何编写即使错位也不会崩溃的代码。

事件背景

2025 年 11 月 1 日晚上，一台支付 API（api-2）的响应开始被记录为 4 分 37 秒。同一时刻，worker（worker-1）的日志中留下了处理一个从未收到过的请求的记录。当晚部署新证书后，只有一台机器的 handshake 失败了几秒钟，随后自行恢复；第二天，美国客户的通知有四条被发送了两次。再过几天，结算汇总只有一天的数据被算成了两倍。这五条线索全都出自同一个原因。

材料

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

该代码块中的韩文说明依次为：四台主机各自按自己的时钟记录的往返日志，每个往返四行（send、recv、reply、ack）；部署新证书之后每 2 秒尝试一次的 handshake 结果；各任务的开始与结束，同时记录了挂钟时间和单调时钟；签发方与验证方不同的 60 个令牌；只以本地时间（America/New_York）留下的通知发送记录；每小时 05 分运行的结算任务的执行历史；有效区间已固定的证书。

事件代码表（最后一步要用的名称）

每个事件都配成一对：“当初错信了什么”和“因此要改变什么”。

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/ 中的四份日志（api-1、api-2、cache-1、worker-1），把概要写入 /root/clock-lab/survey.json。对每台主机，把 host、行数 lines、不同的请求数 requests、文件首行与末行的时间 first_ts 和 last_ts 放入 hosts 列表，并把四个文件的行数之和写入 total_lines。时间要原样照抄文件中写的字符串。
一个请求会留下四行——api-1 的 send、对端的 recv、对端的 reply、api-1 的 ack。找出两对（早于 send 的 recv、早于 reply 的 ack）中任何一对出现错位的请求，写入 /root/clock-lab/inversions.json。其中包括颠倒的请求数 inverted_requests、按对端主机统计的颠倒对数 by_peer（没有颠倒对的对端也写 0）、颠倒最严重的请求 worst_request 及其幅度 worst_gap_ms（毫秒，原因时间减去结果时间）。
只有 api-1 的时间同步已得到确认，以它为基准。对每台对端主机，用往返的四个时间点求出 theta = 1/2 * [(T2-T1) + (T3-T4)]，取其中位数，四舍五入到以秒为单位的小数点后第一位，写入 /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 处理；校正后的时间相同时保持输入顺序。用这个函数校正四份日志共 480 行，并在 /root/clock-lab/aligned.json 中写入 records、校正后仍然颠倒的对数 inverted_after、first_true_ms、last_true_ms。
/opt/fixtures/clocklab/alerts-local.csv 是只以美国东部（America/New_York）本地时间留下的通知发送记录。这条规则每天发送 96 次，从 00:00 起每隔 15 分钟一次。为文件中出现的各天生成网格进行判定，并写入 /root/clock-lab/dst.json。其中包括 zone、行数 rows、不存在的本地时间 nonexistent_locals、出现两次的本地时间 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 同时用挂钟时间和单调时钟记录了在同一台主机上运行的各任务的开始与结束。在 /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 是每小时 05 分运行的结算任务的执行历史。period 是该次执行所处理区间的标签。把历史记录中出现的各天每小时的区间全部生成出来进行比对，并写入 /root/clock-lab/recurring.json。其中包括 expected_periods、actual_runs、一次也没有被处理的 missing_periods、被处理了两次的 duplicate_periods、在前一次执行结束之前就已开始的 overlapping_runs（run_id 列表）及其中重叠最多的秒数 max_overlap_sec、在重复区间中第二次执行重写的行数 double_counted_rows。然后在 /root/clock-lab/clocklab.py 中加入 run_key(record)——同一区间的重新执行要得到相同的值，不同的事情要得到不同的值。
保持前八步的产出物原样不动，在 /root/clock-lab/report.json 中把六个事件（skew、causality、dst、monotonic、deadline、recurring）分别与 cause、prevention、evidence 连接起来。原因和预防的代码在下面的参考中，evidence 是装有该事件依据的产出物的文件名。最后的评分不只看报告——还会一并确认前面各步的记录是否仍与材料相符，以及 /root/clock-lab/clocklab.py 中的三个函数是否原样保留。

参考

产出物全部创建在 /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。
常见错误有两个——把误差的符号写反，以及想在文件里找不存在的时间（文件里没有）。

把四台服务器的日志摊开来看

阅读 /opt/fixtures/clocklab/logs/ 中的四份日志（api-1、api-2、cache-1、worker-1），把概要写入 /root/clock-lab/survey.json。对每台主机，把 host、行数 lines、不同的请求数 requests、文件首行与末行的时间 first_ts 和 last_ts 放入 hosts 列表，并把四个文件的行数之和写入 total_lines。时间要原样照抄文件中写的字符串。

每份日志都是 JSON Lines。一行就是一个事件，req 是请求 ID。文件按该主机自己的时钟顺序排序，所以直接使用首行和末行即可。把四个文件的时间范围并排放在一起，先用眼睛看看哪里不对劲。

找出比原因更早发生的结果

一个请求会留下四行——api-1 的 send、对端的 recv、对端的 reply、api-1 的 ack。找出两对（早于 send 的 recv、早于 reply 的 ack）中任何一对出现错位的请求，写入 /root/clock-lab/inversions.json。其中包括颠倒的请求数 inverted_requests、按对端主机统计的颠倒对数 by_peer（没有颠倒对的对端也写 0）、颠倒最严重的请求 worst_request 及其幅度 worst_gap_ms（毫秒，原因时间减去结果时间）。

按请求 ID 把四行归并在一起来看。对端主机在 api-1 所留那一行的 peer 中。颠倒出现在哪一对上，每个对端各不相同，这个差别就是下一步的线索。有一个对端完全没有问题。

用四个时间点重新测量错位的大小

只有 api-1 的时间同步已得到确认，以它为基准。对每台对端主机，用往返的四个时间点求出 theta = 1/2 * [(T2-T1) + (T3-T4)]，取其中位数，四舍五入到以秒为单位的小数点后第一位，写入 /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。为什么要把两项相加再除以二，请在阅读材料中确认。为什么不能只用一个样本来确定，在 spread_ms 中会原样体现出来。正数表示该主机的时钟超前。

校正后重新排列，顺序就回来了

在 /root/clock-lab/clocklab.py 中编写 realign(records, offsets)。records 是带有 host 和 ts_ms（以该主机时钟为准的 epoch 毫秒）的字典列表，offsets 是 호스트 → 오차 밀리초（韩文，意为“主机 → 误差毫秒数”）。对每条记录的拷贝加上 true_ms = ts_ms - 오차（其中的韩文意为“误差”），然后按 true_ms 升序排序，返回一个新列表。不要改动输入；不在误差列表中的主机按 0 处理；校正后的时间相同时保持输入顺序。用这个函数校正四份日志共 480 行，并在 /root/clock-lab/aligned.json 中写入 records、校正后仍然颠倒的对数 inverted_after、first_true_ms、last_true_ms。

评分器会直接用不属于材料的输入来调用这个函数。只把结果凑对是无法通过的。误差使用第 3 步写下的值，换算成毫秒即可。如果原地排序，输入会被改变，要小心。

凌晨一点出现了两次的那天

/opt/fixtures/clocklab/alerts-local.csv 是只以美国东部（America/New_York）本地时间留下的通知发送记录。这条规则每天发送 96 次，从 00:00 起每隔 15 分钟一次。为文件中出现的各天生成网格进行判定，并写入 /root/clock-lab/dst.json。其中包括 zone、行数 rows、不存在的本地时间 nonexistent_locals、出现两次的本地时间 ambiguous_locals（二者都是 YYYY-MM-DD HH:MM:SS 格式的字符串列表）、由此缺失的发送数 missing_rows、重叠的发送数 duplicate_rows、夏令时结束的切换前后的偏移量 fallback_offset_before 和 fallback_offset_after（形如 -04:00）。

用 zoneinfo 和 fold 来判定。仅凭两个候选的偏移量不同，无法区分不存在的时间和出现两次的时间——让它做一次往返转换试试。不存在的时间，文件里根本没有那一行，所以只浏览文件是找不到的，必须自己生成网格。

经过时间被记录成负数的任务

/opt/fixtures/clocklab/timers.jsonl 同时用挂钟时间和单调时钟记录了在同一台主机上运行的各任务的开始与结束。在 /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——如果那个时钟超前，寿命中就会消失掉相当于误差的那一部分。

次数吻合，却有一次被漏掉，另一次跑了两遍

/opt/fixtures/clocklab/cron-runs.csv 是每小时 05 分运行的结算任务的执行历史。period 是该次执行所处理区间的标签。把历史记录中出现的各天每小时的区间全部生成出来进行比对，并写入 /root/clock-lab/recurring.json。其中包括 expected_periods、actual_runs、一次也没有被处理的 missing_periods、被处理了两次的 duplicate_periods、在前一次执行结束之前就已开始的 overlapping_runs（run_id 列表）及其中重叠最多的秒数 max_overlap_sec、在重复区间中第二次执行重写的行数 double_counted_rows。然后在 /root/clock-lab/clocklab.py 中加入 run_key(record)——同一区间的重新执行要得到相同的值，不同的事情要得到不同的值。

先把总执行次数和预期的区间数比一比。两个数字相同，并不代表正常。如果在键里加入 run_id 或 started_utc，跑了两次的任务就会被当成两次都是新任务——评分器会把它应用到整个历史记录上，统计有多少个键发生重叠。

用原因和预防为六个事件收尾

保持前八步的产出物原样不动，在 /root/clock-lab/report.json 中把六个事件（skew、causality、dst、monotonic、deadline、recurring）分别与 cause、prevention、evidence 连接起来。原因和预防的代码在下面的参考中，evidence 是装有该事件依据的产出物的文件名。最后的评分不只看报告——还会一并确认前面各步的记录是否仍与材料相符，以及 /root/clock-lab/clocklab.py 中的三个函数是否原样保留。

把六个事件区分开、避免混淆的标准是“当初错信了什么”。时钟本身的错位、据此时间确定顺序，以及以本地时间存储，是三种不同的错误。只重写报告是无法通过的，所以不要删除前面的产出物。