docs: A-3 — four logins returned tokens for sessions the crash erased
Keycloak commits the login INSERT with synchronous_commit off, so a crash loses whole sessions and not just refresh timestamps. Measured 4 of 153 lost, matching the default wal_writer_delay window. Two injections failed silently first: --grace-period=0 --force lets the container runtime send SIGTERM so PostgreSQL flushes and shuts down cleanly, and SIGKILL to PID 1 from inside its own namespace is ignored by the kernel. Killing a backend makes the postmaster reinitialize, which is a real crash recovery. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
DongHyeonka
co-authored by
Claude Opus 5
Claude Opus 5
parent
4177fb6a48
commit
99b689e715
@@ -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
|
||||
@@ -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
|
||||
@@ -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
|
||||
@@ -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 건
|
||||
@@ -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
|
||||
@@ -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
|
||||
@@ -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)
|
||||
|
||||
@@ -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"으로 보였지만 실제로는 크래시가 아니었다.
|
||||
Reference in New Issue
Block a user