document-haness/docs/keycloak-session-store/tech-log-studio/session-custody-across-nodes/setup/setup-reproduce-a7a-volatile-cause.md

id, kind, slug, title, topic, topicName, project, status, studio, pinnedVersions, source, sourceRevision

id	kind	slug	title	topic	topicName	project	status	studio	pinnedVersions	source	sourceRevision
21dce25a-a165-47dc-bb40-2ed9f6f9efea	SETUP	reproduce-a7a-volatile-cause	문장 로깅으로 그 500 을 낸 SQL 을 확정하고 캐시 온도 셋을 재현한다	session-custody-across-nodes	Keycloak 두 노드가 같은 세션을 읽는 경로	keycloak-session-store	게시 전	https://hyeonworks.com/studio/documents/21dce25a-a165-47dc-bb40-2ed9f6f9efea/edit	name version Keycloak 26.7.0 name version curlimages/curl 8.11.1 name version persistent-user-sessions v1	final/document.md#a층-재현-절차-열-편을-직접-치는-순서-a-7a	cdac9b8178391311d8eca1ebc6cac15bb62d79af

문장 로깅으로 그 500 을 낸 SQL 을 확정하고 캐시 온도 셋을 재현한다

PostgreSQL 문장 로깅을 켜고 volatile 상태의 로그인과 refresh 가 각각 SQL 을 몇 개 쏘는지 화면에서 직접 보는 절차다. 이어서 재현 셋을 rollout restart 로 갈라 치면 같은 설정에서 400 과 500 과 200 이 차례로 나온다. 약 40분.

관계

• 같은 설정이 캐시 온도만으로 세 가지 답을 냈다 이 절차가 재현 A·B·C 로 갈라 잰 것을 그 기록이 결론으로 적는다.
• persistent-user-sessions 가 세션의 거처를 정한다 여기서 끄는 그 기능이 무엇을 바꾸는지는 그 기록이 설명한다.
• persistent-user-sessions 를 끄고 A층 결론 넷을 다시 잰다 이 절차가 확정하는 500 이 거기서 나왔다. 그쪽은 주입이 args 와 iptables 와 DB 정지이고 계기가 교차 노드 응답 코드이며, 여기는 주입이 문장 로깅과 args 와 DB 정지이고 계기가 표식과 문장 로그다.
• 예측을 먼저 적고, 주입이 걸렸는지 결과와 따로 확인하고, 대조군 없이 귀속하지 않는다 주입이 셋이라 검증도 셋이고, 표식이 로그에 들어갔는지를 확인하지 않으면 뒤의 구간 자르기가 통째로 헛돈다.

본문

읽기 전에 — 어디서 치는가

명령은 전부 [kc-lab-1] 에서 kubectl 로 친다. 이 절차에는 노드 자체를 건드리는 명령이 없어서 kc-lab-2 로 들어갈 일이 없다. kubectl 에 sudo 를 붙이지 않는다 — root 홈에는 ~/.kube/config 가 없어서 localhost:8080 으로 붙으려다 connection refused 로 끝난다.

이 편의 시각은 UTC 다. 증거의 11:18:49 는 KST 로 20:18 이고 같은 순간이다. PostgreSQL 컨테이너가 UTC 로 로그를 찍기 때문이고, 로그 시각과 date 를 견줄 때 이걸 잊으면 9시간을 헤맨다.

무엇	값
네임스페이스	keycloak-lab
대상	StatefulSet keycloak 파드 둘 · Deployment postgres 하나
탐침 파드	a7a-probe — curlimages/curl:8.11.1, sleep 7200, --restart=Never
켜는 것	log_statement = 'all' · 반드시 pg_reload_conf() 까지
끄는 기능	--features-disabled=persistent-user-sessions
표식	MARK_TEST · MARK_LOGIN_START · MARK_LOGIN_END · MARK_REFRESH_START · MARK_REFRESH_END · MARK_R1~MARK_R_END
소음	JGROUPS_PING 폴링이 5초마다 로그를 채운다

터미널은 둘을 연다. 하나는 표식과 요청용, 하나는 로그 관찰용이다.

이 실험이 가르는 것

A-7 은 이렇게 끝났다.

측정은 확실하지만 원인은 확정하지 못했다. 유력한 후보는 REVOKED_TOKEN 테이블이다 — refresh token 회전에서 이미 쓴 토큰인지 확인하려면 그 테이블을 봐야 하고, 그 경로는 캐시되지 않는다.

그럴듯하고, 틀렸다.

   가설을 세우는 것       →  괜찮다
   가설을 표에 적는 것    →  다음 사람이 사실로 읽는다
   확정하는 방법이 있는데 안 하는 것  →  이 실험이 고치는 것

「refresh 가 어느 테이블 때문에 실패하는가」는 Keycloak 소스를 읽지 않고도 답할 수 있다. DB 가 실제로 받은 문장을 보면 된다. 확정해 보니 원인만 틀린 게 아니었다 — 같은 설정에서 캐시 온도만으로 답이 셋으로 갈린다.

이 절차를 끝까지 치면 여섯을 손으로 보게 된다. 로그인이 SQL 을 0개 쏘는 것, refresh 가 쏘는 딱 한 문장의 이름이 CLIENT_SCOPE_CLIENT 인 것, 그 문장이 첫 refresh 에만 나오는 것, REVOKED_TOKEN 이 한 번도 안 나오는 것, 같은 설정에서 400 과 500 과 200 이 전부 나오는 것, 그리고 실패한 SQL 을 Keycloak 로그가 직접 지목하는 것.

전제와 되돌리기

앞선 구축 단계 05-keycloak 이 끝나 있어야 한다. A-7 을 먼저 한다 — 이 절차는 A-7 이 남긴 가설을 확정하는 것이고, 거기서 본 500 에서 출발한다. A-3 에서 문장 로깅을 해 봤으면 같은 기법이다.

주입이 셋이고 복구도 셋이다.

• PostgreSQL 문장 로깅을 켠다 → 끄지 않으면 다음 실험의 로그가 폭주한다
• Keycloak 을 volatile 로 바꾼다 → 되돌리지 않으면 A층 결론이 오염된다
• PostgreSQL 을 여러 번 내렸다 올린다 → 마지막에 올라와 있어야 한다

실험대에서만 한다. 중간에 그만두려면 복구 절을 위에서부터 그대로 친다.

표식을 넣는 방식에서 이 절차가 원 실행과 갈라진다. 원 실행은 표식을 셸 함수로 감쌌다.

m() { kubectl -n keycloak-lab exec deploy/postgres -- \
        psql -U keycloak -d keycloak -tAc "select 'MARK_$1'" >/dev/null; }

짧고 편한데 출력을 /dev/null 로 버린다. 표식이 실제로 로그에 들어갔는지 확인하지 않고 다음 명령으로 넘어간다는 뜻이고, 로깅이 안 켜져 있었다면 표식 없는 로그를 한참 뒤에 awk 로 자르다가 알게 된다.

따라 하는 사람은 표식을 한 줄씩 손으로 넣는다. 느리지만 그 즉시 보이고, 안 보이면 그 즉시 안다. 아래 절차가 전부 그 형태다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_TEST'"

주입 전에 같은 명령으로 먼저 본다

파드 → 문장 로깅이 꺼져 있나 → args → 탐침 파드 → 로그가 지금 무엇으로 차 있나

1. 파드 셋이 전부 떠 있는지 본다

목적 — 이 절차가 내렸다 올릴 postgres 가 지금 있는지 확인한다.

kubectl -n keycloak-lab get pods -o wide

예상 결과 — 모양은 이렇고 값은 환경마다 다르다.

NAME                        READY  STATUS   RESTARTS  AGE  IP           NODE
keycloak-0                  1/1    Running  0         2d   10.42.1.94   kc-lab-2
keycloak-1                  1/1    Running  0         2d   10.42.0.45   kc-lab-1
postgres-7b474b88c8-t6rrf   1/1    Running  0         5d   10.42.0.22   kc-lab-1

왜 필요한가 — 셋 다 Running 이어야 하고 postgres 가 특히 그렇다. 이 절차는 그것을 세 번 내렸다 올린다.

문제가 생기면 — postgres 가 없으면 scale deployment/postgres --replicas=1 부터 친다.

2. 문장 로깅이 지금 꺼져 있는지 본다

목적 — 지금 쌓이는 로그가 이 실험 것인지 앞 실험 것인지 가른다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "show log_statement"

예상 결과

 log_statement
---------------
 none

왜 필요한가 — all 이면 앞 실험이 켜 둔 채 끝낸 것이고, 지금 쌓인 로그가 어느 실험 것인지 구별할 수 없다.

문제가 생기면 — all 이 나오면 먼저 끄고 로그가 한 바퀴 돌 때까지 기다린 뒤에 시작한다.

3. 지금 args 를 적어 둔다

목적 — 복구에서 되돌릴 문자열을 확보한다.

kubectl -n keycloak-lab get statefulset keycloak \
  -o jsonpath='{.spec.template.spec.containers[0].args}' ; echo

예상 결과

["start"]

왜 필요한가 — 복구 단계가 이 값 그대로 되돌린다.

문제가 생기면 — 이미 --features-disabled=persistent-user-sessions 가 붙어 있으면 앞 실험이 원복하지 않고 끝냈다. 그것부터 되돌린다.

4. 탐침 파드를 StatefulSet 밖에 띄운다

목적 — Keycloak 을 여러 번 재시작해도 죽지 않는 요청 장치를 세운다.

Keycloak 컨테이너에는 curl 도 wget 도 없어서 kubectl exec keycloak-0 -- curl 은 exit 127 로 끝난다.

K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
  --restart=Never \
  --env="K0=$K0" \
  --env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 7200
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s

비밀번호는 명령 치환으로 넘어가므로 터미널에도 셸 히스토리에도 값이 남지 않는다. 길이만 본다.

kubectl -n keycloak-lab get secret keycloak-lab-secrets \
  -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d | wc -c

19

kubectl -n keycloak-lab exec a7a-probe -- sh -c 'echo "K0=$K0 PW길이=${#PW}"'

예상 결과 — IP 가 보이고 PW길이 가 0 이 아니다.

왜 필요한가 — 명령줄에 평문 비밀번호를 쓰면 파드 안 ps 에도 셸 히스토리에도 남는다. 원래 실험의 재현 절차에 그 형태가 그대로 적혀 있었다.

문제가 생기면 — PW길이=0 이면 --env 가 빈 값을 받았다. 파드를 지우고 다시 띄운다.

5. 로그가 지금 무엇으로 차 있는지 본다

목적 — 켜기 전의 로그를 한 번 봐 두고, 켠 뒤의 소음과 견준다.

kubectl -n keycloak-lab logs deploy/postgres --tail=20

예상 결과 — 조용하다. 여기까지는 에러만 찍힌다.

왜 필요한가 — 다음 절에서 로깅을 켜면 JGroups 가 5초마다 하는 JGROUPS_PING 폴링이 로그를 계속 채운다. 그 소음을 먼저 봐 두면 나중에 grep -v JGROUPS_PING 으로 거르는 까닭을 안다.

문제가 생기면 — 지금 SQL 이 줄줄이 나오면 로깅이 이미 켜져 있다. 2번으로 돌아간다.

주입

주입 셋을 차례로 넣는다. 셋 다 되돌리는 명령을 먼저 읽어 둔다.

6. PostgreSQL 문장 로깅을 켠다

목적 — 서버가 받은 모든 SQL 을 로그에 찍게 한다.

되돌리는 명령을 먼저 읽어 둔다.

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 exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "alter system set log_statement='all'" -c "select pg_reload_conf()"

예상 결과 — ALTER SYSTEM 과 pg_reload_conf 가 차례로 돌고, 곧 로그가 차기 시작한다.

왜 필요한가 — 애플리케이션을 고치지 않고 「이 요청이 DB 를 어떻게 쓰는지」를 밖에서 볼 수 있다. 이것 없이 하면 정확히 A-7 이 겪은 일이 벌어진다 — 그럴듯한 테이블 이름을 골라 가설로 적게 되고, 그게 틀려도 아무도 모른다.

문제가 생기면 — 로그가 안 차면 pg_reload_conf() 가 안 돌았다. alter system 은 postgresql.auto.conf 에 쓸 뿐이고 reload 를 해야 적용된다.

7. Keycloak 을 volatile 로 바꾼다

목적 — 세션을 메모리로 옮겨 A-7 이 본 조건을 만든다.

되돌리는 명령을 먼저 읽어 둔다.

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 rollout status statefulset/keycloak --timeout=500s

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

파드 IP 가 바뀌었으므로 탐침 파드를 다시 띄운다.

kubectl -n keycloak-lab delete pod a7a-probe --ignore-not-found
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
  --restart=Never --env="K0=$K0" \
  --env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 7200
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s

예상 결과 — 롤아웃이 partitioned roll out complete 로 끝나고 탐침이 Ready 가 된다.

왜 필요한가 — 빌드 옵션이라 기동할 때 재빌드가 일어나 오래 걸린다. 그래서 --timeout=500s 를 준다.

문제가 생기면 — 타임아웃이 나면 같은 명령을 다시 치고 logs keycloak-0 에 빌드 진행이 보이는지 본다.

8. PostgreSQL 을 내린다

목적 — DB 가 없는 구간을 만들어 캐시가 무엇을 대신하는지 본다.

kubectl -n keycloak-lab scale deployment/postgres --replicas=0
kubectl -n keycloak-lab wait --for=delete pod -l app=postgres --timeout=90s

예상 결과 — postgres 파드가 목록에서 사라진다.

왜 필요한가 — 세 재현마다 한 번씩, 모두 세 번 내린다. 각 재현에서 내리는 시점이 다르고 그 시점이 곧 캐시 온도를 정한다.

문제가 생기면 — 파드가 안 사라지면 --timeout 을 늘려서 다시 기다린다. delete pod 은 쓰지 않는다 — Deployment 가 곧바로 새로 만든다.

주입 검증

주입이 셋이라 검증도 셋이다. 로깅이 켜졌는지, 표식이 로그에 들어가는지, volatile 전환이 동작으로도 바뀌었는지를 따로 본다.

9. 로깅이 실제로 켜졌고 로그가 차기 시작했는지 본다

목적 — 설정값과 실제 출력을 둘 다 확인한다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "show log_statement"

 log_statement
---------------
 all

kubectl -n keycloak-lab logs deploy/postgres --tail=10

예상 결과

2026-09-04 11:17:40.112 UTC [214] LOG:  execute <unnamed>: select ... from JGROUPS_PING ...

왜 필요한가 — JGROUPS_PING 이 계속 나오는 것이 앞에서 예고한 소음이고, 이게 안 보이면 로깅이 안 켜졌다.

문제가 생기면 — none 이 나오면 pg_reload_conf() 를 다시 친다.

10. 표식이 로그에 들어가는지 본다

목적 — 구간을 자를 수 있는 상태인지 확인한다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_TEST'"

kubectl -n keycloak-lab logs deploy/postgres --tail=5 | grep MARK_TEST

예상 결과

2026-09-04 11:18:40.102 UTC [301] LOG:  statement: select 'MARK_TEST'

왜 필요한가 — statement: select 'MARK_TEST' 가 보이면 이제 표식과 표식 사이만 잘라 볼 수 있다.

문제가 생기면 — 안 보이면 9번의 로깅 확인으로 돌아간다.

11. volatile 전환을 args 와 동작으로 둘 다 본다

목적 — 선언과 동작이 같이 바뀌었는지 확인한다.

kubectl -n keycloak-lab get statefulset keycloak \
  -o jsonpath='{.spec.template.spec.containers[0].args}' ; echo
kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -o /dev/null -w "%{http_code}\n" -X POST \
     "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli \
     -d username=admin -d "password=$PW"'
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select count(*) from offline_user_session where offline_flag='0'"

예상 결과

volatile 전환 확인
  args: ["start","--features-disabled=persistent-user-sessions"]
  로그인 200 · offline_user_session 행수 = 0        ← volatile 맞다

왜 필요한가 — 세 가지가 다 맞아야 한다. 로그인이 200 인데 행이 안 생기는 것으로 판정한다.

문제가 생기면 — 행 수가 0 이 아니면 옛 행이 남아 있다. A-7 처럼 delete from offline_user_session 을 먼저 하고 다시 잰다.

문장 로그가 지금 요청을 잡고 있는지도 본다.

kubectl -n keycloak-lab logs deploy/postgres --since=60s | tail -20

이 시점에서는 거의 JGROUPS_PING 뿐일 텐데, 그게 이 실험의 첫 발견이다. 지금은 「내 요청이 어디 있는지 모르겠다」로만 보이고, 구간을 나눠야 보인다.

관찰

표식 → 요청 → 표식 순으로 치고 awk 로 그 사이를 자른다.

12. 로그인이 무슨 SQL 을 쏘는지 본다

목적 — 로그인 한 번이 DB 에 무엇을 보내는지 센다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_LOGIN_START'"
kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -X POST "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli \
     -d username=admin -d "password=$PW" > /tmp/tok
   sed -n "s/.*\"refresh_token\":\"\([^\"]*\)\".*/\1/p" /tmp/tok > /tmp/rt
   echo "rt $(wc -c < /tmp/rt) bytes"'
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_LOGIN_END'"

rt 1188 bytes

kubectl -n keycloak-lab logs deploy/postgres --tail=4000 > /tmp/pg.log
awk '/MARK_LOGIN_START/,/MARK_LOGIN_END/' /tmp/pg.log | grep -v JGROUPS_PING

예상 결과

  11:18:49.461 statement: select 'MARK_LOGIN_START'
  11:18:49.743 statement: select 'MARK_LOGIN_END'
                                   ↑ 사이에 아무것도 없다

왜 필요한가 — 두 줄뿐이고 로그인은 SQL 을 0개 쏜다. realm 과 사용자와 클라이언트가 전부 Infinispan 캐시에 있고 volatile 이라 세션 쓰기도 없다. awk '/A/,/B/' 는 A 가 나온 줄부터 B 가 나온 줄까지 출력한다. 로그를 파일로 먼저 받는 까닭은 같은 로그를 여러 구간으로 반복해서 잘라 볼 것이기 때문이다.

문제가 생기면 — rt 1 bytes 면 파싱이 실패했고, 그 상태로 다음을 하면 빈 토큰을 보내고 엉뚱한 오류를 보게 된다. cat /tmp/tok 으로 본문을 본다.

13. refresh 가 쏘는 한 문장의 이름을 읽는다

목적 — A-7 의 가설이 지목한 테이블이 실제로 나오는지 본다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_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/realms/master/protocol/openid-connect/token" \
     -d grant_type=refresh_token -d client_id=admin-cli \
     -d "refresh_token=$(cat /tmp/rt)"'
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_REFRESH_END'"

kubectl -n keycloak-lab logs deploy/postgres --tail=4000 > /tmp/pg.log
awk '/MARK_REFRESH_START/,/MARK_REFRESH_END/' /tmp/pg.log | grep -v JGROUPS_PING

예상 결과

  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'

세 가지를 본다 — BEGIN 과 COMMIT 사이에 select 가 하나뿐인 것, 테이블 이름이 CLIENT_SCOPE_CLIENT 인 것, parameters 줄의 $2 = 'f'.

가설이 지목한 테이블이 정말 없는지 직접 센다.

awk '/MARK_REFRESH_START/,/MARK_REFRESH_END/' /tmp/pg.log | grep -ci revoked_token

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 이 세션 계열 테이블을 의심한 것이 자연스러웠지만 빗나갔다.

그 UUID 가 어느 클라이언트인지 궁금하면 물어본다. UUID 는 렐름을 만들 때 정해지므로 실험대마다 다르다. ②가 자른 구간의 parameters 줄에 있는 $1 값을 그대로 옮겨 넣는다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "select id, client_id from client where id='{{CLIENT_UUID}}'"

이 실험대의 값은 131a9912-b578-4b9c-b16a-97518704077e 였다(observed).

admin-cli 가 나오면 방금 친 요청의 클라이언트가 맞다.

문제가 생기면 — 구간에 표식이 두 번 나오면 로그를 여러 번 받아 구간이 겹쳤다. --tail 을 줄이거나 새 표식 이름을 쓴다.

14. 그 조회가 한 번뿐인 것을 본다

목적 — 첫 refresh 가 캐시를 채우고 이후로는 DB 를 보지 않는다는 것을 확인한다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_R1'"
kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -X POST "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=refresh_token -d client_id=admin-cli \
     -d "refresh_token=$(cat /tmp/rt)" > /tmp/tok
   sed -n "s/.*\"refresh_token\":\"\([^\"]*\)\".*/\1/p" /tmp/tok > /tmp/rt
   echo "rt $(wc -c < /tmp/rt) bytes"'
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select 'MARK_R2'"

같은 모양으로 MARK_R3 과 MARK_R_END 까지 두 번 더 한다. 매번 /tmp/rt 를 다시 채운다 — refresh token 은 회전하고, 옛것을 계속 쓰면 나오는 오류가 무효화 때문인지 재사용 때문인지 구별되지 않는다.

kubectl -n keycloak-lab logs deploy/postgres --tail=4000 > /tmp/pg.log
awk '/MARK_R1/,/MARK_R_END/' /tmp/pg.log | grep -v JGROUPS_PING

예상 결과

연속 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 를 보지 않으므로, DB 를 언제 내리느냐에 따라 답이 달라진다.

문제가 생기면 — 400 Session not active 가 나오면 옛 refresh token 을 재사용했다. 매번 /tmp/rt 를 갱신한다.

15. 재현 A — 완전 냉시동이면 로그인부터 400 이다

목적 — 캐시가 전부 빈 상태에서 DB 를 내렸을 때의 답을 잰다.

캐시는 Keycloak 을 재시작해야만 식는다.

   Infinispan 캐시 = 프로세스 메모리
        │
        └─ 파드가 살아 있는 한 안 식는다
             └─ 그래서 세 재현 사이마다 rollout restart 를 한다

이 재시작을 건너뛰면 세 상태가 하나로 뭉개진다. 이미 더워진 캐시에서 계속 재게 되므로 A 와 B 를 재도 C 의 답이 나오고, 「A-7 이 틀렸다」는 엉뚱한 결론에 이른다.

kubectl -n keycloak-lab rollout restart statefulset/keycloak
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=500s
kubectl -n keycloak-lab scale deployment/postgres --replicas=0
kubectl -n keycloak-lab wait --for=delete pod -l app=postgres --timeout=90s

재시작과 DB 정지 사이에 아무 요청도 보내지 않는다. 한 번이라도 로그인하면 캐시가 더워져서 이건 재현 B 가 된다. 파드 IP 가 바뀌었으므로 탐침을 다시 띄운 다음 로그인을 본문까지 본다.

탐침의 K0 는 만들 때 고정된 값이라 재시작 뒤에는 낡았다. 지우고 새 IP 로 다시 만든다. 이 블록을 건너뛰면 뒤의 curl 이 없는 주소로 가고, 그 침묵을 「DB 가 없어서 실패」로 읽게 된다.

kubectl -n keycloak-lab delete pod a7a-probe --ignore-not-found
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
  --restart=Never --env="K0=$K0" \
  --env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 7200
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s

kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -w "\n%{http_code}\n" -X POST \
     "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli \
     -d username=admin -d "password=$PW"'

예상 결과

    로그인 400 {"error":"unauthorized_client",
                "error_description":"Unexpected error when authenticating client"}

unauthorized_client 이고 invalid_grant 가 아니다. 세션 문제가 아니라 클라이언트를 못 찾았다. 왜인지는 Keycloak 로그가 직접 말한다.

kubectl -n keycloak-lab logs keycloak-0 --tail=150 \
  | grep -oE 'JDBC exception executing SQL \[[^]]*\] \[[^]]*\]'

  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=?]

왜 필요한가 — 대괄호가 두 쌍이다. 앞은 DB 가 준 오류, 뒤는 실패한 SQL 원문이고 grep -oE 가 그 두 쌍만 뽑는다. A-7 은 「volatile 이면 DB 없이 로그인된다」고 적었는데 냉시동에서는 클라이언트 조회조차 캐시에 없어서 로그인부터 실패한다.

문제가 생기면 — 아무것도 안 나오면 --tail 을 늘리거나 grep -i 'JDBC exception' 으로 먼저 넓게 본다. 정규식이 안 맞는 것과 로그에 없는 것은 다르다. 로그인이 200 이 나오면 재시작 후 요청을 한 번이라도 보낸 것이므로 이 재현을 처음부터 다시 한다.

16. 재현 B — 로그인만 한 번 하면 refresh 가 500 이다

목적 — A-7 이 본 그 조건을 그대로 만든다.

kubectl -n keycloak-lab scale deployment/postgres --replicas=1
kubectl -n keycloak-lab rollout status deployment/postgres --timeout=180s
kubectl -n keycloak-lab rollout restart statefulset/keycloak
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=500s

탐침을 새 IP 로 다시 띄운 뒤 로그인 한 번만 한다. 15번과 같은 이유로 여기서도 탐침을 다시 만든다.

kubectl -n keycloak-lab delete pod a7a-probe --ignore-not-found
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
  --restart=Never --env="K0=$K0" \
  --env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 7200
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s

kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -X POST "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli \
     -d username=admin -d "password=$PW" > /tmp/tok
   sed -n "s/.*\"refresh_token\":\"\([^\"]*\)\".*/\1/p" /tmp/tok > /tmp/rt
   echo "rt $(wc -c < /tmp/rt) bytes"'

여기서 refresh 를 하면 재현 C 가 된다. 8번의 DB 정지를 친 다음에 refresh 한다.

kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -w "\n%{http_code}\n" -X POST \
     "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=refresh_token -d client_id=admin-cli \
     -d "refresh_token=$(cat /tmp/rt)"'

예상 결과

    로그인   200
    refresh  500 {"error":"unknown_error"}

실패한 SQL 을 15번과 같은 grep -oE 로 뽑으면 이렇게 나온다.

  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=?]

왜 필요한가 — 13번에서 문장 로깅이 「이 문장을 쏜다」를 보여 줬고 여기서는 「이 문장이 실패했다」가 나온다. 둘이 만나면 가설이 아니라 확정이 된다. 500 unknown_error 인 까닭도 이제 안다 — 세션은 멀쩡하고, 토큰을 조립하다가 DB 가 없어서 못 만든 것을 Keycloak 이 사용자 오류로 분류할 방법이 없어서 unknown_error 를 준다.

문제가 생기면 — 200 / 200 이 나오면 로그인 뒤 refresh 를 미리 했다. 로그인 한 번만 하고 DB 를 내린다.

17. 재현 C — 미리 세 번 갱신해 두면 둘 다 200 이다

목적 — 캐시가 완전히 더운 상태의 답을 잰다.

DB 를 살리고, 재시작하고, 탐침을 새로 만들고, 로그인하고, refresh 를 3회 미리 돌린 뒤 DB 를 내린다. 앞 절들의 명령을 그대로 다시 친다.

kubectl -n keycloak-lab scale deployment/postgres --replicas=1
kubectl -n keycloak-lab rollout status deployment/postgres --timeout=180s
kubectl -n keycloak-lab rollout restart statefulset/keycloak
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=500s

파드가 새로 떴으므로 K0 가 낡았다. 탐침도 그 값을 --env 로 박아 뒀으니 같이 다시 만든다.

kubectl -n keycloak-lab delete pod a7a-probe --ignore-not-found
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
kubectl -n keycloak-lab run a7a-probe --image=curlimages/curl:8.11.1 \
  --restart=Never --env="K0=$K0" \
  --env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 7200
kubectl -n keycloak-lab wait --for=condition=Ready pod/a7a-probe --timeout=120s

새 탐침에는 /tmp/rt 가 없다. 16번의 ③ 과 같은 명령으로 다시 만든다.

kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -X POST "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli \
     -d username=admin -d "password=$PW" > /tmp/tok
   sed -n "s/.*\"refresh_token\":\"\([^\"]*\)\".*/\1/p" /tmp/tok > /tmp/rt
   echo "rt $(wc -c < /tmp/rt) bytes"'

여기서 재현 C 가 끊긴다. 다음에 와야 할 것은 DB 를 내리기 전에 refresh 를 세 번 돌려 캐시를 마저 채우는 단계인데, 그 세 번을 치는 명령이 원본 가이드에 없다(unknown). 가이드는 「refresh 3회를 미리 돌린 뒤」라고 쓰고 그 세 번의 명령도, 회전하는 refresh token 을 /tmp/rt 에 매번 다시 쓰는 형태도 남기지 않았다. 14번의 ① 이 표식 사이에서 refresh 를 한 번 돌리며 /tmp/rt 를 갱신하는 형태를 갖고 있지만, 그것을 세 번 돌리는 것이 가이드가 말한 그 3회와 같은지는 확인되지 않았다. 이 단계를 채우지 못하면 아래 ④⑤ 를 쳐도 재현 B 와 같은 상태이고 500 이 나온다.

그 세 번을 돌렸다고 보고, 8번과 같은 명령으로 DB 를 내린다.

kubectl -n keycloak-lab scale deployment/postgres --replicas=0
kubectl -n keycloak-lab wait --for=delete pod -l app=postgres --timeout=90s

kubectl -n keycloak-lab exec a7a-probe -- sh -c \
  'curl -s -o /dev/null -w "login %{http_code}\n" -X POST \
     "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=password -d client_id=admin-cli -d "password=$PW" -d username=admin
   curl -s -o /dev/null -w "refresh %{http_code}\n" -X POST \
     "http://$K0:8080/realms/master/protocol/openid-connect/token" \
     -d grant_type=refresh_token -d client_id=admin-cli \
     -d "refresh_token=$(cat /tmp/rt)"'

예상 결과

  refresh 를 3회 미리 돌려 캐시를 채운 뒤 postgres 정지
    로그인   200
    refresh  200        ← 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건)

무엇이 다른지는 kubectl get 어디에도 안 나온다. 캐시 온도는 보이지 않는 상태이고, A-1 에서 conntrack 이 「주입했는데 안 걸렸다」를 만든 것과 같은 계열의 함정이다.

   volatile + DB 정지의 결과
     = "무엇을 하느냐"가 아니라
       "그 경로가 이미 캐시를 채웠느냐"

persistent 기본값에는 이 조건부성이 없다. 세션 자체를 DB 에 쓰므로 DB 가 없으면 캐시 온도와 무관하게 실패한다. 이것은 volatile 고유의 성질이고, 옛 방식이 「DB 의존이 적다」고 말할 때 놓치는 부분이다.

문제가 생기면 — 세 재현이 전부 200/200 이면 재시작을 건너뛰어 캐시가 계속 더웠다. 재현마다 rollout restart 를 넣는다.

복구와 원상복구 확인표

셋을 순서대로 되돌린다. DB 가 살아 있어야 나머지가 된다.

kubectl -n keycloak-lab scale deployment/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 exec deploy/postgres -- psql -U keycloak -d keycloak \
  -c "show log_statement"

 log_statement
---------------
 none

왜 급한가 — A-3 은 수백 건의 로그인을 최대한 빨리 돈다. log_statement='all' 이면 로그인 하나에 SQL 열 몇 줄씩 쌓이고, 로그가 폭주하고 디스크 입출력이 늘어 크래시 타이밍 자체가 달라진다. 다음 실험의 측정값이 이 설정 때문에 바뀐다.

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 rollout status statefulset/keycloak --timeout=500s

args 문자열만 보고 끝내지 않는다. 탐침을 새 IP 로 띄우고 로그인을 한 번 한 다음 행을 센다.

kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
  -tAc "select count(*) from offline_user_session where offline_flag='0'"

0 이 아니어야 한다. 로그인 후 행이 생기면 persistent 로 돌아온 것이고, 원래 재현 절차도 마지막에 이 한 줄을 둔다.

항목	명령	돌아왔을 때
문장 로깅	psql -c "show log_statement"	none
args	get statefulset keycloak -o jsonpath='{...containers[0].args}'	["start"]
DB	kubectl -n keycloak-lab get pods -l app=postgres	1/1 Running
동작	로그인 뒤 select count(*) ...	세션 행이 생긴다
파드	kubectl -n keycloak-lab get pods -o wide	keycloak 둘 다 1/1 Running
클러스터	vendor_cluster_size	양쪽 2
탐침 파드	kubectl -n keycloak-lab get pod a7a-probe	NotFound
임시 파일	ls /tmp/pg.log	지워도 된다
밖	curl -s -o /dev/null -w '%{http_code}\n' https://auth.hyeonworks.com/realms/master	200

kubectl -n keycloak-lab delete pod a7a-probe --ignore-not-found
rm -f /tmp/pg.log

막히면

아래는 전부 이 실험대가 실제로 겪은 증상이고 지어낸 것은 없다.

증상	원인	확인
표식이 로그에 안 보인다	pg_reload_conf() 를 안 했다	show log_statement 가 all 인지
표식 사이가 JGROUPS_PING 으로 가득하다	정상이다. 5초마다 폴링한다	grep -v JGROUPS_PING
표식이 두 번 나온다	로그를 여러 번 받아 구간이 겹쳤다	--tail 을 줄이거나 새 표식 이름을 쓴다
로그 시각이 9시간 어긋난다	컨테이너 로그가 UTC 다	date -u 와 비교한다
refresh 가 400 Session not active	옛 refresh token 을 재사용했다	매번 /tmp/rt 를 갱신
rt 1 bytes	파싱 실패. 빈 토큰을 보내게 된다	cat /tmp/tok 으로 본문 확인
세 재현이 전부 200/200	재시작을 건너뛰어 캐시가 계속 더웠다	재현마다 rollout restart
재현 A 가 200 이 나온다	재시작 후 요청을 한 번이라도 보냈다	재시작 뒤 바로 DB 정지
재현 B 가 200/200	로그인 뒤 refresh 를 미리 했다	로그인 한 번만 하고 DB 정지
JDBC exception grep 이 빈 출력	--tail 이 짧거나 정규식이 안 맞는다	grep -i 'JDBC exception' 으로 먼저 넓게
재시작 뒤 아무 데도 안 닿는다	파드 IP 가 바뀌었다	탐침을 지우고 새 IP 로 다시 띄운다
kubectl exec keycloak-0 -- curl 이 exit 127	Keycloak 이미지에 curl 도 wget 도 없다	탐침 파드를 쓴다
다음 실험의 postgres 로그가 폭주한다	문장 로깅을 끄지 않았다	show log_statement 가 none
다음 실험의 세션이 안 살아남는다	volatile 로 둔 채 끝냈다	로그인 뒤 행 수 확인

무엇이 관측이고 무엇이 아닌가

이 실험대가 실제로 본 것(observed)은 volatile 전환 확인의 세 줄(args · 로그인 200 · 행수 0), 로그인 구간의 표식 두 줄 11:18:49.461 과 11:18:49.743 및 그 사이 SQL 0건, refresh 구간의 다섯 줄과 CLIENT_SCOPE_CLIENT 문장 전문과 파라미터 $1 = '131a9912-b578-4b9c-b16a-97518704077e' 및 $2 = 'f', REVOKED_TOKEN 0건, 연속 refresh 3회의 표식 네 줄과 SQL 0건, 재현 A 의 400 unauthorized_client 와 select ce1_0.ID from CLIENT ... 실패 SQL, 재현 B 의 200 과 500 unknown_error 및 CLIENT_SCOPE_CLIENT 실패 SQL, 재현 C 의 200 과 200, 비밀번호 길이 19, 표식 시험의 statement: select 'MARK_TEST' 다.

이 편에는 가이드가 미검증으로 표시한 명령이 하나도 없다(unknown 이 0건이다). 표식을 감싼 셸 함수 m() 은 원 실행이 실제로 썼고(observed), 그것을 한 줄씩 손으로 푸는 형태가 가이드의 권고다.

시각 표기는 UTC 다. 증거 파일과 위 인용이 전부 UTC 이고 KST 로는 20:18–20:24 이며, PostgreSQL 컨테이너가 UTC 로 찍기 때문이다.

A-7 에서 틀린 것으로 확정된 것이 둘이다. 원인 테이블을 REVOKED_TOKEN 으로 본 가설, 그리고 「volatile 이면 DB 없이 로그인된다」는 서술이다. 냉시동에서는 로그인부터 실패한다.

이 절차가 재지 않은 것은 캐시가 얼마나 오래 더운지다. CLIENT_SCOPE_CLIENT 결과의 캐시 만료 시간을 모르므로 한참 뒤에 다시 재면 또 다른 답이 나올 수도 있다. 그것까지 확인하려면 재현 C 뒤에 시간을 두고 같은 시험을 반복해야 한다.