DongHyeonkaandClaude Opus 5
2109f726fe
기록 84편을 계약 에이전트로 다시 썼다. 기존 71편(kss 25 · virt 46)과, 계약에만 있고 안 쓰여 있던 새 글감 13편이다. 원장 84개를 열어 단계마다 스킬 영수증과 관문 종료 코드를 적었고 verify-pipeline-run.py 가 error 0 으로 닫는다. SSOT 결함 둘을 고쳤다. - kss 의 `약 58일` 이 반입 중 `약 59일` 로 바뀌어 있었다. 원 증거 파일이 「남은 일수: 88일 … 실제 갱신까지 약 58일」로 산수를 직접 적는다. D-4a 쪽 `약 59일` 은 강제 갱신 뒤(`VALID: 89 days`)라 맞는 값이라 그대로 뒀다. - virt §198 의 `11.6GB` 는 §178 의 원 측정 `Mem: 11648`(MiB)과 어긋나는데 원 가이드의 표기 그대로라 고치지 않고 쓰이는 자리에 대조를 적었다. 기록의 수치 오류 셋을 고쳤다 — CASE 요약의 「게스트 셋에 8240MB」(5120+3120 은 둘이다), k3s 편이 같은 것을 여섯·일곱·여덟로 세던 것, no-docker 편의 「셋을 더 든다」(§281 의 표는 네 행이고 디스크 행이 빠져 있었다). 계약을 셋 고쳤다. - kss 의 sourceRepository 리비전이 cdac9b8 이었는데 그 커밋에는 docs/guides/** 28개가 아예 없다. 9465582b 로 바꾸고, 반입한 바이트가 어느 커밋과도 같지 않다는 것을 측정값과 함께 적었다 — 반입은 커밋이 아니라 그 시점의 작업 트리에서 떠 온 것이다(kss 297/306 · virt 12/14 가 작업 트리와 같고, 200 커밋을 거슬러 전수 대조했을 때 가장 가까운 커밋도 28개가 어긋났다). - virt 계약이 「2026-09-11 재배분」이라고 적는데 SSOT 는 재배분 날짜를 적지 않고 재배분 뒤 값은 이미 2026-09-10 측정에 찍혀 있다. - kss 후보 대장이 지나친 절 아홉에 처분을 적었다(warn 9 → 0). 새 글감은 0건이고 넷은 앵커가 h3 슬러그의 접두가 아니라 중간 토막이라 검사기가 못 본 것이었다. style_profile.mjs 의 결함 둘을 고쳤다 — frontmatter 가 문장으로 세어져 (실측 398자짜리 「문장」 하나) 평균 길이를 기준 안으로 밀어 올리고 있었고, engPerSent 의 분자는 목록을 포함한 글에서, 분모는 목록을 걷어낸 글에서 세고 있었다(Question 기록에서 11.94 → 3.86). verify-pipeline.py 전 항목 PASS · error 0 · unittest 334건 OK. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
143 lines
9.6 KiB
Markdown
143 lines
9.6 KiB
Markdown
---
|
|
kind: CASE
|
|
slug: seventy-six-failures-that-were-not-the-servers
|
|
title: 실패 76 건이 서버 탓이 아니었다 — 대조군이 오보를 막았다
|
|
topic: when-the-measurement-lies
|
|
topicName: 주입이 걸렸는지 무엇으로 아는가
|
|
project: keycloak-session-store
|
|
status: 게시 전
|
|
lastVerifiedOn: 2026-09-04
|
|
sourceRevision: cdac9b8178391311d8eca1ebc6cac15bb62d79af
|
|
source:
|
|
- final/document.md#결정이-지켜지는지-확인하는-방법-대조군-없이는
|
|
assets:
|
|
- key: measurement-control
|
|
file: ../../../final/assets/measurement-control/measurement-control.svg
|
|
evidence:
|
|
- ../../../final/evidence/raw/d4-certificate-renewal__05-control-no-injection.txt
|
|
- ../../../final/evidence/raw/d4-certificate-renewal__11-inflight-full.txt
|
|
---
|
|
|
|
# 실패 76 건이 서버 탓이 아니었다 — 대조군이 오보를 막았다
|
|
|
|
nginx reload 중 감시 로그에 찍힌 실패 76건은 서버에 닿지 않은 요청이었다. 연결수가 0 이고 소요 시간이 50µs 였다. 같은 순간 대조 폴링 49건은 전부 200 이었고, 같은 조건을 100번 반복해도 재현되지 않았다. 주입 전에 대조군 900건을 잡아 두지 않았다면 「갱신 중 대규모 요청 실패」로 적었다.
|
|
|
|
## 관계
|
|
|
|
- **예측을 먼저 적고, 주입이 걸렸는지 결과와 따로 확인하고, 대조군 없이 귀속하지 않는다**
|
|
그 기준의 세 번째 규칙을 이 확인이 실제로 써 본 결과다.
|
|
- **up 지표는 살아 있지만 쓸모없는 상태를 보지 못한다**
|
|
이 실험대에서 한 지표만 보고 판정한 다른 경우이고, 방향이 반대다. 그쪽은 이상을 못 봤고 이쪽은 없는 이상을 봤다.
|
|
- **두 시계에서 온 값을 빼지 않는다**
|
|
같은 D-4 에서 나온 다른 측정 결함이다. 감시를 돌린 기계와 실험대의 시계가 106초 달랐다.
|
|
|
|
## 문제
|
|
|
|
인증서 갱신 중 nginx reload 가 진행 중이던 요청을 끊는지 확인해야 했다. 새 연결만 폴링하면 TLS 핸드셰이크가 매번 새로 일어나서 「새 연결을 받아주는가」만 재게 되므로, reload 순간에 실제로 전송 중인 요청을 따로 만들어 감시했다.
|
|
|
|
그 감시 로그에 실패가 76건 남았다. 이 값만 보면 reload 가 진행 중 요청을 대량으로 끊은 것으로 읽힌다.
|
|
|
|
## 결론
|
|
|
|
감시 로그의 실패 : 76건
|
|
같은 순간 대조 폴링 : 49건 전부 200
|
|
실패한 요청의 연결수 : 0
|
|
실패한 요청의 소요 시간 : 50µs
|
|
같은 조건 재현 : 0/100
|
|
주입 전 대조군 : 900건 전부 200, 오류 0
|
|
서버 쪽 원인으로 귀속 : x
|
|
|
|
TCP 연결 시도조차 없었고 소요 시간이 DNS 조회보다 짧았으므로 요청이 서버에 닿지 않았다. 같은 순간 다른 경로로 들어간 요청은 전부 200 을 받았다. 훅을 넣고 다시 검증한 D-4a 에서 reload 자체는 새 연결 8856건 전부 200 이었고, 전송 12초째에 reload 를 맞은 42초짜리 요청은 845361바이트를 온전히 받았다.
|
|
|
|
## 검증 환경
|
|
|
|
실험 : D-4 인증서 갱신 중 nginx reload
|
|
호스트 TLS 종단 : nginx, Let's Encrypt 인증서
|
|
주입 전 대조군 : 0.2초 간격 900회 = 180초
|
|
대조군 응답시간 : 최소 67 중앙 98 p95 195 최대 1121 평균 106.9 (ms)
|
|
진행 중 요청 : 845KB 번들을 20k/s 로 받아 한 요청을 42초 동안 유지
|
|
관측 지점 : 외부 curl · Prometheus 지표 · PostgreSQL 직접 조회
|
|
시계 : test-server 는 NTP 가 꺼져 있어 106초 빠르다
|
|
|
|
## 재현 조건
|
|
|
|
1. 주입 전에 평시 오류율을 잰다.
|
|
0.2초 간격으로 900회 폴링하고 상태코드 분포와 응답시간, TLS 핸드셰이크 횟수를 기록한다.
|
|
|
|
2. reload 순간에 전송 중인 요청이 있도록 만든다.
|
|
845KB 번들을 20k/s 로 내려받아 요청 하나를 42초 동안 유지한다.
|
|
|
|
3. 새 연결 폴링과 진행 중 요청 감시를 각각 다른 프로세스로 띄우고 같은 시간대에 돌린다.
|
|
|
|
4. 인증서를 강제 갱신하고 nginx 를 reload 한다.
|
|
|
|
5. 실패가 나오면 그 순간의 대조 폴링 결과, 연결수, 소요 시간을 함께 읽는다.
|
|
|
|
6. 같은 조건을 100회 반복해 재현되는지 본다.
|
|
|
|
## 본문
|
|
|
|
<!-- body:start -->
|
|
## 주입 전에 평시를 먼저 쟀다
|
|
|
|
D-4 의 물음은 nginx reload 중 진행 중이던 요청이 어떻게 되는가였다. 주입에 쓸 강제 갱신은 진짜 인증서를 발급하는 명령이라 되돌릴 수 없고 Let's Encrypt 의 발급 한도(주당 중복 인증서 5장)를 한 장 깎는다. 그래서 이 실험 전체에서 한 번만 쓰기로 했고, 그 한 번을 헛되게 쓰지 않으려면 잴 것을 주입 전에 전부 재 둬야 했다. 답하기 전에 주입 없는 상태의 오류율부터 잡은 것이 그래서다 — 0.2초 간격으로 900회, 180초 동안 폴링해서 900건 전부 200 이고 오류가 0 이라는 것을 확인했다. 중앙값은 98ms, p95 는 195ms 였다.
|
|
|
|
이 폴링에는 한계가 하나 있었다. TLS 핸드셰이크가 900회 전부 일어나서 매 요청이 새 연결이었고, 그래서 이 폴링이 재는 것은 「새 연결을 받아주는가」다. 계획서가 물은 것은 진행 중이던 요청이므로 reload 순간에 실제로 전송 중인 요청이 있어야 했다. 845KB 짜리 번들을 20k/s 로 일부러 느리게 받아 요청 하나를 42초 동안 유지하는 감시를 따로 띄웠다.
|
|
|
|
## 76건이 한 초에 몰려 찍혔다
|
|
|
|
감시 로그는 146줄이었고 그중 76줄이 `코드=000` 이었다. 나머지 70줄은 `코드=200` 에 `바이트=845361` 이었다.
|
|
|
|
```text label="진행 중 요청 감시 — 76줄이 같은 초에 찍혔다"
|
|
08:14:22 코드=200 바이트=845361 시간=42.338482 연결수=1
|
|
08:15:04 코드=000 바이트=0 시간=0.001148 연결수=0
|
|
08:15:04 코드=000 바이트=0 시간=0.000051 연결수=0
|
|
08:15:04 코드=000 바이트=0 시간=0.000056 연결수=0
|
|
08:15:04 코드=200 바이트=845361 시간=42.236496 연결수=1
|
|
```
|
|
|
|
76줄의 시각이 전부 `08:15:04` 로 같고, 같은 초의 다음 줄은 다시 `코드=200` 에 42.236496초다. 42초씩 걸리던 요청이 한 초 안에 76번 끝났다. 실패가 즉시 돌아오니 다음 요청을 바로 띄우는 감시 루프가 그 1초 동안 폭주했다.
|
|
|
|
## 76건을 서버 탓으로 적지 않은 근거 네 가지
|
|
|
|
76건을 reload 탓으로 적기 전에 네 가지를 봤다.
|
|
|
|
| 근거 | 값 |
|
|
|---|---|
|
|
| 같은 순간 폴링 | 49건 전부 200 |
|
|
| 연결수 | 0 — TCP 연결 시도조차 못 했다 |
|
|
| 소요 시간 | 50µs — DNS 조회보다 짧다 |
|
|
| 재현 | 0/100 |
|
|
|
|
연결수가 0 이므로 서버까지 패킷이 가지 않았다. 소요 시간 50µs 는 이름 풀이 한 번보다 짧아서 요청이 네트워크로 나간 시간이 아니다. 같은 순간 다른 프로세스가 보낸 49건은 전부 200 을 받았으므로 그 시각에 서버는 요청을 처리하고 있었다. 같은 조건으로 100번 더 돌려도 한 번도 다시 나오지 않았다.
|
|
|
|
## 대조군이 없었다면 무엇이 됐나
|
|
|
|
|
|
|
|
같은 관측이 두 갈래로 갈린다. 평시 오류율을 아는 쪽에서는 76건을 대조군 900건과 견주어 서버 바깥 원인으로 돌릴 수 있고, 모르는 쪽에서는 「갱신 중 대규모 요청 실패」로 적게 된다.
|
|
|
|
이 실험대에서 대조군 규칙은 이미 두 번 어겨졌다. A-6 에서는 대조군이 −41% 인데도 「영향 없음」이라고 적었고, A-8 에서는 표본 9개로 무중단을 주장했다. 둘 다 나중에 고쳤다. 세 번째가 이 76건인데, 이번에는 대조군을 먼저 잡아 둔 덕분에 기록에 들어가기 전에 걸렸다.
|
|
|
|
## 같은 대조를 문서 전체에 돌렸다
|
|
|
|
기록을 다 쓴 뒤 본문의 주장과 증거 파일을 하나씩 맞춰 봤다. 어긋난 곳이 여섯 군데 나왔다.
|
|
|
|
| 어디 | 무엇이 어긋났나 |
|
|
|---|---|
|
|
| C-1 | 본문은 「세션 0」인데 증거는 4 |
|
|
| C-2 | `exit code 1` 인 명령의 성공 읽기를 실었다 |
|
|
| A-1 | 4초 전 파드 재시작이 만든 분단을 conntrack 공으로 돌렸다 |
|
|
| A-2 | 첫 측정의 `000000{"error":"HTTP 401"}401` 을 숨겼다 |
|
|
| A-3 | `wal_writer_delay` 를 재지 않고 단언했다 (실측 200ms, 로그인율도 19/s 가 아니라 14/s) |
|
|
| D-1 | 본문은 RTO 30초, 자기 타임라인은 41초 |
|
|
|
|
전부 고치면서 무엇이 어긋났는지를 표로 남겼다. 76건과 이 여섯 건은 같은 방향으로 틀린다 — 숫자 하나를 그 숫자가 나온 조건과 떼어 놓고 읽으면 본문이 자기 증거와 다른 말을 하게 된다.
|
|
|
|
## 이 확인이 말하지 않는 것
|
|
|
|
76건이 서버 탓이 아니라는 것까지가 이 확인의 범위다. 감시를 돌린 쪽에서 무엇이 그 한 초 동안 76번 즉시 실패했는지는 특정하지 못했다. 감시를 `-s` 로 돌려 curl 의 오류 메시지를 버렸고 종료 코드도 남기지 않았기 때문이고, 재현이 0/100 이라 같은 조건을 다시 만들어 좁힐 수도 없었다. 장치가 왜 실패했는지를 남기지 않은 탓에, 이 76건을 서버 밖으로 돌린 근거는 같은 시각 대조 폴링이 멀쩡했다는 사실 하나였다.
|
|
|
|
그래서 감시 자체를 바꿨다. curl 의 종료 코드까지 함께 적고 실패하면 1초 쉬어 루프 폭주를 막는 형태로 갈아끼웠고, 같은 로그의 뒷부분에는 그 뒤로 `curl종료=0` 이 줄마다 붙어 있다. 다음에 같은 일이 생기면 6이 이름 풀이, 7이 연결, 35가 TLS 라는 식으로 종료 코드가 바로 답한다.
|
|
<!-- body:end -->
|