diff --git a/.playwright-mcp/console-2026-09-04T02-56-16-987Z.log b/.playwright-mcp/console-2026-09-04T02-56-16-987Z.log index 9ad8635..499e5a5 100644 --- a/.playwright-mcp/console-2026-09-04T02-56-16-987Z.log +++ b/.playwright-mcp/console-2026-09-04T02-56-16-987Z.log @@ -14,3 +14,42 @@ [ 75046ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 [ 75890ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 [ 96067ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 113467ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 121972ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 139681ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 150971ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 161211ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 180744ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 191401ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 210668ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 229082ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 239345ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 252119ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 266045ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 276705ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 289911ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 296875ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 315099ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 325431ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 328418ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 343774ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 347054ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 352405ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 361291ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 370639ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 374286ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 377413ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 394362ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 405423ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 425476ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 434299ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 441775ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 450786ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 456829ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 468812ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 478913ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 491241ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 495228ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 502295ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 511625ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 +[ 524619ms] [ERROR] WebSocket connection to 'wss://app2.hyeonworks.com/api/live/ws' failed: Error during WebSocket handshake: Unexpected response code: 400 @ https://app2.hyeonworks.com/public/build/1518.a3f1f690c084a37f01c7.js:362 diff --git a/docs/evidence/a3-database-crash/01-crash-injection.txt b/docs/evidence/a3-database-crash/01-crash-injection.txt new file mode 100644 index 0000000..1791e1e --- /dev/null +++ b/docs/evidence/a3-database-crash/01-crash-injection.txt @@ -0,0 +1,19 @@ +=== [준비] 손실 측정 설계 확인 === + LAST_SESSION_REFRESH 는 integer(초) — 200ms 손실은 보이지 않는다 + created_on | integer | | not null | + last_session_refresh | integer | | not null | 0 + "idx_user_session_expiration_created" btree (realm_id, offline_flag, remember_me, created_on, user_session_id, user_id) + "idx_user_session_expiration_last_refresh" btree (realm_id, offline_flag, remember_me, last_session_refresh, user_session_id, user_id) + → 대신 행 존재 여부로 잰다. 로그인 하나 = 행 하나 = 이진 판정 + + 전역 synchronous_commit: on + +=== [1] 빠른 연속 로그인을 백그라운드로 시작 === + 루프 시작 + 6초 경과 — 지금까지 성공한 로그인: 0 + +=== [2] PostgreSQL 강제 종료 (SIGKILL) === + 종료 시각: 12:00:26.511 +pod "postgres-7b474b88c8-xc2vt" force deleted from keycloak-lab namespace + 삭제 반환: 12:00:26.586 + 클라이언트가 200 을 받은 로그인 수: 0 diff --git a/docs/evidence/a3-database-crash/02-design-check.txt b/docs/evidence/a3-database-crash/02-design-check.txt new file mode 100644 index 0000000..e51e626 --- /dev/null +++ b/docs/evidence/a3-database-crash/02-design-check.txt @@ -0,0 +1,14 @@ +deployment "postgres" successfully rolled out + +=== crash recovery 가 실행되었는가 (강제 종료의 흔적) === +2026-09-04 02:58:41.036 UTC [1] LOG: database system is ready to accept connections + +=== [설계 확인] 로그인 트랜잭션도 synchronous_commit 을 끄는가 === + --- 로그인 트랜잭션 (INSERT 가 있는 것) --- +2:BEGIN +5:COMMIT +6:BEGIN +9:insert into OFFLINE_USER_SESSION (BROKER_SESSION_ID,CREATED_ON,DATA,LAST_SESSION_REFRESH,REALM_ID,REMEMBER_ME,USER_ID,VERSION,OFFLINE_FLAG,USER_SESSION_ID) values ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) +10:insert into OFFLINE_CLIENT_SESSION (DATA,REALM_ID,TIMESTAMP,VERSION,CLIENT_ID,CLIENT_STORAGE_PROVIDER,EXTERNAL_CLIENT_ID,OFFLINE_FLAG,USER_SESSION_ID) values ($1,$2,$3,$4,$5,$6,$7,$8,$9) +11:SET LOCAL synchronous_commit TO OFF +12:COMMIT diff --git a/docs/evidence/a3-database-crash/03-loss-measurement.txt b/docs/evidence/a3-database-crash/03-loss-measurement.txt new file mode 100644 index 0000000..3da73fc --- /dev/null +++ b/docs/evidence/a3-database-crash/03-loss-measurement.txt @@ -0,0 +1,17 @@ +=== [1] 로그인 루프 시작 (호스트에서 백그라운드로 exec — 세션이 살아 있어야 한다) === + 8초 동안 클라이언트가 200 을 받은 로그인: 106 건 + +=== [2] SIGKILL === + 종료: 12:01:32.981 + 반환: 12:01:33.236 + 최종 성공 로그인 수: 110 건 + 마지막 sid: FimM-krSybBACP2qIvshLWwU + 마지막 sid: EwFfFwOIfqiv8N5GQ5OjtsVq + 마지막 sid: CJX-PxFkS7rUc_9FQgB7iw1f + 마지막 sid: 1EFK7SgUA4M7tq_SkC_BD2er + 마지막 sid: _LiqTczuyxlpOs3T3xs25SLv + +=== [3] PostgreSQL 재기동 후 crash recovery 확인 === +Waiting for deployment "postgres" rollout to finish: 0 of 1 updated replicas are available... +deployment "postgres" successfully rolled out + 2026-09-04 02:59:48.427 UTC [1] LOG: database system is ready to accept connections diff --git a/docs/evidence/a3-database-crash/04-comparison.txt b/docs/evidence/a3-database-crash/04-comparison.txt new file mode 100644 index 0000000..b9f5af3 --- /dev/null +++ b/docs/evidence/a3-database-crash/04-comparison.txt @@ -0,0 +1,27 @@ +=== [4] 클라이언트가 받은 sid 가 DB 에 있는가 === + 클라이언트가 200 을 받은 sid: 291 건 + DB 온라인 세션 총계: 375 + + --- 마지막 15건을 하나씩 조회 --- + TCCOYnVlN30Y2fGyJEsVJ_Lq 있음 + vBcllIkKWovh-FXN9tSzmxAe 있음 + eMpN_ywUdRTks9uBE9aTumPK 있음 + aPC_T0yrlMjrlskcLAp0AvY6 있음 + UBPxmduB-ahGHBg636sY3AEz 있음 + HLnBloNX9R3qQJSkpOnkNqL4 있음 + _KPJS30IAqVhkTJGHcCxKvrM 있음 + rq3caZ9MkyMYlFSSzRjQLygD 있음 + ivvQm70hjl55DPpF7vpYmz_E 있음 + 81mx-rmi-tAeogHx3-su3z2q 있음 + WnvNDH93uzcz1XNFbaMSXk1A 있음 + DXPAIhjO5sGpCUlcD8IEoS8L 있음 + aZMvl4IwPdK-rC_7bG005Z5C 있음 + eIuBCprfWA5x0glcgSKYrrX0 있음 + ozES5kEeu2IFf_cfcC_jFlbF 있음 + + 마지막 15건 중 유실: 0 건 + +=== [5] 전체 대조 — 몇 건이나 사라졌는가 === + 클라이언트 성공: 291 건 + DB 에 존재: 291 건 + ★ 유실: 0 건 diff --git a/docs/evidence/a3-database-crash/05-true-crash.txt b/docs/evidence/a3-database-crash/05-true-crash.txt new file mode 100644 index 0000000..f9a679f --- /dev/null +++ b/docs/evidence/a3-database-crash/05-true-crash.txt @@ -0,0 +1,12 @@ +=== [정리] 세션 테이블 비우고 루프 잔여 확인 === +DELETE 375 + 남은 세션: 0 + +=== [재주입] postmaster(PID 1)에 SIGKILL — 진짜 크래시 === + 8초 후 성공 로그인: 110 건 + SIGKILL: 12:03:21.441 + 최종 성공 로그인: 139 건 + +=== [검증] 이번엔 crash recovery 가 돌았는가 === +deployment "postgres" successfully rolled out + 2026-09-04 02:59:48.427 UTC [1] LOG: database system is ready to accept connections diff --git a/docs/evidence/a3-database-crash/06-backend-kill-crash.txt b/docs/evidence/a3-database-crash/06-backend-kill-crash.txt new file mode 100644 index 0000000..daa2ef2 --- /dev/null +++ b/docs/evidence/a3-database-crash/06-backend-kill-crash.txt @@ -0,0 +1,17 @@ +=== 로그인 루프 시작 === + 8초 후: 112 건 + +=== 백엔드 프로세스에 SIGKILL → postmaster 가 재초기화한다 === + 시각: 12:04:22.063 + 최종 성공 로그인: 153 건 + +=== [검증] crash recovery 가 돌았는가 === + 2026-09-04 02:59:48.427 UTC [1] LOG: database system is ready to accept connections + 2026-09-04 03:02:35.807 UTC [1] LOG: server process (PID 40) was terminated by signal 9: Killed + 2026-09-04 03:02:35.807 UTC [1] LOG: terminating any other active server processes + 2026-09-04 03:02:35.814 UTC [1] LOG: all server processes terminated; reinitializing + 2026-09-04 03:02:35.896 UTC [2585] LOG: database system was not properly shut down; automatic recovery in progress + 2026-09-04 03:02:35.899 UTC [2585] LOG: redo starts at 0/23CAB68 + 2026-09-04 03:02:35.904 UTC [2585] LOG: redo done at 0/2529E40 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s + 2026-09-04 03:02:35.923 UTC [2586] LOG: checkpoint complete: wrote 113 buffers (0.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.004 s, sync=0.004 s, total=0.015 s; sync files=27, longest=0.003 s, average=0.001 s; distance=1405 kB, estimate=1405 kB; lsn=0/252A048, redo lsn=0/252A048 + 2026-09-04 03:02:35.926 UTC [1] LOG: database system is ready to accept connections diff --git a/docs/evidence/a3-database-crash/07-loss-result.txt b/docs/evidence/a3-database-crash/07-loss-result.txt new file mode 100644 index 0000000..523d6a9 --- /dev/null +++ b/docs/evidence/a3-database-crash/07-loss-result.txt @@ -0,0 +1,19 @@ +=== 크래시 전후 대조 === + 클라이언트가 200 과 토큰을 받은 로그인 : 153 건 + 그중 DB 에 실제로 존재 : 149 건 + ★ 유실 : 4 건 + DB 전체 온라인 세션 : 150 건 + +=== 유실된 sid 목록 === + ★ CQUfg9HLH29xvhiu6pVlfWOo ← 토큰은 발급됐는데 세션이 없다 + ★ 5gLP4fqmpZBbjhH_d-0TPMMr ← 토큰은 발급됐는데 세션이 없다 + ★ hkcOv1QskUFmYveMLB6Hljra ← 토큰은 발급됐는데 세션이 없다 + ★ p5XybeQIYmAs818gO4Vl_5ea ← 토큰은 발급됐는데 세션이 없다 + +=== 그 토큰이 지금 실제로 쓰이는가 (마지막 sid 로 확인) === + 마지막 sid: 8do0Bw6tkVLDVxgxotE7GosH + user_session_id | created_on | last_session_refresh +--------------------------+------------+---------------------- + 8do0Bw6tkVLDVxgxotE7GosH | 1788490958 | 1788490958 +(1 row) + diff --git a/docs/evidence/a3-database-crash/README.md b/docs/evidence/a3-database-crash/README.md new file mode 100644 index 0000000..6bf6c8c --- /dev/null +++ b/docs/evidence/a3-database-crash/README.md @@ -0,0 +1,20 @@ +# A-3 — DB 강제 종료와 데이터 손실 증거 + +2026-09-04 12:00–12:05 KST · Keycloak 26.7.0 / PostgreSQL 16 +해설: [`docs/experiment-a3-database-crash.md`](../../experiment-a3-database-crash.md) + +| 파일 | 무엇을 보여주는가 | +|---|---| +| `01-crash-injection.txt` | 첫 시도 실패 — 파드 안 백그라운드 루프가 `exec` 종료와 함께 죽어 0건 수집 | +| `02-design-check.txt` | **핵심 설계 확인** — 로그인 트랜잭션도 `SET LOCAL synchronous_commit TO OFF` 로 커밋한다 | +| `03-loss-measurement.txt` | `--grace-period=0 --force` 주입 | +| `04-comparison.txt` | **유실 0건** — 그러나 crash recovery 가 안 돌았다. 죽인 적이 없는 것 | +| `05-true-crash.txt` | `kill -9 1` 시도 — **컨테이너 안에서 PID 1 은 SIGKILL 을 무시한다** | +| `06-backend-kill-crash.txt` | **성공한 주입** — 백엔드에 SIGKILL → `not properly shut down` / `redo starts` / `redo done` | +| `07-loss-result.txt` | **결과: 153건 중 4건 유실.** 토큰은 발급됐는데 세션 행이 없는 sid 목록 | + +## 핵심 세 줄 + +1. **로그인도 비동기 커밋이다.** refresh 시각뿐 아니라 **로그인 자체**가 사라질 수 있다. +2. **153건 중 4건(약 2.6%) 유실** — 초당 19건 기준 마지막 0.2초 분량, `wal_writer_delay` 기본값과 일치. +3. **주입을 세 번 시도해 세 번째에 성공했다.** 앞의 둘은 "손실 0"으로 보였지만 실제로는 크래시가 아니었다. diff --git a/docs/experiment-a3-database-crash.md b/docs/experiment-a3-database-crash.md new file mode 100644 index 0000000..0db939b --- /dev/null +++ b/docs/experiment-a3-database-crash.md @@ -0,0 +1,323 @@ +# A-3 — DB 를 강제로 죽이면 무엇을 잃는가 (RPO) + +브랜치 `feature/keycloak-a3-database-crash` · +증거 [`docs/evidence/a3-database-crash/`](evidence/a3-database-crash/) · +2026-09-04 12:00–12:05 KST · Keycloak 26.7.0 / PostgreSQL 16 + +선행: [`A-0`](experiment-00-session-replication.md) · +[`A-2`](experiment-a2-database-loss.md) + +--- + +## 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)도 그런지는 +확인하지 않았다. 아니라면 이 측정 설계 자체가 성립하지 않는다. + +```bash +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` 는 크래시가 아니다 + +```bash +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 을 받지 않는다 + +```bash +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 다. + +```bash +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건 정도 로그인하던 중이었으므로 +**대략 마지막 0.2초 분량**이다 — `wal_writer_delay` 기본값(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 을 못 죽인다 | 크래시 재현은 **자식 프로세스**나 **노드에서** | + +### 바꿀 수 있는가 + +```sql +-- 세션 트랜잭션까지 동기 커밋으로 강제하려면 (지연 대가를 치른다) +ALTER DATABASE keycloak SET synchronous_commit = on; -- SET LOCAL 이 이깁니다 +``` + +**`SET LOCAL` 이 우선하므로 이것으로는 못 막는다.** Keycloak 설정이나 +소스 수준의 문제이며, **RPO 0 이 필요하면 복제(streaming replication)로 +푸는 것이 맞다** — 동기 스탠바이가 있으면 `synchronous_commit` 의 의미가 +달라진다. + +--- + +## 8. 재현 절차 (명령어) + +```bash +# 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 종료와 함께 죽는다) +kubectl -n keycloak-lab exec a2-probe -- sh -c '<로그인 반복, sid 를 /tmp/sids 에>' & + +# 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. 대조 +kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak -tAc \ + "select count(*) from offline_user_session where user_session_id in ()" +``` + +--- + +## 9. 다음 실험에 남기는 것 + +| 실험 | 이 실험이 준 것 | +|---|---| +| **D-1** 백업·복구 | RPO 는 **백업 주기 + 이 손실**이다. 둘을 더해야 진짜 RPO | +| **B-6** Redis 영속화 | `appendfsync everysec` 은 **같은 모양의 트레이드오프** | +| **A-4** 노드 상실 | 노드가 죽으면 이것도 함께 일어난다 (postgres 가 kc-lab-2) | +| 전체 | **주입 성공 신호를 미리 정한다.** 여기서는 crash recovery 로그 |