DongHyeonkaandClaude Opus 5
a2f749292a
Each of A-7a, B-7a and D-4a had the concepts, procedure, commands and
terminal evidence but no diagram, which the rest of the series carries.
a7a-cache-temperature.svg the three cache states and the SQL each issues
b7a-orphan-lifecycle.svg ticket structure, accumulation across two
rotations, and why TTL is the only signal
d4a-hook-timeline.svg the 38m25s gap against the 1-2s one, on one axis
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
293 lines
12 KiB
Markdown
293 lines
12 KiB
Markdown
# A-7a — volatile 에서 refresh 가 500 인 진짜 이유
|
||
|
||
브랜치 `feature/keycloak-a7a-volatile-cause` ·
|
||
증거 [`docs/evidence/a7a-volatile-cause/`](evidence/a7a-volatile-cause/) ·
|
||
2026-09-04 20:18–20:24 KST
|
||
|
||
A-7 이 **가설로 남긴 것**을 확정하는 실험이다. 확정해 보니 가설이 틀렸고,
|
||
더 중요하게는 **A-7 의 표 자체가 조건부였다**는 것이 드러났다.
|
||
|
||
---
|
||
|
||
## 구조
|
||
|
||
|
||
|
||
> 다이어그램 규약은 [`diagrams/_style.md`](diagrams/_style.md).
|
||
|
||
---
|
||
|
||
## 0. 결론부터
|
||
|
||
| 확인 | 결과 |
|
||
|---|---|
|
||
| A-7 의 가설 (`REVOKED_TOKEN`) | **틀렸다.** 로그에 한 번도 나오지 않는다 |
|
||
| **진짜 원인** | **`CLIENT_SCOPE_CLIENT` 조회** — 선택적 클라이언트 스코프 |
|
||
| 로그인이 쏘는 SQL | **0개** |
|
||
| refresh 가 쏘는 SQL | **1개, 그리고 첫 번째만.** 이후 캐시된다 |
|
||
| **★ A-7 의 표** | **캐시 온도에 따라 400/500/200 으로 갈린다.** 셋 다 재현했다 |
|
||
|
||
---
|
||
|
||
## 1. A-7 이 무엇을 남겼나
|
||
|
||
> **측정은 확실하지만 원인은 확정하지 못했다.** 유력한 후보는
|
||
> `REVOKED_TOKEN` 테이블이다 — refresh token 회전에서 **이미 쓴 토큰인지**
|
||
> 확인하려면 그 테이블을 봐야 하고, 그 경로는 캐시되지 않는다.
|
||
> **확정하려면 A-3 에서 쓴 문장 로깅을 켜고 다시 재현해야 한다.**
|
||
|
||
그 지시대로 했다.
|
||
|
||
### 개념 — PostgreSQL 문장 로깅
|
||
|
||
**무엇인가.** `log_statement = 'all'` 을 켜면 서버가 받은 모든 SQL 을 로그에
|
||
찍는다. 애플리케이션을 고치지 않고 **"이 요청이 DB 를 어떻게 쓰는지"** 를
|
||
밖에서 볼 수 있다.
|
||
|
||
**왜 여기 나오나.** "refresh 가 어느 테이블 때문에 실패하는가"는 추측으로
|
||
답할 문제가 아니다. Keycloak 내부를 읽는 대신 **DB 가 실제로 받은 문장**을
|
||
보면 된다. A-3 에서 RPO 를 잴 때 쓴 것과 같은 기법이다.
|
||
|
||
**없거나 틀리면.** 여기서 정확히 A-7 이 겪은 일이 벌어진다 — 그럴듯한
|
||
테이블 이름을 골라 가설로 적게 되고, 그게 틀려도 아무도 모른다.
|
||
|
||
**확인.**
|
||
```bash
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-c "ALTER SYSTEM SET log_statement = 'all';" -c "SELECT pg_reload_conf();"
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-tAc "show log_statement" # all 이면 켜졌다
|
||
```
|
||
|
||
### 표식으로 구간을 나눈다
|
||
|
||
로그는 JGroups 의 `JGROUPS_PING` 폴링으로 계속 채워진다. 어느 문장이
|
||
로그인이고 어느 것이 refresh 인지 가르려면 **경계를 찍어야 한다.**
|
||
|
||
```bash
|
||
psql -tAc "select 'MARK_LOGIN_START'" # 이 문장 자체가 로그에 남는다
|
||
```
|
||
|
||
---
|
||
|
||
## 2. 측정 — 로그인은 DB 를 안 본다
|
||
|
||
```
|
||
11:18:49.461 statement: select 'MARK_LOGIN_START'
|
||
11:18:49.743 statement: select 'MARK_LOGIN_END'
|
||
↑ 사이에 아무것도 없다
|
||
```
|
||
|
||
realm·사용자·클라이언트가 전부 Infinispan 캐시에 있고, volatile 이라
|
||
세션 쓰기도 없다. **DB 없이 완결된다** — A-7 이 적은 그대로다.
|
||
|
||
## 3. ★ refresh 는 한 문장을 쏜다 — 그리고 그게 아니다
|
||
|
||
```
|
||
11:18:52.009 statement: select 'MARK_REFRESH_START'
|
||
11:18:52.137 statement: BEGIN
|
||
11:18:52.137 execute <unnamed>/C_107:
|
||
select cscme1_0.SCOPE_ID from CLIENT_SCOPE_CLIENT cscme1_0
|
||
where cscme1_0.CLIENT_ID=$1 and cscme1_0.DEFAULT_SCOPE=$2
|
||
parameters: $1 = '131a9912-b578-4b9c-b16a-97518704077e', $2 = 'f'
|
||
11:18:52.148 execute S_2: COMMIT
|
||
11:18:52.253 statement: select 'MARK_REFRESH_END'
|
||
```
|
||
|
||
**`REVOKED_TOKEN` 은 한 번도 나오지 않는다.**
|
||
|
||
### 개념 — `DEFAULT_SCOPE='f'` 가 무슨 뜻인가
|
||
|
||
**무엇인가.** Keycloak 의 클라이언트는 스코프를 두 종류로 갖는다.
|
||
|
||
| | 뜻 | `DEFAULT_SCOPE` |
|
||
|---|---|---|
|
||
| default scope | 항상 붙는다 | `t` |
|
||
| **optional scope** | **요청이 `scope=` 로 달라고 해야 붙는다** | **`f`** |
|
||
|
||
**왜 여기 나오나.** refresh 는 새 access token 을 만든다. 그 토큰에 어떤
|
||
스코프를 담을지 정하려면 **"이 클라이언트가 요청 가능한 optional 스코프가
|
||
무엇인가"** 를 알아야 한다. 그 목록이 `CLIENT_SCOPE_CLIENT` 에 있다.
|
||
로그인 때는 이미 결정된 것을 쓰지만, refresh 는 다시 계산한다.
|
||
|
||
**없거나 틀리면.** 이 조회가 실패하면 토큰을 만들 수 없어 **500** 이다.
|
||
`400 Session not active` 와 달리 **세션 문제가 아니다** — 그래서 A-7 이
|
||
세션 계열 테이블(`REVOKED_TOKEN`)을 의심한 것이 자연스러웠지만 틀렸다.
|
||
|
||
## 4. 그 조회는 한 번뿐이다
|
||
|
||
연속 refresh 3회, 전부 200. 표식 사이 SQL:
|
||
|
||
```
|
||
statement: select 'MARK_R1'
|
||
statement: select 'MARK_R2'
|
||
statement: select 'MARK_R3'
|
||
statement: select 'MARK_R_END'
|
||
↑ SQL 0건
|
||
```
|
||
|
||
**첫 refresh 가 캐시를 채우고, 이후로는 DB 를 보지 않는다.**
|
||
여기서 A-7 의 표가 흔들리기 시작한다.
|
||
|
||
---
|
||
|
||
## 5. ★ 그래서 A-7 의 표는 조건부였다
|
||
|
||
같은 설정에서 **캐시 온도만으로 결과가 셋으로 갈린다.** 전부 재현했다.
|
||
|
||
| 캐시 상태 | 로그인 | refresh | 실패한 SQL |
|
||
|---|---|---|---|
|
||
| **완전 냉시동** (재시작 직후) | **400** | 400 | `select ce1_0.ID from CLIENT where CLIENT_ID=? and REALM_ID=?` |
|
||
| **CLIENT 만 더움** ← A-7 이 본 것 | 200 | **500** | `select cscme1_0.SCOPE_ID from CLIENT_SCOPE_CLIENT …` |
|
||
| **완전히 더움** | 200 | **200** | 없음 (SQL 0건) |
|
||
|
||
### 재현 A — 완전 냉시동이면 로그인부터 400
|
||
|
||
```
|
||
keycloak 재시작 → postgres 정지 → 로그인
|
||
400 {"error":"unauthorized_client",
|
||
"error_description":"Unexpected error when authenticating client"}
|
||
|
||
ERROR KC-SERVICES0015: Unexpected error when authenticating client:
|
||
JDBC exception executing SQL [FATAL: terminating connection …]
|
||
[select ce1_0.ID from CLIENT ce1_0 where ce1_0.CLIENT_ID=? and ce1_0.REALM_ID=?]
|
||
```
|
||
|
||
**A-7 은 "volatile 이면 DB 없이 로그인된다"고 적었다. 냉시동에서는 아니다.**
|
||
클라이언트 조회조차 캐시에 없기 때문이다.
|
||
|
||
### 재현 B — A-7 이 본 그 조건
|
||
|
||
```
|
||
keycloak 재시작 → (DB 살아있을 때) 로그인 1회 → postgres 정지 → refresh
|
||
로그인 200
|
||
refresh 500 {"error":"unknown_error"}
|
||
|
||
JDBC exception executing SQL [FATAL: terminating connection …]
|
||
[select cscme1_0.SCOPE_ID from CLIENT_SCOPE_CLIENT cscme1_0
|
||
where cscme1_0.CLIENT_ID=? and cscme1_0.DEFAULT_SCOPE=?]
|
||
```
|
||
|
||
**로그가 실패한 SQL 을 직접 지목한다.** 가설이 아니라 확정이다.
|
||
|
||
### 재현 C — 완전히 더우면 둘 다 200
|
||
|
||
```
|
||
refresh 3회로 캐시를 채운 뒤 postgres 정지
|
||
로그인 200
|
||
refresh 200 ← A-7 의 표와 정반대
|
||
```
|
||
|
||
---
|
||
|
||
## 6. 이 실험이 A층에 남기는 것
|
||
|
||
1. **원인 확정** — `REVOKED_TOKEN` 이 아니라 **선택적 클라이언트 스코프
|
||
조회**다. A-7 의 가설은 틀렸고, 이제 로그가 지목하는 문장이 있다.
|
||
|
||
2. **A-7 의 표에 조건을 붙여야 한다.** 「volatile + DB 정지 → 로그인 200,
|
||
refresh 500」은 **캐시가 반쯤 더울 때만** 참이다.
|
||
|
||
3. **일반화 — 이런 종류는 한 번 재고 표로 적으면 안 된다.**
|
||
volatile 에서 DB 정지 시의 동작은 "무엇을 하느냐"가 아니라
|
||
**"그 경로가 이미 캐시를 채웠느냐"** 로 결정된다. 그래서 같은 명령이
|
||
재시작 직후와 얼마 쓴 뒤에 다른 답을 낸다.
|
||
|
||
> 이것은 A-1 에서 conntrack 이 「주입했는데 안 걸렸다」를 만든 것과
|
||
> 같은 계열의 함정이다. 상태가 결과를 바꾸는데 그 상태가 안 보인다.
|
||
|
||
4. **persistent(기본값)에는 해당하지 않는다.** 세션 자체를 DB 에 쓰므로
|
||
DB 가 없으면 캐시 온도와 무관하게 실패한다. **이 조건부성은 volatile
|
||
고유의 성질**이고, 옛 방식이 "DB 의존이 적다"고 말할 때 놓치는 부분이다.
|
||
|
||
---
|
||
|
||
## 7. 재현 절차 (명령어)
|
||
|
||
```bash
|
||
# ── 1. 문장 로깅을 켠다
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-c "ALTER SYSTEM SET log_statement = 'all';" -c "SELECT pg_reload_conf();"
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-tAc "show log_statement" # all 이어야 한다
|
||
|
||
# ── 2. volatile 로 전환
|
||
kubectl -n keycloak-lab patch statefulset keycloak --type=json \
|
||
-p '[{"op":"replace","path":"/spec/template/spec/containers/0/args",
|
||
"value":["start","--features-disabled=persistent-user-sessions"]}]'
|
||
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=500s
|
||
|
||
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
|
||
PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
|
||
-o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)
|
||
TE=/realms/master/protocol/openid-connect/token
|
||
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
|
||
--restart=Never --command -- sleep 3600
|
||
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s
|
||
|
||
# ── 3. 표식을 넣어가며 로그인 → refresh
|
||
m() { kubectl -n keycloak-lab exec deploy/postgres -- \
|
||
psql -U keycloak -d keycloak -tAc "select 'MARK_$1'" >/dev/null; }
|
||
|
||
m LOGIN_START
|
||
R=$(kubectl -n keycloak-lab exec a7a-probe -- sh -c \
|
||
"curl -s -X POST http://$K0:8080$TE -d grant_type=password \
|
||
-d client_id=admin-cli -d username=admin -d password=$PW")
|
||
m LOGIN_END
|
||
RT=$(echo "$R" | sed -n 's/.*"refresh_token":"\([^"]*\)".*/\1/p')
|
||
|
||
m REFRESH_START
|
||
kubectl -n keycloak-lab exec a7a-probe -- sh -c \
|
||
"curl -s -o /dev/null -w '%{http_code}\n' -X POST http://$K0:8080$TE \
|
||
-d grant_type=refresh_token -d client_id=admin-cli -d refresh_token='$RT'"
|
||
m REFRESH_END
|
||
|
||
# ── 4. 표식 사이의 SQL 만 뽑는다
|
||
PG=$(kubectl -n keycloak-lab get pod -l app=postgres -o jsonpath='{.items[0].metadata.name}')
|
||
kubectl -n keycloak-lab logs $PG --tail=4000 > /tmp/pg.log
|
||
awk '/MARK_REFRESH_START/,/MARK_REFRESH_END/' /tmp/pg.log | grep -v JGROUPS_PING
|
||
|
||
# ── 5. 세 가지 캐시 상태를 각각 재현한다
|
||
# A. 완전 냉시동 — 재시작 직후 곧바로 DB 정지
|
||
kubectl -n keycloak-lab rollout restart statefulset/keycloak
|
||
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=500s
|
||
kubectl -n keycloak-lab scale deploy/postgres --replicas=0
|
||
# → 로그인 400
|
||
|
||
# B. CLIENT 만 더움 — 재시작 후 로그인 1회, refresh 는 하지 않고 DB 정지
|
||
kubectl -n keycloak-lab scale deploy/postgres --replicas=1
|
||
kubectl -n keycloak-lab rollout restart statefulset/keycloak
|
||
# (로그인 1회 실행)
|
||
kubectl -n keycloak-lab scale deploy/postgres --replicas=0
|
||
# → 로그인 200 · refresh 500
|
||
|
||
# C. 완전히 더움 — refresh 를 3회 미리 돌린 뒤 DB 정지
|
||
# → 로그인 200 · refresh 200
|
||
|
||
# ── 6. 실패 지점은 로그가 직접 말해준다
|
||
kubectl -n keycloak-lab logs keycloak-0 --tail=150 \
|
||
| grep -oE 'JDBC exception executing SQL \[[^]]*\] \[[^]]*\]'
|
||
|
||
# ── 7. 복구 — 잊으면 다음 실험이 전부 오염된다
|
||
kubectl -n keycloak-lab scale deploy/postgres --replicas=1
|
||
kubectl -n keycloak-lab wait --for=condition=Ready pod -l app=postgres --timeout=180s
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-c "ALTER SYSTEM RESET log_statement;" -c "SELECT pg_reload_conf();"
|
||
kubectl -n keycloak-lab patch statefulset keycloak --type=json \
|
||
-p '[{"op":"replace","path":"/spec/template/spec/containers/0/args","value":["start"]}]'
|
||
kubectl -n keycloak-lab delete pod a7a-probe
|
||
# 확인: DB 에 세션 행이 다시 생기면 persistent 로 돌아온 것이다
|
||
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
|
||
-tAc "select count(*) from offline_user_session where offline_flag='0'"
|
||
```
|
||
|
||
---
|
||
|
||
## 증거 파일
|
||
|
||
| 파일 | 종류 | 무엇을 보여주는가 |
|
||
|---|---|---|
|
||
| [`01-cause-determined.txt`](evidence/a7a-volatile-cause/01-cause-determined.txt) | 터미널 | 문장 로그 원문 · 세 캐시 상태의 재현 · 실패 SQL 을 지목하는 Keycloak 로그 |
|
||
|
||
파일별 상세는 [`evidence/a7a-volatile-cause/README.md`](evidence/a7a-volatile-cause/README.md).
|