From 22d873eb4fd5f0abaaf4b246d94851602497cc13 Mon Sep 17 00:00:00 2001 From: DongHyeonka Date: Fri, 4 Sep 2026 10:14:45 +0900 Subject: [PATCH] docs: capture the SQL the other node actually runs, and correct the replication claim PostgreSQL statement logging shows keycloak-1 reading and updating the session created on keycloak-0. The same transaction reveals optimistic locking via VERSION, SKIP LOCKED, and synchronous_commit turned off. Fixes the earlier concept note that credited Infinispan with cross-node propagation. Co-Authored-By: Claude Opus 5 --- .../scripts/experiment-session-read-path.sh | 108 +++++++++++ .../session-replication/04-read-path-sql.txt | 56 ++++++ docs/evidence/session-replication/README.md | 9 + docs/experiment-00-session-replication.md | 174 ++++++++++++++++-- docs/session-lab-concepts.md | 35 +++- 5 files changed, 359 insertions(+), 23 deletions(-) create mode 100755 deploy/lab/scripts/experiment-session-read-path.sh create mode 100644 docs/evidence/session-replication/04-read-path-sql.txt diff --git a/deploy/lab/scripts/experiment-session-read-path.sh b/deploy/lab/scripts/experiment-session-read-path.sh new file mode 100755 index 0000000..d44d71c --- /dev/null +++ b/deploy/lab/scripts/experiment-session-read-path.sh @@ -0,0 +1,108 @@ +#!/usr/bin/env bash +# Experiment 0d — capture the actual SQL that the OTHER node runs. +# +# Experiments 0b/0c showed that session entries never appear in keycloak-1's +# memory, yet keycloak-1 can use a session keycloak-0 created. The conclusion +# "keycloak-1 reads it from PostgreSQL" was an inference, not an observation. +# +# This script turns on statement logging in PostgreSQL for a few seconds, sends +# ONE refresh request to keycloak-1 for a session born on keycloak-0, and greps +# the database log for that session id. If the inference is right, the SQL is +# there, issued from keycloak-1's pod IP. +# +# It also checks whether serving that request makes keycloak-1 cache the session +# — which sharpens "each node caches what it handled" from "what it logged in" +# to "what it touched". +set -uo pipefail + +NS="${NS:-keycloak-lab}" +PSQL="kubectl -n $NS exec deploy/postgres -- psql -U keycloak -d keycloak -tAc" + +K0_IP=$(kubectl -n "$NS" get pod keycloak-0 -o jsonpath='{.status.podIP}') +K1_IP=$(kubectl -n "$NS" get pod keycloak-1 -o jsonpath='{.status.podIP}') +ADMIN_PW=$(kubectl -n "$NS" get secret keycloak-lab-secrets \ + -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d) + +echo "수집 시각: $(date '+%Y-%m-%d %H:%M:%S %Z')" +echo " keycloak-0 = $K0_IP (세션을 만드는 노드)" +echo " keycloak-1 = $K1_IP (읽기만 하는 노드)" +echo + +# %h 를 넣어야 어느 파드가 보낸 질의인지 로그에서 구분된다. +echo "=== PostgreSQL 문장 로깅을 켠다 ===" +$PSQL "alter system set log_statement='all'" >/dev/null 2>&1 +$PSQL "alter system set log_line_prefix='%m [%p] %h '" >/dev/null 2>&1 +$PSQL "select pg_reload_conf()" >/dev/null 2>&1 +echo " log_statement = $($PSQL 'show log_statement' 2>/dev/null)" +echo " log_line_prefix = $($PSQL 'show log_line_prefix' 2>/dev/null)" +echo + +# 로그 커서를 잡아둔다. 이 줄 수 이후만 본다. +LOG_BEFORE=$(kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null | wc -l) + +RESULT=$(kubectl -n "$NS" run kc-readpath --rm -i --restart=Never \ + --image=curlimages/curl:8.11.1 --quiet --command -- sh -c " +O=/tmp/o; : > \$O +TOKEN_EP='/realms/master/protocol/openid-connect/token' +jget() { sed -n \"s/.*\\\"\$1\\\":\\\"\\([^\\\"]*\\)\\\".*/\\1/p\"; } +ent() { + curl -s --retry 3 --max-time 20 http://\$1:9000/metrics \ + | grep -E '^vendor_statistics_approximate_entries_unique.cache=.sessions' | awk '{print \$NF}' +} +# keycloak-0 에서 로그인한다 +L=\$(curl -s -X POST \"http://$K0_IP:8080\$TOKEN_EP\" -d grant_type=password \ + -d client_id=admin-cli -d username=admin -d 'password=$ADMIN_PW') +SID=\$(echo \"\$L\" | jget access_token | cut -d. -f2 | sed 's/\$/==/' | base64 -d 2>/dev/null | jget sid) +RT=\$(echo \"\$L\" | jget refresh_token) +echo \"SID=\$SID\" >> \$O +echo \"K1_ENTRIES_BEFORE=\$(ent $K1_IP)\" >> \$O +sleep 2 +# 반대편 노드에 refresh 를 딱 한 번 보낸다 +# 인용을 한 겹 더 쌓으면 curl 이 URL 을 통째로 못 읽는다. 실제로 000 이 나왔다. +CODE=\$(curl -s -o /dev/null -w '%{http_code}' -X POST \ + \"http://$K1_IP:8080\$TOKEN_EP\" \ + -d grant_type=refresh_token -d client_id=admin-cli -d \"refresh_token=\$RT\") +echo \"REFRESH_ON_K1=\$CODE\" >> \$O +sleep 3 +echo \"K1_ENTRIES_AFTER=\$(ent $K1_IP)\" >> \$O +cat \$O +" 2>&1 | grep -v '^pod .* deleted$') + +echo "=== 요청 ===" +echo "$RESULT" | sed 's/^/ /' +SID=$(echo "$RESULT" | sed -n 's/^SID=//p') + +echo +echo "=== PostgreSQL 문장 로깅을 끈다 ===" +$PSQL "alter system reset log_statement" >/dev/null 2>&1 +$PSQL "alter system reset log_line_prefix" >/dev/null 2>&1 +$PSQL "select pg_reload_conf()" >/dev/null 2>&1 +echo " log_statement = $($PSQL 'show log_statement' 2>/dev/null)" + +echo +echo "=== keycloak-1 이 실제로 보낸 SQL 문장 ===" +echo " (파라미터가 \$1 로 묶여 있어, sid 는 바로 아래 DETAIL 줄에 있다)" +echo +kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \ + | tail -n +$((LOG_BEFORE + 1)) \ + | grep -F "$K1_IP" | grep -E "LOG: execute" \ + | sed 's/.*execute [^:]*: //' | sed 's/^/ /' | head -12 +echo +echo "=== 그 sid 를 언급한 SQL — 누가 보냈는가 ===" +echo " 찾는 sid: $SID" +echo +kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \ + | tail -n +$((LOG_BEFORE + 1)) \ + | grep -F "$SID" \ + | sed -e "s/$K0_IP/[keycloak-0]/g" -e "s/$K1_IP/[keycloak-1]/g" \ + | cut -c1-220 \ + | head -20 + +echo +echo "=== 요약: 파드별 질의 건수 ===" +kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \ + | tail -n +$((LOG_BEFORE + 1)) \ + | grep -F "$SID" \ + | grep -oE "^[0-9-]+ [0-9:.]+ [A-Z]+ \[[0-9]+\] [0-9.]+" \ + | awk '{print $NF}' | sort | uniq -c \ + | sed -e "s/$K0_IP/[keycloak-0]/" -e "s/$K1_IP/[keycloak-1]/" -e 's/^/ /' diff --git a/docs/evidence/session-replication/04-read-path-sql.txt b/docs/evidence/session-replication/04-read-path-sql.txt new file mode 100644 index 0000000..69c000d --- /dev/null +++ b/docs/evidence/session-replication/04-read-path-sql.txt @@ -0,0 +1,56 @@ +=================================================================== + 실험 0d — 반대편 노드가 정말 DB 에서 읽는가 (SQL 을 직접 잡는다) +=================================================================== + +수집 시각: 2026-09-04 10:14:17 KST + keycloak-0 = 10.42.1.43 (세션을 만드는 노드) + keycloak-1 = 10.42.0.35 (읽기만 하는 노드) + +=== PostgreSQL 문장 로깅을 켠다 === + log_statement = all + log_line_prefix = %m [%p] %h + +=== 요청 === + SID=jSt9GEPVQLJsO-1CeJjVgltg + K1_ENTRIES_BEFORE=5.0 + REFRESH_ON_K1=200 + K1_ENTRIES_AFTER=5.0 + +=== PostgreSQL 문장 로깅을 끈다 === + log_statement = none + +=== keycloak-1 이 실제로 보낸 SQL 문장 === + (파라미터가 $1 로 묶여 있어, sid 는 바로 아래 DETAIL 줄에 있다) + + select puse1_0.OFFLINE_FLAG,puse1_0.USER_SESSION_ID,puse1_0.BROKER_SESSION_ID,puse1_0.CREATED_ON,puse1_0.DATA,puse1_0.LAST_SESSION_REFRESH,puse1_0.REALM_ID,puse1_0.REMEMBER_ME,puse1_0.USER_ID,puse1_0.VERSION from OFFLINE_USER_SESSION puse1_0 where (puse1_0.OFFLINE_FLAG,puse1_0.USER_SESSION_ID) in (($1,$2)) + select puse1_0.VERSION from OFFLINE_USER_SESSION puse1_0 where puse1_0.USER_SESSION_ID=$1 and puse1_0.OFFLINE_FLAG=$2 for no key update of puse1_0 skip locked + select pcse1_0.CLIENT_ID,pcse1_0.CLIENT_STORAGE_PROVIDER,pcse1_0.EXTERNAL_CLIENT_ID,pcse1_0.OFFLINE_FLAG,pcse1_0.USER_SESSION_ID,pcse1_0.DATA,pcse1_0.REALM_ID,pcse1_0.TIMESTAMP,pcse1_0.VERSION from OFFLINE_CLIENT_SESSION pcse1_0 where (pcse1_0.CLIENT_ID,pcse1_0.CLIENT_STORAGE_PROVIDER,pcse1_0.EXTERNAL_CLIENT_ID,pcse1_0.OFFLINE_FLAG,pcse1_0.USER_SESSION_ID) in (($1,$2,$3,$4,$5)) + select pcse1_0.VERSION from OFFLINE_CLIENT_SESSION pcse1_0 where pcse1_0.USER_SESSION_ID=$1 and pcse1_0.OFFLINE_FLAG=$2 and pcse1_0.CLIENT_ID=$3 and pcse1_0.EXTERNAL_CLIENT_ID=$4 and pcse1_0.CLIENT_STORAGE_PROVIDER=$5 for no key update of pcse1_0 skip locked + update OFFLINE_CLIENT_SESSION set TIMESTAMP=$1,VERSION=$2 where CLIENT_ID=$3 and CLIENT_STORAGE_PROVIDER=$4 and EXTERNAL_CLIENT_ID=$5 and OFFLINE_FLAG=$6 and USER_SESSION_ID=$7 and VERSION=$8 + update OFFLINE_USER_SESSION set LAST_SESSION_REFRESH=$1,VERSION=$2 where OFFLINE_FLAG=$3 and USER_SESSION_ID=$4 and VERSION=$5 + SET LOCAL synchronous_commit TO OFF + COMMIT + DELETE from JGROUPS_PING WHERE address=$1 + INSERT INTO JGROUPS_PING (address, name, cluster_name, ip, coord, last_update, coordinated_by) values ($1, $2, $3, $4, $5, $6, $7) + COMMIT + DELETE from JGROUPS_PING WHERE address=$1 + +=== 그 sid 를 언급한 SQL — 누가 보냈는가 === + 찾는 sid: jSt9GEPVQLJsO-1CeJjVgltg + +2026-09-04 01:12:32.851 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '0', $2 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:32.852 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '131a9912-b578-4b9c-b16a-97518704077e', $2 = 'local', $3 = 'local', $4 = '0', $5 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:32.860 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '0', $2 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:32.862 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '131a9912-b578-4b9c-b16a-97518704077e', $2 = 'local', $3 = 'local', $4 = '0', $5 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:32.863 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = NULL, $2 = '1788484352', $3 = '{"ipAddress":"10.42.1.50","authMethod":"openid-connect","rememberMe":false,"started":0,"notes":{"KC_DEVICE_NOTE":" +2026-09-04 01:12:32.864 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '{"authMethod":"openid-connect","notes":{"clientId":"131a9912-b578-4b9c-b16a-97518704077e","userSessionStartedAt":"1788484352","iss":"https://aut +2026-09-04 01:12:34.934 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '0', $2 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:34.936 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = 'jSt9GEPVQLJsO-1CeJjVgltg', $2 = '0' +2026-09-04 01:12:34.937 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '131a9912-b578-4b9c-b16a-97518704077e', $2 = 'local', $3 = 'local', $4 = '0', $5 = 'jSt9GEPVQLJsO-1CeJjVgltg' +2026-09-04 01:12:34.938 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = 'jSt9GEPVQLJsO-1CeJjVgltg', $2 = '0', $3 = '131a9912-b578-4b9c-b16a-97518704077e', $4 = 'local', $5 = 'local' +2026-09-04 01:12:34.944 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '1788484354', $2 = '1', $3 = '131a9912-b578-4b9c-b16a-97518704077e', $4 = 'local', $5 = 'local', $6 = '0', $7 = 'jSt9GEPVQLJsO-1CeJjVgltg', $8 = +2026-09-04 01:12:34.946 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '1788484354', $2 = '1', $3 = '0', $4 = 'jSt9GEPVQLJsO-1CeJjVgltg', $5 = '0' + +=== 요약: 파드별 질의 건수 === + 6 [keycloak-1] + 6 [keycloak-0] diff --git a/docs/evidence/session-replication/README.md b/docs/evidence/session-replication/README.md index da6e7f6..fbe46c6 100644 --- a/docs/evidence/session-replication/README.md +++ b/docs/evidence/session-replication/README.md @@ -15,3 +15,12 @@ 클러스터는 형성되지만 **세션 엔트리는 노드를 건너가지 않는다.** 두 노드가 같은 답을 하는 이유는 Infinispan 복제가 아니라 **같은 PostgreSQL** 이다. + +| 파일 | 무엇을 보여주는가 | +|---|---| +| `04-read-path-sql.txt` | PostgreSQL 문장 로깅으로 잡은 **keycloak-1 이 실제로 날린 SQL**. `SELECT ... FROM OFFLINE_USER_SESSION` 로 남의 세션을 읽고 `UPDATE ... where VERSION=$5` 로 쓴다. 같은 트랜잭션에 `SET LOCAL synchronous_commit TO OFF` 가 들어 있다 | + +## 추론이 관측이 된 지점 + +0b·0c 는 "keycloak-1 메모리에 없는데 쓸 수 있으니 DB 에서 읽었을 것"이라는 +**추론**이었다. 0d 에서 그 SQL 을 파드 IP 와 함께 직접 잡았다. diff --git a/docs/experiment-00-session-replication.md b/docs/experiment-00-session-replication.md index 634b3da..dc7502c 100644 --- a/docs/experiment-00-session-replication.md +++ b/docs/experiment-00-session-replication.md @@ -4,7 +4,8 @@ - 실행 스크립트 — [`deploy/lab/scripts/experiment-session-replication.sh`](../deploy/lab/scripts/experiment-session-replication.sh), [`experiment-cache-replication-delta.sh`](../deploy/lab/scripts/experiment-cache-replication-delta.sh), - [`experiment-cache-ownership.sh`](../deploy/lab/scripts/experiment-cache-ownership.sh) + [`experiment-cache-ownership.sh`](../deploy/lab/scripts/experiment-cache-ownership.sh), + [`experiment-session-read-path.sh`](../deploy/lab/scripts/experiment-session-read-path.sh) - 증거 — [`docs/evidence/session-replication/`](evidence/session-replication/) - 수집 시각 — 2026-09-04 09:54 KST, Keycloak 26 / Infinispan 16.0.12 / PostgreSQL 16 @@ -17,7 +18,7 @@ | 한 노드에서 만든 세션을 다른 노드가 쓸 수 있는가 | **그렇다** | | 로그아웃이 반대 방향으로 전파되는가 | **그렇다** | | **그 공유는 Infinispan 복제 덕분인가** | **아니다** | -| 그럼 무엇이 공유하는가 | **PostgreSQL** | +| 그럼 무엇이 공유하는가 | **PostgreSQL** — 반대편 노드가 날린 SQL을 직접 잡았다 | **클러스터가 형성됐다는 것과 세션이 복제된다는 것은 다른 얘기였다.** 로그에는 `(2) [keycloak-0, keycloak-1]`이 찍히고 `JGROUPS_PING`에도 둘 다 @@ -251,7 +252,146 @@ keycloak-0 에 로그인 5회 7.0 5.0 ← k0 만 +5, k --- -## 6. 그래서 무엇이 세션을 공유하는가 +## 6. 실험 0d — 반대편 노드가 정말 DB에서 읽는가 + +0b·0c까지는 **추론**이었다. "keycloak-1의 메모리에 없는데 쓸 수 있으니 DB에서 +읽었을 것이다" — 그럴듯하지만 **SQL을 본 적은 없다.** + +PostgreSQL의 문장 로깅을 몇 초만 켜고, keycloak-0에서 만든 세션에 대해 +**keycloak-1에 refresh를 딱 한 번** 보낸 뒤 로그를 뒤졌다. + +```bash +alter system set log_statement='all'; +alter system set log_line_prefix='%m [%p] %h '; -- %h 로 파드 IP 를 남긴다 +select pg_reload_conf(); +``` + +### 잡힌 트랜잭션 — [`04-read-path-sql.txt`](evidence/session-replication/04-read-path-sql.txt) + +``` +01:12:34.934 pid=81376 | BEGIN +01:12:34.934 pid=81376 | select ... from OFFLINE_USER_SESSION where (OFFLINE_FLAG,USER_SESSION_ID) in (($1,$2)) +01:12:34.936 pid=81376 | select VERSION from OFFLINE_USER_SESSION ... for no key update skip locked +01:12:34.937 pid=81376 | select ... from OFFLINE_CLIENT_SESSION where (...) in ((...)) +01:12:34.938 pid=81376 | select VERSION from OFFLINE_CLIENT_SESSION ... for no key update skip locked +01:12:34.944 pid=81376 | update OFFLINE_CLIENT_SESSION set TIMESTAMP=$1,VERSION=$2 where ... and VERSION=$8 +01:12:34.946 pid=81376 | update OFFLINE_USER_SESSION set LAST_SESSION_REFRESH=$1,VERSION=$2 where ... and VERSION=$5 +01:12:34.946 pid=81376 | SET LOCAL synchronous_commit TO OFF +01:12:34.947 pid=81376 | COMMIT +``` + +이 연결의 클라이언트 IP는 `10.42.0.35` — **keycloak-1의 파드 IP**다. +sid 하나에 대해 keycloak-0이 6건(로그인), keycloak-1이 6건(갱신)을 날렸다. + +``` +=== 요약: 파드별 질의 건수 === + 6 [keycloak-1] + 6 [keycloak-0] +``` + +**추론이 관측이 되었다.** keycloak-1은 세션을 DB에서 읽고, DB에 쓴다. + +### 여기서 딸려 나온 것 세 가지 + +이 13밀리초짜리 트랜잭션 하나에 **원래 질문들의 답이 절반쯤 들어 있다.** + +#### (1) 낙관적 락 — `VERSION` 컬럼 + +```sql +update OFFLINE_USER_SESSION + set LAST_SESSION_REFRESH=$1, VERSION=$2 + where OFFLINE_FLAG=$3 and USER_SESSION_ID=$4 and VERSION=$5 + ───────────── + 읽을 때의 버전과 같을 때만 쓴다 +``` + +읽은 뒤 다른 노드가 먼저 고쳤다면 `VERSION`이 달라져 **`UPDATE`가 0행을 +갱신하고 실패한다.** 잠금을 오래 잡지 않고 충돌을 사후에 검출하는 방식이다. + +**리프레시 토큰 동시 갱신 경쟁(로드맵 B-5)이 여기서 갈린다.** 두 요청이 +같은 세션을 동시에 갱신하면 하나는 이 검사에서 진다. + +#### (2) `FOR NO KEY UPDATE ... SKIP LOCKED` + +```sql +select VERSION from OFFLINE_USER_SESSION + where USER_SESSION_ID=$1 and OFFLINE_FLAG=$2 + for no key update of puse1_0 skip locked + ────────────── ──────────── + 키가 아닌 컬럼만 잠근다 잠긴 행은 건너뛴다 (기다리지 않는다) +``` + +| 절 | 뜻 | +|---|---| +| `FOR NO KEY UPDATE` | 행을 잠그되 **외래키 참조는 막지 않는다.** `FOR UPDATE`보다 약해 경합이 준다 | +| **`SKIP LOCKED`** | 이미 잠긴 행을 **기다리지 않고 건너뛴다** | + +`SKIP LOCKED`가 핵심이다. 같은 세션에 동시 요청이 몰려도 **줄을 서지 않는다.** +대기 대신 낙관적 락 실패로 처리한다 — 처리량을 위해 **지연 대신 재시도**를 +고른 설계다. + +#### (3) `SET LOCAL synchronous_commit TO OFF` — 내구성을 일부 포기한다 + +**같은 트랜잭션 안에서**, `COMMIT` 직전에 나온다. pid로 경계를 확인했다. + +| | | +|---|---| +| 기본값 `on` | `COMMIT`이 **WAL이 디스크에 내려간 뒤** 돌아온다 | +| **`off`** | **WAL 플러시를 기다리지 않고** 즉시 돌아온다 | + +**결과: PostgreSQL이 갑자기 죽으면 직전 수백 밀리초의 세션 갱신이 사라질 수 +있다.** 커밋했다고 응답해놓고 없어진다. + +Keycloak이 이걸 의도적으로 켠 이유는 명확하다 — `LAST_SESSION_REFRESH` 갱신은 +**초당 수백 번 일어나고, 몇백 밀리초쯤 잃어도 사용자가 다시 갱신하면 그만**이다. +로그인·로그아웃 같은 것과 달리 잃어도 되는 쓰기다. + +> **DB 복구 실험(A-2)에서 그대로 관측될 지점이다.** PostgreSQL을 정상 종료가 +> 아니라 강제 종료시키면, 마지막 몇백 밀리초의 세션 갱신이 실제로 없어져야 +> 한다. 이건 버그가 아니라 **설계된 트레이드오프**다. + +```bash +kubectl -n keycloak-lab exec deploy/postgres -- \ + psql -U keycloak -d keycloak -c "show synchronous_commit" # 전역 기본값은 on +``` + +전역 설정은 `on`이고, **Keycloak이 세션 트랜잭션에만 `SET LOCAL`로 끈다.** +`SET LOCAL`은 그 트랜잭션이 끝나면 되돌아간다. + +### 덤: 캐시는 읽어도 채워지지 않는다 + +``` +K1_ENTRIES_BEFORE=5.0 +REFRESH_ON_K1=200 +K1_ENTRIES_AFTER=5.0 ← 갱신을 처리하고도 그대로 +``` + +**keycloak-1은 남의 세션을 DB에서 읽어 처리하고도 캐시에 담지 않았다.** + +0c에서 세운 모델 "각 노드는 자기가 처리한 것만 캐시한다"를 더 좁혀야 한다. + +> 캐시에 담기는 것은 **그 노드가 로그인시켜 만든 세션**뿐이다. +> 남의 세션은 매번 DB에서 읽는다. + +로드밸런서가 세션을 만든 노드가 아닌 쪽으로 요청을 보내면 **매번 DB를 친다.** +세션 어피니티(sticky session)가 정확성이 아니라 **성능** 문제인 이유가 이것이다. + +### 덤 2: jdbc-ping 하트비트가 그대로 보인다 + +``` +01:12:37.551 pid=81369 | BEGIN +01:12:37.551 pid=81369 | DELETE from JGROUPS_PING WHERE address=$1 +01:12:37.552 pid=81369 | INSERT INTO JGROUPS_PING (address, name, cluster_name, ip, coord, last_update, coordinated_by) values (...) +01:12:37.553 pid=81369 | COMMIT +``` + +**디스커버리는 별도 연결(pid=81369)에서 주기적으로 자기 행을 지우고 다시 +넣는다.** 세션 트래픽과 완전히 분리된 경로다 — 11층에서 말한 "디스커버리와 +트랜스포트는 다른 경로"가 로그에서 눈으로 확인된다. + +--- + +## 7. 그래서 무엇이 세션을 공유하는가 ``` 로그인 (keycloak-0) @@ -277,9 +417,9 @@ DB가 진실의 원천이 됐고, 세션 캐시는 **복제할 이유가 없어 --- -## 7. 개념 +## 8. 개념 -### 7-1. `persistent-user-sessions` +### 8-1. `persistent-user-sessions` Keycloak 25에서 도입되고 **26에서 기본값**이 된 기능. 사용자 세션을 Infinispan에만 두지 않고 **데이터베이스에 기록**한다. @@ -299,7 +439,7 @@ kubectl -n keycloak-lab exec keycloak-0 -- \ /opt/keycloak/bin/kc.sh show-config 2>/dev/null | grep -i feature ``` -### 7-2. 온라인 세션이 `OFFLINE_` 테이블에 들어간다 +### 8-2. 온라인 세션이 `OFFLINE_` 테이블에 들어간다 **`USER_SESSION` 테이블은 존재하지 않는다.** 처음에 이걸 찾다가 없어서 당황했다. @@ -332,7 +472,7 @@ select user_session_id, offline_flag, created_on, last_session_refresh **이름이 내용을 배신하는 스키마다.** 운영에서 "온라인 세션이 DB 어디 있냐"를 찾을 때 이걸 모르면 한참 헤맨다. -### 7-3. `sid` — 토큰과 DB를 잇는 열쇠 +### 8-3. `sid` — 토큰과 DB를 잇는 열쇠 ``` JWT access_token 의 sid jiv3rVZi1VeaO07oVJkL_MYW @@ -345,7 +485,7 @@ Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW 세 곳에서 같은 문자열이다. **장애를 추적할 때 이 값 하나로 토큰·DB·관리 API를 꿰뚫을 수 있다.** 백채널 로그아웃의 `sid` 클레임도 이것이다. -### 7-4. `openid` scope가 없으면 OIDC 토큰이 아니다 +### 8-4. `openid` scope가 없으면 OIDC 토큰이 아니다 `admin-cli`에 `scope` 없이 direct grant를 하면 나오는 클레임은 이렇다. @@ -361,7 +501,7 @@ Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW 같은 이유로 `userinfo`가 403 `insufficient_scope`를 준다 — userinfo는 OIDC 엔드포인트다. **두 현상은 하나의 원인**이다. -### 7-5. 룩어사이드(lookaside) 캐시 +### 8-5. 룩어사이드(lookaside) 캐시 ``` 읽기: 캐시 확인 → 없으면 DB → 캐시에 채움 @@ -376,7 +516,7 @@ Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW --- -## 8. 다음 실험에 대한 예측 +## 9. 다음 실험에 대한 예측 기준선이 생겼으므로 **틀릴 수 있는 예측**을 세울 수 있다. 예측이 빗나가면 그것이야말로 배울 거리다. @@ -385,6 +525,8 @@ Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW |---|---|---| | **A-1** TCP 7800 차단 | **세션 공유는 안 깨진다.** 대신 무효화 전파와 `work` 캐시가 깨진다 | 세션은 7800으로 오가지 않는다 | | **A-2** DB 손실 | **즉시 전면 장애.** 캐시에 있는 세션도 못 쓴다 | DB가 진실의 원천 | +| **A-2'** DB **강제** 종료 | 직전 수백 ms 의 세션 갱신이 **사라진다** | `synchronous_commit OFF` | +| **B-5** 동시 갱신 경쟁 | 한쪽이 `VERSION` 검사에서 지고 재시도한다 | 낙관적 락 | | **A-3** 노드 상실 (kc-lab-2) | **세션은 살아남는다.** 죽은 노드의 캐시만 사라진다 | 룩어사이드 | | **A-4** volatile 비교 | 7800 차단이 **A-1과 정반대로** 치명적이 된다 | 그때는 캐시가 진실의 원천 | @@ -393,9 +535,9 @@ Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW --- -## 9. 겪은 함정 +## 10. 겪은 함정 -### 9-1. kubectl 스트림에서 출력이 통째로 사라졌다 +### 10-1. kubectl 스트림에서 출력이 통째로 사라졌다 `kubectl run --rm -i ... | grep` 로 받으면 **중간 조각이 유실됐다.** keycloak-1의 스냅샷과 그 다음 마커가 함께 없어져, 전값이 0으로 잡히면서 @@ -423,7 +565,7 @@ for n in ('BEFORE_K0','BEFORE_K1','AFTER_K0','AFTER_K1'): **계측 코드는 자기가 실패했는지 스스로 말해야 한다.** -### 9-2. DB에서 직접 지우면 캐시는 남는다 +### 10-2. DB에서 직접 지우면 캐시는 남는다 정리하려고 `delete from offline_user_session`을 실행했더니, **캐시 엔트리는 그대로 남아** 캐시 합계(19)와 DB 총계(15)가 어긋났다. @@ -433,13 +575,13 @@ for n in ('BEFORE_K0','BEFORE_K1','AFTER_K0','AFTER_K1'): 이 실험의 최종 수치는 **파드 재시작 후** 다시 잰 것이다. -### 9-3. Keycloak 이미지에는 `curl`이 없다 +### 10-3. Keycloak 이미지에는 `curl`이 없다 `kubectl exec keycloak-0 -- curl` 은 실패한다. 임시 `curlimages/curl` 파드를 띄워 파드 네트워크 안에서 호출했다. 파드 IP는 클러스터 밖에서 닿지 않으므로 이 방법이 사실상 유일하다. -### 9-4. 중첩 셸의 변수 치환 +### 10-4. 중첩 셸의 변수 치환 `ssh host '... $VAR ...'` 안에 다시 `sh -c "..."` 를 넣으면 인용이 세 겹이 되어 치환이 조용히 깨진다. 첫 시도에서 파드 IP가 빈 문자열이 되어 아무 출력도 @@ -450,7 +592,7 @@ for n in ('BEFORE_K0','BEFORE_K1','AFTER_K0','AFTER_K1'): --- -## 10. 재현 +## 11. 재현 ```bash # 1. 깨끗한 상태로 되돌린다 (DB 비우고 캐시 비우기) diff --git a/docs/session-lab-concepts.md b/docs/session-lab-concepts.md index 3cf98e6..f38b24c 100644 --- a/docs/session-lab-concepts.md +++ b/docs/session-lab-concepts.md @@ -3141,18 +3141,39 @@ kubectl -n keycloak-lab logs keycloak-0 | grep -E 'ISPN000094|ISPN000079|ISPN100 suspect 하고, GMS가 그 멤버를 뷰에서 제외한다. 각자 자기만 있는 뷰가 되면 **split brain**이고, 통신이 복구되면 MERGE3가 합친다. -### 세션은 어디에 있는가 — 두 곳 다 +### 세션은 어디에 있는가 — 두 곳이되 역할이 다르다 Keycloak 26의 기본값 `persistent-user-sessions`에서는 -| 저장소 | 역할 | -|---|---| -| **PostgreSQL** | **진실의 원천.** 재시작에도 살아남는다 | -| **Infinispan** | 캐시 + 노드 간 실시간 전파 | +| 저장소 | 역할 | 노드 간 공유 | +|---|---|---| +| **PostgreSQL** | **진실의 원천.** 재시작에도 살아남는다 | **여기서만 일어난다** | +| **Infinispan `sessions`** | **자기 노드가 로그인시킨 세션만** 담는 룩어사이드 캐시 | **일어나지 않는다** | + +> **처음에 이 표에 "Infinispan = 캐시 + 노드 간 실시간 전파"라고 썼는데 +> 틀렸다.** 실험 0에서 측정해보니 세션 엔트리는 노드 사이를 건너가지 않는다. +> 두 노드가 같은 답을 하는 이유는 복제가 아니라 같은 DB를 보기 때문이고, +> 반대편 노드가 실제로 날리는 `SELECT ... FROM OFFLINE_USER_SESSION` 을 +> PostgreSQL 로그에서 직접 잡았다. +> → [`docs/experiment-00-session-replication.md`](experiment-00-session-replication.md) `--features-disabled=persistent-user-sessions`로 끄면 Infinispan만 남는 -**volatile** 모드가 되고, 그때는 캐시가 곧 진실의 원천이다. -이 둘의 차이가 로드맵 2번의 주제다. +**volatile** 모드가 되고, 그때는 캐시가 곧 진실의 원천이므로 **복제가 +반드시 일어나야 한다.** 이 둘의 차이가 로드맵 2번의 주제다. + +### 세션 쓰기 트랜잭션의 세 가지 설계 결정 + +PostgreSQL 문장 로깅으로 잡은 갱신 트랜잭션 하나에 다 들어 있다. + +| 보이는 것 | 뜻 | +|---|---| +| `update ... where ... and VERSION=$5` | **낙관적 락.** 읽을 때의 버전과 같을 때만 쓴다 | +| `for no key update ... skip locked` | 잠긴 행을 **기다리지 않고 건너뛴다.** 대기 대신 재시도 | +| **`SET LOCAL synchronous_commit TO OFF`** | **WAL 플러시를 기다리지 않고 커밋한다** | + +마지막 것이 특히 중요하다 — **DB가 강제 종료되면 직전 수백 밀리초의 세션 +갱신이 사라질 수 있다.** 버그가 아니라 의도된 트레이드오프다. +`LAST_SESSION_REFRESH` 갱신은 매우 잦고, 잃어도 사용자가 다시 갱신하면 된다. ---