로그가 미래에서 왔다 — 시계가 만든 다섯 사건 · 한 번만 돌았어야 할 정산이 두 번 돌았다 · 실습
시계 사건 노트 — 아홉 개의 기록을 읽는다
목표
시계가 어긋난 채로 남은 기록 묶음을 읽어, 무엇이 어긋났는지 숫자로 재고 시각을
올바르게 다루는 함수를 직접 씁니다. JSON 과 CSV 를 파이썬으로 읽을 수 있는
중급 학습자를 위한 60분 조사입니다.
왜 중요한가
이 사건에서 서비스는 내내 정상이었습니다. 고장 난 것은 프로세스가 아니라 시각을
적어 둔 종이입니다. 그런데 사람은 그 종이를 읽고 원인을 정하기 때문에, 어긋난
기록은 멀쩡한 시스템을 범인으로 만들고 진짜 원인을 숨깁니다. 여기서 배우는 것은
시계를 맞추는 법이 아닙니다 — 시계를 맞추는 일은 대개 남이 하고, 이 실습 파드에는
그럴 권한도 없습니다. 배우는 것은 어긋난 기록을 읽는 법 과 **어긋나도 무너지지
않는 코드를 쓰는 법** 입니다.
사건 배경
2025년 11월 1일 저녁, 결제 API 한 대(api-2)의 응답이 4분 37초로 찍히기 시작했습니다.
같은 시각 워커(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 유효 구간이 못박힌 인증서사건 코드표 (마지막 단계에서 쓸 이름)
사건마다 「무엇을 잘못 믿었는가」와 「그래서 무엇을 바꿀 것인가」를 한 쌍으로 둡니다.
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— 지역 시각 이름표가 기간을 유일하게 가리킨다고 믿었다. 멱등한 실행 열쇠를 쓴다.
단계
1. /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 에 적습니다. 시각은 파일에 적힌 문자열 그대로 옮기세요.
2. 요청 하나는 네 줄을 남깁니다 — 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 (밀리초, 원인 시각 빼기 결과 시각)를 담습니다.
3. 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 를 적습니다.
4. /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 를 적으세요.
5. /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 꼴).
6. /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 를 적으세요.
7. /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.
8. /opt/fixtures/clocklab/cron-runs.csv 는 매시 5분에 도는 정산 작업의 실행 이력입니다. 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) 를 더하세요 — 같은 기간의 재실행이면 같은 값, 다른 일이면 다른 값이 나와야 합니다.
9. 앞 여덟 단계의 산출물을 그대로 둔 채 /root/clock-lab/report.json 에 사건 여섯 건(skew · causality · dst · monotonic · deadline · recurring)을 cause · prevention · evidence 로 이으세요. 원인과 예방 코드는 아래 참고에 있고, evidence 는 그 사건의 근거가 담긴 산출물 파일 이름입니다. 마지막 채점은 보고서만 보지 않습니다 — 앞 단계의 기록이 여전히 재료와 맞는지, /root/clock-lab/clocklab.py 의 함수 세 개가 그대로 살아 있는지도 함께 확인합니다.
참고
- 산출물은 전부
/root/clock-lab/아래에 만듭니다. 세션이 끝나면 사라지니 필요하면 따로 보관하세요. - 이 실습은 60분으로 잡혀 있어 기본 세션 길이와 같습니다. 시작할 때 미리 시간을 연장해 두세요.
- 파이썬 표준 라이브러리만으로 충분합니다.
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.- 흔한 실수 둘 — 오차의 부호를 반대로 적는 것, 그리고 없는 시각을 파일에서 찾으려는 것(파일에 없습니다).
단계 9개
- 네 대의 로그를 펼쳐 놓는다
- 원인보다 먼저 일어난 결과를 찾는다
- 어긋난 크기를 네 시각으로 되잰다
- 보정해서 다시 세우면 순서가 돌아온다
- 새벽 한 시가 두 번 온 날
- 경과 시간이 음수로 찍힌 작업들
- 멀쩡한 인증서가 거절당한 12초
- 개수는 맞는데 한 번은 빠지고 한 번은 두 번 돌았다
- 여섯 사건을 원인과 예방으로 닫는다