From b9f4ef7bc286be138266a92051f0c86d02bf3180 Mon Sep 17 00:00:00 2001 From: DongHyeonka Date: Fri, 4 Sep 2026 20:27:23 +0900 Subject: [PATCH] docs(a7a): the volatile refresh failure is a client-scope lookup, not REVOKED_TOKEN MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A-7 left the cause as a hypothesis and said to confirm it with the statement logging A-3 used. Doing that shows the hypothesis was wrong. Login issues no SQL at all in volatile mode. Refresh issues exactly one statement, and it is not the one A-7 guessed: 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-...', $2 = 'f' REVOKED_TOKEN never appears. DEFAULT_SCOPE='f' means this is the optional client scope list, which refresh needs because it recomputes which scopes go into the new access token. The larger finding is that A-7's table was conditional and did not say so. The single statement is issued once and then cached, so the same configuration produces three different outcomes depending only on cache warmth — all three reproduced: fully cold login 400 (select ce1_0.ID from CLIENT ...) CLIENT warm login 200, refresh 500 <- what A-7 measured fully warm login 200, refresh 200 So "volatile means you can log in without a database" is also conditional: on a cold start the client lookup itself fails. In each case the Keycloak log names the failing SQL directly, so this is determined rather than inferred. A-7 keeps its original wording with a correction banner above it, so what was mis-guessed and why stays visible. Co-Authored-By: Claude Opus 5 --- .../01-cause-determined.txt | 117 ++++++++ docs/evidence/a7a-volatile-cause/README.md | 15 + docs/experiment-a7-volatile-comparison.md | 14 +- docs/experiment-a7a-volatile-cause.md | 284 ++++++++++++++++++ docs/experiment-index.md | 1 + 5 files changed, 430 insertions(+), 1 deletion(-) create mode 100644 docs/evidence/a7a-volatile-cause/01-cause-determined.txt create mode 100644 docs/evidence/a7a-volatile-cause/README.md create mode 100644 docs/experiment-a7a-volatile-cause.md diff --git a/docs/evidence/a7a-volatile-cause/01-cause-determined.txt b/docs/evidence/a7a-volatile-cause/01-cause-determined.txt new file mode 100644 index 0000000..5c44935 --- /dev/null +++ b/docs/evidence/a7a-volatile-cause/01-cause-determined.txt @@ -0,0 +1,117 @@ +A-7a — volatile 모드에서 refresh 가 500 인 진짜 이유 +======================================================= +수집: 2026-09-04 11:18 ~ 11:24 UTC · kc-lab-1 에서 sudo kubectl + +A-7 이 남긴 가설 +---------------- +> **측정은 확실하지만 원인은 확정하지 못했다.** 유력한 후보는 +> `REVOKED_TOKEN` 테이블이다 — refresh token 회전에서 이미 쓴 토큰인지 +> 확인하려면 그 테이블을 봐야 하고, 그 경로는 캐시되지 않는다. + +★ 이 가설은 틀렸다. + +방법 — PostgreSQL 문장 로깅 (A-3 기법) +--------------------------------------- + ALTER SYSTEM SET log_statement = 'all'; SELECT pg_reload_conf(); + +표식을 넣어 로그인과 refresh 가 각각 어떤 SQL 을 쏘는지 구분했다. + select 'MARK_LOGIN_START' ... 로그인 ... select 'MARK_LOGIN_END' + select 'MARK_REFRESH_START' ... refresh ... select 'MARK_REFRESH_END' + +volatile 전환 확인 + args: ["start","--features-disabled=persistent-user-sessions"] + 로그인 200 · offline_user_session 행수 = 0 ← volatile 맞다 + +[측정 1] 로그인은 SQL 을 0개 쏜다 +---------------------------------- + 11:18:49.461 statement: select 'MARK_LOGIN_START' + 11:18:49.743 statement: select 'MARK_LOGIN_END' + ↑ 사이에 아무것도 없다 + +realm·사용자·클라이언트가 전부 Infinispan 캐시에 있어 DB 를 안 본다. + +[측정 2] ★ refresh 는 CLIENT_SCOPE_CLIENT 를 본다 +-------------------------------------------------- + 11:18:52.009 statement: select 'MARK_REFRESH_START' + 11:18:52.137 statement: BEGIN + 11:18:52.137 execute /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'` 이므로 **선택적(optional) 클라이언트 스코프** 조회다. + +[측정 3] 그 조회는 한 번뿐이다 — 캐시에 들어간다 +------------------------------------------------- +연속 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 의 표 자체가 조건부였다 ════ + +같은 설정에서 **캐시 온도만으로 결과가 셋으로 갈린다.** 전부 측정했다. + +┌──────────────────────┬────────┬─────────┬──────────────────────────────┐ +│ 캐시 상태 │ 로그인 │ refresh │ 실패한 SQL │ +├──────────────────────┼────────┼─────────┼──────────────────────────────┤ +│ 완전 냉시동 │ 400 │ 400 │ select ce1_0.ID from CLIENT │ +│ (재시작 직후) │ │ │ where CLIENT_ID=? REALM_ID=?│ +├──────────────────────┼────────┼─────────┼──────────────────────────────┤ +│ CLIENT 만 더움 │ 200 │ ★ 500 │ select cscme1_0.SCOPE_ID │ +│ ← A-7 이 본 상태 │ │ │ from CLIENT_SCOPE_CLIENT │ +├──────────────────────┼────────┼─────────┼──────────────────────────────┤ +│ 완전히 더움 │ 200 │ 200 │ 없음 (SQL 0건) │ +└──────────────────────┴────────┴─────────┴──────────────────────────────┘ + +[재현 A] 완전 냉시동 — 로그인부터 400 + keycloak 재시작 → postgres 정지 → 로그인 + 로그인 400 {"error":"unauthorized_client", + "error_description":"Unexpected error when authenticating client"} + ERROR [org.keycloak.services] KC-SERVICES0015: Unexpected error when + authenticating client: org.hibernate.exception.GenericJDBCException: + JDBC exception executing SQL [FATAL: terminating connection due to + administrator command] + [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 이 본 그 조건 — 로그인 200, refresh 500 + keycloak 재시작 → (DB 살아있을 때) 로그인 1회 → postgres 정지 → refresh + 로그인 200 + refresh 500 {"error":"unknown_error"} + JDBC exception executing SQL [FATAL: terminating connection due to + administrator command] + [select cscme1_0.SCOPE_ID from CLIENT_SCOPE_CLIENT cscme1_0 + where cscme1_0.CLIENT_ID=? and cscme1_0.DEFAULT_SCOPE=?] + + ★ 로그가 실패한 SQL 을 직접 지목한다. CLIENT_SCOPE_CLIENT 다. + +[재현 C] 완전히 더움 — 둘 다 200 + refresh 를 3회 미리 돌려 캐시를 채운 뒤 postgres 정지 + 로그인 200 + refresh 200 ← A-7 의 표와 정반대다 + +════ 결론 ════ + +1. **원인은 REVOKED_TOKEN 이 아니라 선택적 클라이언트 스코프 조회다.** + `CLIENT_SCOPE_CLIENT` 를 `DEFAULT_SCOPE='f'` 로 조회하는 그 한 문장이다. + +2. **A-7 의 "volatile → refresh 500" 은 캐시가 차가울 때만 참이다.** + 더워지면 200 이 된다. A-7 은 그 조건을 몰랐고, 그래서 표에 적지 않았다. + +3. **"volatile 이면 DB 없이 로그인된다" 도 조건부다.** + 냉시동에서는 400 이다. 클라이언트 조회조차 캐시에 없기 때문이다. + +4. **일반화** — volatile 모드에서 DB 정지 시의 동작은 "무엇을 하느냐"가 + 아니라 **"그 경로가 이미 캐시를 채웠느냐"** 로 결정된다. 그래서 같은 + 명령이 재시작 직후와 얼마 쓴 뒤에 다른 답을 낸다. 이런 종류의 결과는 + **한 번 재보고 표로 적으면 안 된다** — A-7 이 그렇게 했다. diff --git a/docs/evidence/a7a-volatile-cause/README.md b/docs/evidence/a7a-volatile-cause/README.md new file mode 100644 index 0000000..60d8b8f --- /dev/null +++ b/docs/evidence/a7a-volatile-cause/README.md @@ -0,0 +1,15 @@ +# A-7a — volatile refresh 500 의 원인 확정 증거 + +2026-09-04 11:18 – 11:24 UTC +해설: [`docs/experiment-a7a-volatile-cause.md`](../../experiment-a7a-volatile-cause.md) + +| 파일 | 무엇을 보여주는가 | +|---|---| +| `01-cause-determined.txt` | **가설이 틀렸다.** `REVOKED_TOKEN` 이 아니라 `CLIENT_SCOPE_CLIENT` 조회다. 문장 로깅으로 잡고, 실패 로그가 그 SQL 을 직접 지목한다. 그리고 **같은 설정에서 캐시 온도만으로 400/500/200 셋이 나온다** | + +## 핵심 네 줄 + +1. **원인은 선택적 클라이언트 스코프 조회다.** `select cscme1_0.SCOPE_ID from CLIENT_SCOPE_CLIENT where CLIENT_ID=? and DEFAULT_SCOPE=?` — A-7 이 지목한 `REVOKED_TOKEN` 은 로그에 한 번도 안 나온다. +2. **로그인은 SQL 을 0개 쏜다.** refresh 만 이 한 문장을 쏘고, 그것도 **첫 번째만** 쏜다. 이후로는 캐시된다. +3. **A-7 의 표가 조건부였다.** 완전 냉시동이면 로그인부터 400, 캐시가 완전히 더우면 refresh 도 200. A-7 이 본 「로그인 200 · refresh 500」은 그 사이의 한 상태다 — 셋 다 재현했다. +4. **교훈** — volatile + DB 정지의 동작은 "무엇을 하느냐"가 아니라 **"그 경로가 캐시를 채웠느냐"** 로 갈린다. 한 번 재보고 표로 적으면 안 되는 종류의 측정이다. diff --git a/docs/experiment-a7-volatile-comparison.md b/docs/experiment-a7-volatile-comparison.md index 768ea7b..9635c3d 100644 --- a/docs/experiment-a7-volatile-comparison.md +++ b/docs/experiment-a7-volatile-comparison.md @@ -29,6 +29,11 @@ **세 개가 정반대로 뒤집혔다.** 예측한 그대로다. +> **★ 이 표에는 조건이 빠져 있다 (A-7a).** volatile 행의 A-2 결과는 +> **캐시 온도에 따라 달라진다.** 완전 냉시동이면 로그인도 `400` 이고, +> 캐시가 완전히 더우면 refresh 도 `200` 이다. 여기 적힌 값은 그 사이의 +> 한 상태다 — 셋 다 [A-7a](experiment-a7a-volatile-cause.md) 에서 재현했다. + > **"세션 공유는 7800 을 안 탄다"는 A-1 의 결론은 버전에 달린 사실이다.** > 인터넷 자료 대부분이 24 이전 기준이므로 **거기서는 통념이 맞다.** > 틀린 것은 자료가 아니라 **버전을 확인하지 않고 적용하는 것**이다. @@ -164,6 +169,13 @@ partitioned roll out complete: 2 new pods have been updated... ### refresh 가 500 인 이유 — 가설 +> **★ 정정 (A-7a)** — 이 가설은 **틀렸다.** 문장 로깅으로 확정한 결과 +> 원인은 `REVOKED_TOKEN` 이 아니라 **`CLIENT_SCOPE_CLIENT` 조회**였다. +> 더 중요하게는 **위 표 자체가 캐시 온도에 따라 400/500/200 으로 갈린다.** +> [A-7a 문서](experiment-a7a-volatile-cause.md) 참조. + +아래는 정정 전 원문이다 — 무엇을 어떻게 잘못 짚었는지 남긴다. + **측정은 확실하지만 원인은 확정하지 못했다.** 유력한 후보는 `REVOKED_TOKEN` 테이블이다 — refresh token 회전에서 **이미 쓴 토큰인지** 확인하려면 그 테이블을 봐야 하고, 그 경로는 캐시되지 않는다. @@ -174,7 +186,7 @@ kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak -c ``` **확정하려면 A-3 에서 쓴 문장 로깅을 켜고 다시 재현해야 한다.** 여기서는 -**가설로 남긴다.** +**가설로 남긴다.** → **A-7a 에서 그대로 실행해 확정했고, 가설은 틀렸다.** > **volatile 이 "DB 없이 돌아간다"는 뜻은 아니다.** > realm·사용자·클라이언트·취소 토큰은 **여전히 DB 에 있다.** diff --git a/docs/experiment-a7a-volatile-cause.md b/docs/experiment-a7a-volatile-cause.md new file mode 100644 index 0000000..a68e563 --- /dev/null +++ b/docs/experiment-a7a-volatile-cause.md @@ -0,0 +1,284 @@ +# 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 의 표 자체가 조건부였다**는 것이 드러났다. + +--- + +## 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 /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). diff --git a/docs/experiment-index.md b/docs/experiment-index.md index 0c1c3b5..1e34a08 100644 --- a/docs/experiment-index.md +++ b/docs/experiment-index.md @@ -27,6 +27,7 @@ | **D-2** | 버전 업그레이드 | `...d2-version-upgrade` | **이미지를 되돌려도 스키마는 안 돌아온다** | | **D-3** | 비밀 관리 | `...d3-secret-management` | **RBAC 만 실제로 감춘다** | | **D-4** | 인증서 갱신 | `...d4-certificate-renewal` | **갱신은 됐는데 36분 39초 반영 안 됨** (훅 3경로 전부 비었음). reload 자체는 **무중단**(8856건 0실패) | +| **A-7a** | volatile refresh 500 원인 확정 | `...a7a-volatile-cause` | **가설(`REVOKED_TOKEN`)은 틀렸다** — `CLIENT_SCOPE_CLIENT` 조회다. **A-7 의 표는 캐시 온도에 따라 400/500/200** | | **후속** | 미측정 3항목 채우기 | `...followup-untested-items` | **셋 다 완료.** 정방향 업그레이드 무중단 · **롤백 불가는 조건부였다** · role 변경은 요청으로 반영 안 됨 · **D-4 갱신 36분 39초 미반영** | ## 시각 자료