keycloak-pattern/docs/experiment-a3-database-crash.md

A-3 — DB 를 강제로 죽이면 무엇을 잃는가 (RPO)

브랜치 feature/keycloak-a3-database-crash · 증거 docs/evidence/a3-database-crash/ · 2026-09-04 12:00–12:05 KST · Keycloak 26.7.0 / PostgreSQL 16

선행: A-0 · A-2

---

구조

다이어그램 규약은 diagrams/_style.md. 실험대 전체 구조는 diagrams/lab-topology.svg.

---

0. 결론부터

  클라이언트가 200 과 토큰을 받은 로그인 : 153 건
  그중 DB 에 실제로 존재                 : 149 건
  ★ 유실                                 :   4 건

로그인이 성공했다고 응답받았는데 세션이 존재하지 않는다.

A-0 에서 발견한 SET LOCAL synchronous_commit TO OFF 의 대가를 실측했다. 버그가 아니라 의도된 설계이며, 그 비용이 얼마인지를 숫자로 확인한 것이다.

---

1. 설계 — 무엇을 재야 손실이 보이는가

1-1. LAST_SESSION_REFRESH 로는 못 잰다

처음 계획은 "세션 갱신 시각이 되감기는지" 보는 것이었다. 스키마를 보고 접었다.

 created_on           | integer
 last_session_refresh | integer      ← 초 단위

손실 창은 수백 밀리초인데 눈금이 1초다. 보일 리가 없다.

1-2. 행 존재 여부로 잰다 — 이진 판정

   로그인 1회  =  OFFLINE_USER_SESSION 행 1개
   클라이언트가 sid 를 받았다  =  서버가 COMMIT 했다고 응답했다
   크래시 후 그 sid 가 없다    =  잃은 것

있거나 없거나이므로 눈금 문제가 없다.

1-3. 그런데 로그인도 비동기 커밋인가 — 먼저 확인해야 한다

A-0 에서 잡은 것은 refresh 트랜잭션이었다. 로그인(INSERT)도 그런지는 확인하지 않았다. 아니라면 이 측정 설계 자체가 성립하지 않는다.

kubectl -n keycloak-lab exec deploy/postgres -- \
  psql -U keycloak -d keycloak -c "alter system set log_statement='all'"
kubectl -n keycloak-lab exec deploy/postgres -- \
  psql -U keycloak -d keycloak -c "select pg_reload_conf()"

BEGIN
insert into OFFLINE_USER_SESSION (...) values (...)
insert into OFFLINE_CLIENT_SESSION (...) values (...)
SET LOCAL synchronous_commit TO OFF          ← 로그인도 비동기 커밋이다
COMMIT

확인됐고, 함의가 refresh 보다 훨씬 무겁다.

	잃으면
refresh 갱신 시각	세션 수명이 조금 짧아진다. 사용자는 모른다
로그인 자체	토큰은 손에 있는데 세션이 없다. 다음 요청부터 실패

---

2. 실패한 주입 ① — --grace-period=0 --force 는 크래시가 아니다

kubectl -n keycloak-lab delete pod -l app=postgres --grace-period=0 --force

  클라이언트 성공: 291 건
  DB 에 존재:      291 건
  ★ 유실:            0 건

0건. 그런데 이건 "안 잃었다"가 아니라 죽인 적이 없는 것이다.

=== 재기동 로그 ===
  database system is ready to accept connections
  (그뿐. "not properly shut down" 이 없다)

crash recovery 가 돌지 않았다 = 깨끗하게 내려갔다.

신호	PostgreSQL 의 반응
SIGTERM	fast shutdown — 진행 중 트랜잭션을 롤백하고 WAL 을 플러시한 뒤 종료
SIGINT	smart shutdown — 연결이 끊기길 기다린다
SIGKILL	즉사 — 플러시 없음. 다음 기동에 crash recovery

--force --grace-period=0 는 API 오브젝트를 즉시 지우지만 컨테이너 런타임은 여전히 정상 종료 절차를 밟는다. PostgreSQL 은 SIGTERM 을 받고 얌전히 플러시했다.

A-1 에서 배운 것이 또 나왔다 — 주입이 실제로 걸렸는지 먼저 확인하지 않으면 "아무 일도 없었다"를 결과로 착각한다. 여기서는 crash recovery 메시지가 그 확인 수단이다.

---

3. 실패한 주입 ② — 컨테이너 안에서 PID 1 은 SIGKILL 을 받지 않는다

kubectl -n keycloak-lab exec deploy/postgres -- kill -9 1

아무 일도 일어나지 않았다. 파드는 재시작하지 않았고 로그 시각도 그대로였다.

개념 — PID 1 의 시그널 보호

리눅스 커널은 PID 1 을 특별 취급한다. 자기 PID 네임스페이스 안에서 온 시그널은 핸들러가 등록된 것만 전달된다. SIGKILL 도 예외가 아니다.

   같은 네임스페이스 안에서  →  PID 1 은 등록하지 않은 시그널을 무시한다
   조상 네임스페이스에서     →  전달된다 (노드에서 kill -9 하면 죽는다)

부팅 초기에 init 을 실수로 죽여 시스템이 멈추는 것을 막기 위한 장치인데, 컨테이너에서는 "안에서는 PID 1 을 못 죽인다" 로 나타난다.

---

4. 성공한 주입 — 백엔드 프로세스를 죽인다

PostgreSQL 은 postmaster(부모) + 연결마다 백엔드(자식) 구조다. 자식 하나가 비정상 종료하면 postmaster 는 공유 메모리가 오염됐다고 보고 전체를 재초기화한다. 그게 곧 crash recovery 다.

kubectl -n keycloak-lab exec deploy/postgres -- \
  sh -c 'kill -9 $(pgrep -f "postgres: keycloak keycloak" | head -1)'

server process (PID 40) was terminated by signal 9: Killed
terminating any other active server processes
all server processes terminated; reinitializing
database system was not properly shut down; automatic recovery in progress
redo starts at 0/23CAB68
redo done at 0/2529E40
checkpoint complete: wrote 113 buffers ...
database system is ready to accept connections

이번엔 주입이 걸렸다. not properly shut down + redo 가 증거다.

파드는 재시작하지 않는다 (restarts=0) — 컨테이너의 PID 1 인 postmaster 는 살아 있고, 자식만 갈아치운 것이다. 데이터 관점에서는 전원이 나간 것과 같다.

---

5. 결과

=== 크래시 전후 대조 ===
  클라이언트가 200 과 토큰을 받은 로그인 : 153 건
  그중 DB 에 실제로 존재                 : 149 건
  ★ 유실                                 :   4 건

=== 유실된 sid ===
  ★ CQUfg9HLH29xvhiu6pVlfWOo  ← 토큰은 발급됐는데 세션이 없다
  ★ 5gLP4fqmpZBbjhH_d-0TPMMr
  ★ hkcOv1QskUFmYveMLB6Hljra
  ★ p5XybeQIYmAs818gO4Vl_5ea

약 2.6% 유실.

처음 이 문서는 "초당 19건 … wal_writer_delay 기본값(200ms)과 맞는다" 고 썼는데, 그 시점에 wal_writer_delay 를 조회한 적이 없었다. 나중에 쟀다.

 name                   | setting | unit | source
------------------------+---------+------+---------
 wal_writer_delay       | 200     | ms   | default
 wal_writer_flush_after | 128     | 8kB  | default
 synchronous_commit     | on      |      | default

08-wal-settings.txt

값은 맞았지만 그때는 추정이었다. 그리고 로그인 속도도 정확히는 증거의 8초에 112건 ≈ 초당 14건이며 19건이 아니다. 4건은 그 속도에서 약 0.29초 분량이고, 200ms 창과 같은 자릿수이되 정확히 일치하지는 않는다.

사용자에게 어떻게 보이는가

   로그인 성공  →  access token + refresh token 을 받음
        │
        │  (크래시)
        ▼
   다음 요청     →  access token 은 60초간 통한다
        │            (서명만 보는 경로라면)
        ▼
   60초 후 refresh  →  "Session not active"  →  다시 로그인

즉시 드러나지 않는다. access token 수명 동안은 정상으로 보이다가 갱신 시점에 끊긴다. 장애와 증상 사이에 최대 60초의 시차가 있다.

---

6. 개념

WAL 과 synchronous_commit

   COMMIT
     │
     ├─ WAL 버퍼(메모리)에 기록          ← 항상 한다
     │
     ├─ synchronous_commit = on  : 디스크 플러시를 기다렸다가 응답
     └─ synchronous_commit = off : 기다리지 않고 즉시 응답   ← Keycloak
                                     │
                                     └─ 크래시 시 이 구간이 사라진다

설정	응답 속도	잃는 것
on (PostgreSQL 기본)	느리다 (디스크 대기)	없다
off	빠르다	최대 wal_writer_delay × 3 분량

전역 설정은 on 이었다.

전역 synchronous_commit: on

Keycloak 이 자기 트랜잭션에만 SET LOCAL 로 끈다. DBA 가 서버 설정만 보고 "우리는 동기 커밋"이라 믿으면 틀린다. 애플리케이션이 트랜잭션 단위로 뒤집을 수 있다.

crash recovery

   기동 시 pg_control 을 읽는다
     └─ "깨끗하게 종료됨" 표시가 없다
          └─ "database system was not properly shut down"
               └─ 마지막 체크포인트부터 WAL 을 재생(redo)
                    └─ 디스크에 안 내려간 커밋은 복구할 수 없다  ← 손실

redo starts at 0/23CAB68 → redo done at 0/2529E40 사이가 재생된 구간이다. WAL 에 없는 것은 재생할 수도 없다.

이 손실이 "허용된" 이유

Keycloak 의 판단은 이렇게 읽힌다.

세션 쓰기는 매우 잦다	로그인마다, refresh 마다
잃어도 회복 가능하다	사용자가 다시 로그인하면 된다
동기 커밋의 비용은 모든 요청에 붙는다	크래시는 드물다

드문 사고의 비용을 상시 지연으로 지불하지 않겠다는 선택이다. 합리적이지만, 선택했다는 사실을 알고 있어야 한다.

---

7. 운영에 주는 것

알게 된 것	함의
로그인도 비동기 커밋	RPO 가 0 이 아니다. 크래시 시 마지막 수백 ms 로그인은 사라진다
전역 on 인데 세션만 off	서버 설정으로 판단하면 안 된다. 애플리케이션이 뒤집는다
손실이 즉시 안 보인다	access token 수명만큼 시차. 모니터링은 갱신 실패율을 봐야 한다
--grace-period=0 은 크래시가 아니다	장애 훈련이 훈련이 안 될 수 있다
컨테이너 안에서 PID 1 을 못 죽인다	크래시 재현은 자식 프로세스나 노드에서

바꿀 수 있는가

-- 세션 트랜잭션까지 동기 커밋으로 강제하려면 (지연 대가를 치른다)
ALTER DATABASE keycloak SET synchronous_commit = on;   -- SET LOCAL 이 이깁니다

SET LOCAL 이 우선하므로 이것으로는 못 막는다. Keycloak 설정이나 소스 수준의 문제이며, RPO 0 이 필요하면 복제(streaming replication)로 푸는 것이 맞다 — 동기 스탠바이가 있으면 synchronous_commit 의 의미가 달라진다.

---

---

증거 파일

증거 수집 시각: 2026-09-04 11:58 – 16:32 KST (파일 mtime 기준. 문서 상단의 시각 표기는 작성 시점이라 다를 수 있다.)

파일	종류
01-crash-injection.txt	터미널 원문
02-design-check.txt	터미널 원문
03-loss-measurement.txt	터미널 원문
04-comparison.txt	터미널 원문
05-true-crash.txt	터미널 원문
06-backend-kill-crash.txt	터미널 원문
07-loss-result.txt	터미널 원문
08-wal-settings.txt	터미널 원문

파일별 상세는 evidence/a3-database-crash/README.md.

8. 재현 절차 (명령어)

# 0. 설계 확인 — 로그인도 비동기 커밋인지 먼저 본다
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "alter system set log_statement='all'" -c "select pg_reload_conf()"
#   → 로그인 1회 후 로그에서 "SET LOCAL synchronous_commit TO OFF" 확인

# 1. 세션 테이블 비우기
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "delete from offline_user_session"

# 2. 로그인 루프 — 호스트에서 백그라운드로 exec 한다.
#    파드 안에서 ( ... ) & 로 띄우면 exec 세션이 끝날 때 같이 죽는다(실측).
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab exec a2-probe -- sh -c "
  i=0
  while [ \$i -lt 200 ]; do
    R=\$(curl -s --max-time 5 -X POST http://$K0:8080/realms/master/protocol/openid-connect/token \
         -d grant_type=password -d client_id=admin-cli -d username=admin -d password=lab-admin-change-me)
    S=\$(echo \"\$R\" | sed -n 's/.*\"access_token\":\"\\([^\"]*\\)\".*/\\1/p' \
         | cut -d. -f2 | sed 's/\$/==/' | base64 -d 2>/dev/null \
         | sed -n 's/.*\"sid\":\"\\([^\"]*\\)\".*/\\1/p')
    [ -n \"\$S\" ] && echo \"\$S\" >> /tmp/sids
    i=\$((i+1))
  done" >/dev/null 2>&1 &
LOOP=$!

# 3. 진짜 크래시 — 백엔드 프로세스에 SIGKILL
kubectl -n keycloak-lab exec deploy/postgres -- \
  sh -c 'kill -9 $(pgrep -f "postgres: keycloak keycloak" | head -1)'

# 4. 주입이 걸렸는지 확인 — 이게 없으면 결과를 해석하지 않는다
kubectl -n keycloak-lab logs deploy/postgres | grep -E "not properly shut down|redo"

# 5. 대조 — 클라이언트가 200 을 받은 sid 를 그대로 IN 절로 만든다
kill $LOOP 2>/dev/null
kubectl -n keycloak-lab exec a2-probe -- cat /tmp/sids > /tmp/sids.txt
TOTAL=$(wc -l < /tmp/sids.txt)
IN=$(sed "s/^/'/; s/$/'/" /tmp/sids.txt | paste -sd,)
FOUND=$(kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak -tAc \
  "select count(*) from offline_user_session where offline_flag='0' and user_session_id in ($IN)")
echo "클라이언트 성공 $TOTAL / DB 존재 $FOUND / 유실 $((TOTAL-FOUND))"

---

9. 다음 실험에 남기는 것

실험	이 실험이 준 것
D-1 백업·복구	RPO 는 백업 주기 + 이 손실이다. 둘을 더해야 진짜 RPO
B-6 Redis 영속화	appendfsync everysec 은 같은 모양의 트레이드오프
A-4 노드 상실	노드가 죽으면 이것도 함께 일어난다 (postgres 가 kc-lab-2)
전체	주입 성공 신호를 미리 정한다. 여기서는 crash recovery 로그