---
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번 더 돌려도 한 번도 다시 나오지 않았다.

## 대조군이 없었다면 무엇이 됐나

![주입 전 대조군과 대비될 때만 귀속이 성립하고, 대조군이 없으면 같은 관측이 오보로 이어지는 구성](../../../final/assets/measurement-control/measurement-control.svg)

같은 관측이 두 갈래로 갈린다. 평시 오류율을 아는 쪽에서는 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 -->