Files
document-haness/docs/keycloak-session-store/tech-log-studio/session-custody-across-nodes/setup/setup-reproduce-a0-session-sharing-path.md
T
DongHyeonkaandClaude Opus 5 024362d096 fix(setup): 실험대를 새로 세워 setup 35편을 밟고 어긋난 명령과 결과를 고친다
기반 가이드 7단계로 실험대를 철거하고 다시 세운 뒤 virtualization setup 9편과
keycloak-session-store 26편을 순서대로 밟았다. 24편은 끝까지, 11편은 되는 데까지
밟았고 밟은 범위를 편마다 적었다.

명령이 못 도는 것을 고쳤다.

- kubectl 을 `kc-lab-1` 에서 치라고 적었는데 그 기계에 kubeconfig 가 없다.
  라벨 639개와 각 편의 「어디서 치는가」를 `[lab host]` 로 옮겼다
- `-o custom-columns=…[0]…` 이 zsh 에서 글로브로 읽혀 안 돈다. 28곳에 따옴표
- busybox `sed` 가 끝 개행을 안 붙여 A-3 의 측정이 언제나 0 이었다
- `--token-file ~/node-token` 뒤에 그 파일을 지우면 k3s agent 가 재부팅을
  못 견딘다. `/etc/rancher/node-token` 으로 옮기는 처방을 재서 넣었다
- 게스트에 없는 도구를 전제로 한 명령 넷 — `conntrack`·`dig`·`strings`·`nginx -v`
- `echo` 와 JWT 헤더가 `"이름" : [ 값 ]` 으로 찍는데 문서는 공백 없이 옮겨 적어
  그 실측으로 만든 grep·sed 가 한 줄도 못 잡는다
- B-0 이 `directAccessGrantsEnabled` 와 계정 완성을 빠뜨려 B-3 이 못 돈다
- D-4·D-4a 가 `test-server` 와 `certbot-renew.*` 를 가리키는데 실제로는
  `kc-lab-edge` 의 `certbot.service` 다
- `virsh setmaxmem --config` 를 `dominfo` 로 판정하면 틀린다. `--inactive` 로
- `LIBVIRT_DEFAULT_URI` 를 rc 에만 넣으면 `ssh host '명령'` 에서 안 먹는다

결과가 조건부인 것을 갈랐다.

- readiness 는 즉시 안 뒤집힌다. A-1·A-2 의 60초 창을 적었다
- 03 의 층 ②③ `301` 은 04 이후의 값이고 그 단계에서는 `404` 다
- A-0 의 로그 필터를 요청 직후에 치면 정반대 결론이 나온다
- A-5 의 한 방향 차단은 잠깐 `1` 이었다 `2` 로 돌아온다

증거는 두 프로젝트의 `evidence/raw/` 에 99벌을 README 와 함께 남겼다. 비밀은
길이만 적었고 화면에 찍힌 토큰은 가렸다.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-17 15:59:42 +09:00

903 lines
52 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
---
id: 4f56ed58-fc82-4ed1-ac87-c356b30c34f7
kind: SETUP
slug: reproduce-a0-session-sharing-path
title: 세션을 공유하는 것이 Infinispan 인지 PostgreSQL 인지 손으로 가른다
topic: session-custody-across-nodes
topicName: Keycloak 두 노드가 같은 세션을 읽는 경로
project: keycloak-session-store
status: 게시 전
studio: "https://hyeonworks.com/studio/documents/4f56ed58-fc82-4ed1-ac87-c356b30c34f7/edit"
pinnedVersions:
- name: Keycloak
version: 26.7.0
- name: curlimages/curl
version: 8.11.1
source:
- final/document.md#a층-재현-절차-열-편을-직접-치는-순서-a-0
- final/document.md#a층-재현-절차-열-편을-직접-치는-순서
sourceRevision: cdac9b8178391311d8eca1ebc6cac15bb62d79af
---
# 세션을 공유하는 것이 Infinispan 인지 PostgreSQL 인지 손으로 가른다
세션이 Infinispan 복제로 공유되는지 두 노드가 같은 PostgreSQL 을 읽어서 공유되는지를 손으로 가르는 절차다. 세션 테이블을 비우고 재시작해 0 에서 출발한 뒤, 상주 탐침 파드에서 시험 넷을 차례로 친다. 전 구간 약 40분이고 A층 뒤의 아홉 편이 이 결과 위에 선다.
## 관계
- **클러스터는 형성됐는데 세션을 나르는 것은 데이터베이스였다**
이 절차가 낸 결론을 담은 기록이다. 무엇을 발견했는지는 그쪽에 있고 여기에는 치는 순서만 있다.
- **persistent-user-sessions 가 세션의 거처를 정한다**
이 절차의 모든 숫자가 그 설정이 켜진 상태에서 나온다. 끄면 같은 명령이 다른 답을 낸다.
- **예측을 먼저 적고, 주입이 걸렸는지 결과와 따로 확인하고, 대조군 없이 귀속하지 않는다**
시험 0 에서 반대편 노드의 응답만 재고 발급 노드에 같은 요청을 안 보내면 `403` 을 복제 실패로 읽는다. 그 규칙을 편 기록이다.
- **7800 을 막고 디스커버리와 트랜스포트를 갈라 끊는다**
여기서 잰 교차 노드 refresh `200` 과 로그아웃 뒤 `400` 이 그 편의 대조군 값이 된다.
- **PostgreSQL 을 진짜로 크래시시키고 잃은 로그인을 센다**
시험 0d 에서 잡은 `SET LOCAL synchronous_commit TO OFF` 한 줄의 대가를 그 편이 건수로 잰다.
## 본문
<!-- body:start -->
## 읽기 전에 — 어디서 치는가
명령은 전부 `[lab host]` 에서 `kubectl``psql` 로 친다. 노드 자체를 건드리는 명령이 없어서 게스트에 들어갈 일이 없다. `kubectl``sudo` 를 붙이지 않는다.
```bash label="[lab host] sudo 를 붙이는 쪽이 틀린 형태다"
kubectl -n keycloak-lab get pods # 이렇게
sudo kubectl -n keycloak-lab get pods # 이렇게 치면 안 된다
```
`sudo` 를 붙이면 root 환경으로 돌아 사용자 홈의 kubeconfig 를 못 본다. root 홈에는 `~/.kube/config` 가 없어서 `localhost:8080` 으로 붙으려다 `connection refused` 로 끝난다. 막힌 곳은 클러스터가 아니라 `kubectl` 이 어느 설정 파일을 읽느냐다.
**`kc-lab-1` 에서 치지 않는다.** 원본 가이드는 `kc-lab-1` 에서 치라고 적었는데, 기반 가이드가 세운 실험대에서는 **그 기계에 kubeconfig 가 아예 없다.** 2026-09-17 에 양쪽에서 쳐서 확인했다(observed).
| 어디서 | `kubectl …` | `sudo kubectl …` |
|---|---|---|
| lab host | 된다 | 안 된다 |
| `kc-lab-1` | 안 된다 | 된다 |
`kc-lab-1` 에서 `sudo` 없이 치면 `connection refused` 가 아니라 이렇게 끝난다.
```text
error: error loading config file "/etc/rancher/k3s/k3s.yaml": open /etc/rancher/k3s/k3s.yaml: permission denied
```
k3s 의 `kubectl` 은 `~/.kube/config` 가 없으면 `/etc/rancher/k3s/k3s.yaml` 로 떨어지는데 그 파일은 `600 root` 다. 기반 가이드는 그 파일을 **lab host 의 `~/.kube/config` 로만** 복사하고 게스트의 사용자 홈에는 일부러 두지 않는다 — 워커 한 대가 털리면 클러스터가 통째로 털리는 구성을 피하려고 그렇게 했다. 그래서 「`sudo` 를 붙이지 않는다」는 규칙은 **lab host 의 규칙**이고, 기계를 `kc-lab-1` 로 읽으면 첫 명령부터 막힌다.
터미널은 둘을 연다. 하나는 탐침 파드 셸용이라 붙잡혀 있고, 하나는 관찰용이다. 그래서 `[lab host]` 라벨이 붙은 블록이 `[탐침 파드]` 블록 사이에 끼어 있으면 **관찰용 터미널에서 친다** — 파드 셸을 나가라는 뜻이 아니다. 나가라고 할 때는 `exit` 를 블록으로 따로 적는다.
| 무엇 | 값 |
|---|---|
| 네임스페이스 | `keycloak-lab` · 관측 스택은 `observability` |
| 대상 | StatefulSet `keycloak` 파드 둘 · Deployment `postgres` 하나 |
| 탐침 파드 | `kc-probe` — `curlimages/curl:8.11.1`, `--rm -it`, `--restart=Never` |
| 주 계기 | `vendor_statistics_approximate_entries_unique` 와 PostgreSQL 문장 로그 |
| 스크레이프 간격 | 15초. 지표를 다시 묻기 전에 30초 기다린다 |
| 걸리는 시간 | 전 구간 약 40분 |
| 도구 | `jq` 가 이 실험대에 없다. Prometheus 출력은 `tr` 과 `grep` 으로 자른다 |
## 이 실험이 가르는 것
앞 단계에서 Keycloak 2노드 클러스터를 세우고 로그에서 `ISPN000094` 멤버 2개를 확인했다면 아는 것은 「클러스터가 떴다」까지다. 그 위에 장애를 주입해도 무엇이 무엇 때문에 깨졌는지 해석할 수 없다.
갈라야 할 것은 둘이다.
```text
두 노드가 같은 답을 한다
├── (a) Infinispan 이 세션을 복제했다 ← 통념
└── (b) 두 노드가 같은 PostgreSQL 을 본다 ← 확인할 것
```
「반대편에서도 된다」만 보면 (a) 와 (b) 의 결과가 같아서 구별이 안 된다. 그래서 시험을 넷으로 나눈다.
| 시험 | 무엇을 가르나 |
|---|---|
| **0** 교차 노드 사용 | 반대편이 그 세션을 쓸 수 있는가 (여기까지는 (a)·(b) 구별 안 됨) |
| **0b** 캐시 계수기 델타 | 로그인 하나에 반대편 캐시가 **움직이는가** |
| **0c** 엔트리 소유 | 엔트리가 **어느 노드에** 생기는가 |
| **0d** SQL 포획 | 반대편이 **정말 DB 를 읽는가** — 추론을 관측으로 바꾼다 |
절차를 끝까지 밟으면 한 노드에서 만든 세션을 반대편이 갱신하는 것, 반대편에서 로그아웃하면 원래 노드가 `400` 을 주는 것, 로그인을 받은 노드의 캐시만 늘고 반대편은 `+0` 인 것, 캐시 합계와 DB 총계가 `7 + 5 = 12` 로 맞는 것, 반대편 노드가 날린 `SELECT`·`UPDATE` 문장, 그 트랜잭션 안의 `SET LOCAL synchronous_commit TO OFF` 를 자기 화면에서 보게 된다.
## 전제와 되돌리기
- `05-keycloak` · `06-observability` 가 끝나 있다.
- 두 Keycloak 파드가 서로 다른 노드에 있어야 한다. 같은 노드면 이 실험이 성립하지 않는다.
- 게스트 셸이 따로 필요한 것은 `nft`·`tc`·`systemctl` 처럼 노드 자체를 건드리는 명령뿐이고 이 편에는 그런 명령이 없다.
**이건 상태를 부수는 실험이다.** 세션 테이블을 비우고, StatefulSet 을 재시작하고, PostgreSQL 의 문장 로깅을 켠다. **실험대에서만 한다.** 지운 세션은 돌아오지 않는다. 되돌릴 수 있는 것은 문장 로깅 하나이고, 켜기 전에 끄는 명령을 먼저 읽어 둔다.
```bash label="[lab host] 중간에 그만둘 때 치는 한 묶음"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "alter system reset log_statement" -c "alter system reset log_line_prefix" \
-c "select pg_reload_conf()"
```
## 주입 전에 같은 명령으로 먼저 본다
넓은 것부터 좁혀 간다.
```text
노드 → 파드 → 클러스터 뷰(로그) → 디스커버리(DB) → DB 세션 수 → 노드별 캐시 → 탐침 고르기
```
### 1. 두 파드가 서로 다른 노드에 있는가
**무엇을 보는가** — 파드가 둘 다 Ready 이고 다른 기계에 나뉘어 있는지.
```bash label="[lab host] ① 노드를 본다"
kubectl get nodes
```
```bash label="[lab host] ② 파드가 어느 노드에 있는지 본다"
kubectl -n keycloak-lab get pods -o wide
```
**어디를 보나** — `READY` 가 둘 다 `1/1`, `RESTARTS` 가 `0`, 그리고 `NODE` 열이 서로 다른지. `postgres` 가 어느 노드에 있는지도 적어 둔다.
**이 값이 뜻하는 것** — 두 Keycloak 파드가 같은 노드에 있으면 이 실험은 성립하지 않는다. 원래 실행에서는 `keycloak-0` 이 `kc-lab-2`, `keycloak-1` 이 `kc-lab-1` 이었다(observed). 파드 번호와 노드 번호가 어긋나므로 이름만 보고 짐작하지 않는다. `postgres` 의 위치는 A-2 와 A-3 에서 쓴다.
### 2. 파드 IP 두 개를 변수에 담는다
**무엇을 보는가** — 뒤의 모든 요청이 향할 주소.
```bash label="[lab host] 파드 IP 를 변수에 담고 눈으로 확인한다"
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
K1=$(kubectl -n keycloak-lab get pod keycloak-1 -o jsonpath='{.status.podIP}')
echo "$K0 $K1"
```
**어디를 보나** — 두 값이 빈 문자열이 아닌지.
**이 값이 뜻하는 것** — 실측은 이렇게 나왔다(observed, `01-cross-node-session.txt`).
```text
=== 대상 ===
keycloak-0 10.42.1.43 kc-lab-2
keycloak-1 10.42.0.35 kc-lab-1
```
### 3. 클러스터 뷰를 로그에서 읽는다
**무엇을 보는가** — 두 노드가 서로를 멤버로 세고 있는지.
```bash label="[lab host] 양쪽 로그에서 마지막 클러스터 뷰 한 줄씩"
kubectl -n keycloak-lab logs keycloak-0 | grep ISPN000094 | tail -1
kubectl -n keycloak-lab logs keycloak-1 | grep ISPN000094 | tail -1
```
**어디를 보나** — 괄호 안의 멤버 수. 실측은 이렇다(observed).
```text
2026-09-04 00:52:09,294 INFO [org.infinispan.CLUSTER] (executor-thread-1) ISPN000094: Received new cluster view for channel ISPN: [keycloak-1-48749(v=16.0.12)|5] (2) [keycloak-1-48749(v=16.0.12), keycloak-0-30843(v=16.0.12)]
```
한 줄을 토막으로 끊으면 이렇게 읽힌다.
```text
[keycloak-1-48749|5] (2) [keycloak-1-48749, keycloak-0-30843]
└── 코디네이터 ──┘ │ │ └────── 멤버 목록 ──────┘
│ └─ 멤버 수
└─ 뷰 ID (바뀔 때마다 1 증가)
```
**이 값이 뜻하는 것** — 멤버가 2 다. 이 줄이 증명하는 범위는 거기까지이고, 멤버가 둘이라는 것과 세션이 오간다는 것은 다른 말이다.
### 4. 디스커버리 테이블을 본다
**무엇을 보는가** — 노드가 서로를 찾는 길인 `JGROUPS_PING` 테이블에 무엇이 등록돼 있는지.
```bash label="[lab host] 디스커버리 테이블 세 열"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "select name, ip, coord from jgroups_ping order by name"
```
**어디를 보나** — `coord` 열에 `t` 가 정확히 하나인지. 실측은 이렇다(observed).
```text
name | ip | coord
------------------+-----------------+-------
keycloak-1-48749 | 10.42.0.35:7800 | t
keycloak-0-30843 | 10.42.1.43:7800 | f
(2 rows)
```
**이 값이 뜻하는 것** — 이 테이블은 지금 등록되어 있다는 것만 말한다. 로그는 그때 그렇게 보였다는 기록이고 둘은 다른 것을 말한다.
### 5. 세션이 사는 테이블을 확인한다
**무엇을 보는가** — 온라인 세션이 어느 테이블에 들어가는지.
```bash label="[lab host] 테이블 목록"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak -c "\dt"
```
**어디를 보나** — `USER_SESSION` 이라는 이름이 목록에 없는 것. 실측은 이렇다 — **`(100 rows)` 가운데 이 실험이 쓰는 여섯 줄만 옮겼다**(observed, 2026-09-17 에 다시 세운 실험대에서도 100행이었다).
```text
public | auth_session | table | keycloak
public | jgroups_ping | table | keycloak
public | offline_client_session | table | keycloak
public | offline_user_session | table | keycloak
public | revoked_token | table | keycloak
public | root_auth_session | table | keycloak
```
**이 값이 뜻하는 것** — `persistent-user-sessions`(Keycloak 26 기본값)는 새 테이블을 만들지 않고 기존 오프라인 세션 테이블을 재사용한다. `offline_flag` 컬럼으로 구분하고 `'0'` 이 일반 로그인, `'1'` 이 `offline_access` 다. 기본키가 `(user_session_id, offline_flag)` 복합키인 까닭이 여기 있고, 이 절차의 모든 질의는 `offline_flag='0'` 이다.
```bash label="[lab host] 지금 몇 건인지 센다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "select offline_flag, count(*) from offline_user_session group by offline_flag"
```
### 6. 노드별 캐시 엔트리를 밖에서 묻는다
**무엇을 보는가** — 이 실험의 주 계기인 캐시 엔트리 수.
Keycloak 컨테이너에는 `curl` 도 `wget` 도 없어 `exec` 로 물으면 `exit 127` 이 난다. Prometheus 가 15초마다 이미 긁고 있으므로 밖에서 묻는 쪽이 짧다.
```bash label="[lab host] ① 한 줄짜리 JSON 을 통째로 본다"
kubectl -n observability exec deploy/prometheus -- \
wget -qO- 'localhost:9090/api/v1/query?query=vendor_statistics_approximate_entries_unique'
```
처음 한 번은 자르지 않고 그대로 본다. 어떤 라벨이 붙어 있는지 알아야 다음부터 무엇으로 거를지 정할 수 있다. 라벨을 보고 나면 읽기 좋게 자른다 — 아래 줄은 가이드가 미검증으로 표시했다(unknown).
```bash label="[lab host] ② 라벨을 보고 나서 필요한 줄만 자른다"
kubectl -n observability exec deploy/prometheus -- \
wget -qO- 'localhost:9090/api/v1/query?query=vendor_statistics_approximate_entries_unique' \
| tr ',' '\n' | grep -E '"cache":|"pod":|^"[0-9]'
```
**어디를 보나** — `cache` 가 `sessions` 인 두 줄과 그 값.
**이 값이 뜻하는 것** — `clientSessions`·`work` 같은 다른 캐시도 같이 나오므로 `cache` 라벨을 반드시 확인한다. 중괄호를 URL 에 그대로 넣으면 `wget` 이 싫어할 수 있어 쿼리에 라벨 필터를 걸지 않고 받은 뒤에 거른다.
### 7. 탐침을 무엇으로 할지 정한다
**무엇을 보는가** — 어떤 요청을 보내야 세션 공유를 재는 것이 되는지.
첫 판본은 `userinfo` 로 쟀고 `http_code=403` 을 복제 실패로 읽을 뻔했다. 발급 노드에 같은 요청을 나란히 보내 보니 이랬다(observed).
```text
--- userinfo, scope 없음 ---
k0(발급노드) 403
k1(반대편) 403
--- 403 본문 ---
WWW-Authenticate: Bearer realm="master", error="insufficient_scope",
error_description="Missing openid scope"
```
양쪽 다 403 이었고 원인은 복제가 아니라 요청에 `openid` scope 가 없다는 것이었다. 오히려 두 노드가 똑같이 답했다는 사실 자체가 일치의 증거였다. 반대편 노드의 응답은 발급 노드의 응답과 나란히 놓기 전까지 아무 의미가 없다.
| 탐침 | 하는 일 | 적합한가 |
|---|---|---|
| `userinfo` | 서명 검증 + scope 확인 | **아니다.** 세션을 몰라도 통과할 수 있다 |
| **`refresh_token` 그랜트** | 세션을 찾고, 살아 있는지 보고, 갱신 시각을 쓴다 | **그렇다** |
refresh token 은 회전한다. 한 번 쓰면 옛 것이 무효가 되므로 반대편 노드에 먼저 써야 하고, 발급 노드에 먼저 쓰면 시험군에 쓸 토큰이 사라진다.
판정은 세션 개수가 아니라 sid 로 한다. 관리 API 의 `active=2` 를 보고 판정하려던 첫 시도는 스크립트 자체가 로그인을 두 번 했기 때문에(시험용 + 관리 API 호출용) 실패했다. 같은 문자열이 세 곳에 나온다.
```text
JWT access_token 의 sid jiv3rVZi1VeaO07oVJkL_MYW
↕ 같은 값
DB user_session_id jiv3rVZi1VeaO07oVJkL_MYW
↕ 같은 값
Admin API 세션 목록의 id jiv3rVZi1VeaO07oVJkL_MYW
```
## 주입
주입은 둘이다. 첫째는 출발값을 0 으로 만드는 것이고, 둘째는 시험 0d 직전에 몇 초만 켜는 문장 로깅이다.
### 1. 세션 테이블을 비우고 StatefulSet 을 재시작한다
**목적** — DB 행과 캐시 엔트리를 동시에 0 으로 만들어, 뒤에 세는 숫자가 이 실험이 만든 것만 담게 한다.
```bash label="[lab host] ① 온라인·오프라인 세션 행을 지운다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "delete from offline_user_session"
```
```bash label="[lab host] ② 재시작 시각을 남기고 롤아웃을 건다"
date '+%H:%M:%S 재시작'
kubectl -n keycloak-lab rollout restart statefulset/keycloak
```
```bash label="[lab host] ③ 새 파드가 다 설 때까지 블록한다"
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=300s
```
**예상 결과** — ③ 이 돌아오면 두 파드가 새로 떠 있다. 세션이 전부 지워지고 두 파드가 재시작된 상태이며 되돌릴 수 없다.
**왜 필요한가** — DB 만 지우면 캐시 엔트리가 그대로 있어 출발값이 어긋난다. 원래 실행에서 정리하려고 `delete from offline_user_session` 만 했더니 캐시 합계 19 와 DB 총계 15 가 맞지 않았다(observed). ② 의 시각은 나중에 Grafana 로 시계열을 볼 때 캐시가 0 으로 떨어진 절벽을 찾는 데 쓴다.
**문제가 생기면** — ③ 이 타임아웃으로 끝나면 파드 목록부터 보고, 파드가 안 뜨면 앞 단계인 `05-keycloak` 로 돌아간다.
### 2. PostgreSQL 문장 로깅 — 여기서 켜지 않는다
**목적** — 둘째 주입의 자리를 밝혀 둔다. 명령은 「관찰」의 시험 0d 안에 있다.
문장 로깅은 몇 초만 켠다. 여기서 켜면 시험 0·0b·0c 를 켠 채로 돌게 되고, 그 셋은 로그인과 refresh 를 수십 번 보내므로 로그가 폭주해 시험 0d 에서 찾아야 할 열두 줄이 묻힌다. 켜는 명령과 그 검증은 시험 0d 의 첫 두 단계다.
## 주입 검증
결과를 해석하기 전에 주입이 의도한 것을 정확히 했는지 본다.
### 파드가 새로 떴고 IP 가 바뀌었는가
```bash label="[lab host] 새 파드와 새 IP 를 다시 잡는다"
kubectl -n keycloak-lab get pods -o wide | grep keycloak
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
K1=$(kubectl -n keycloak-lab get pod keycloak-1 -o jsonpath='{.status.podIP}')
echo "$K0 $K1"
```
`AGE` 가 방금이고 `RESTARTS` 가 `0`(새 파드다), 그리고 IP 가 아까 적어 둔 값과 다른지 본다. IP 를 다시 잡지 않으면 뒤의 모든 curl 이 아무 데도 안 닿고, 이 상태를 복제 실패로 읽는 실수가 이 실험에서 가장 흔하다.
### DB 에 세션이 한 행도 없는가
```bash label="[lab host] 남은 행을 센다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "select offline_flag, count(*) from offline_user_session group by offline_flag"
```
한 행도 없어야 한다. 행이 남아 있으면 `delete` 가 실패했거나 그 사이 누가 로그인했다.
### 캐시가 양쪽 다 0 인가
앞의 미검증 형태(`tr`·`grep` 줄)를 다시 치고 `cache":"sessions"` 인 두 줄이 다 `0` 인지 본다. 한쪽만 확인하고 넘어가면 원래 있던 값을 나중에 복제가 왔다고 읽는다. Prometheus 는 15초마다 긁으므로 재시작 직후에 물으면 옛 값이 나올 수 있어 30초쯤 기다렸다가 다시 친다.
## 관찰
상주 탐침 파드를 띄운다. Keycloak 이미지에 `curl` 이 없고, 토큰을 단계 사이로 넘겨야 하며, Service 로 보내면 어느 노드가 처리했는지 알 수 없다. 이 실험의 질문 자체가 어느 노드인가이므로 파드 IP 로 직접 친다.
```bash label="[lab host] 탐침 파드를 띄우고 그 안의 셸로 들어간다"
kubectl -n keycloak-lab run kc-probe --rm -it --restart=Never \
--image=curlimages/curl:8.11.1 \
--env="K0=$K0" --env="K1=$K1" \
--env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
-o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
--command -- sh
```
셸에서 `exit` 하면 `--rm` 이 파드를 지운다. 비밀번호는 명령 치환으로 넘기므로 값이 터미널에도 셸 히스토리에도 남지 않는다. 존재와 길이만 밖에서 확인한다.
```bash label="[lab host] 비밀번호의 길이만 센다"
kubectl -n keycloak-lab get secret keycloak-lab-secrets \
-o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d | wc -c
```
실측은 `19` 다(observed). 파드 안에서도 값이 들어왔는지 길이로만 본다.
```sh label="[탐침 파드] 환경변수가 들어왔는지 길이로 본다"
echo "K0=$K0 K1=$K1 PW길이=${#PW}"
```
`PW길이=0` 이면 `--env` 가 빈 값을 넘긴 것이므로 나가서 다시 띄운다.
### 시험 0 — 반대편 노드가 그 세션을 쓸 수 있는가
`keycloak-0` 에서 로그인하고 응답을 한 번 통째로 본다.
```sh label="[탐침 파드] ① 발급 노드에 로그인하고 응답을 그대로 본다"
TOK=/realms/master/protocol/openid-connect/token
curl -s -X POST "http://$K0:8080$TOK" \
-d grant_type=password -d client_id=admin-cli \
-d username=admin -d "password=$PW"
```
`expires_in` 과 `refresh_expires_in` 을 본다. 실측은 이렇다(observed, `01-cross-node-session.txt`).
```text
=== [1] keycloak-0 에서 로그인 ===
sid jiv3rVZi1VeaO07oVJkL_MYW
sub None
iss https://auth.hyeonworks.com/realms/master
access 수명 60초
refresh 수명 1800초 typ=Refresh
refresh jti 7669cc49-4778-851f-3c49-65f76964ae8e
```
access token 은 60초짜리고 그동안은 서버에 안 물어본다. 그래서 탐침이 access token 이면 안 된다. `sub` 이 없는 것은 `admin-cli` 에 `scope` 없이 direct grant 를 하면 클레임이 `azp, exp, iat, iss, jti, scope, sid, typ` 뿐이기 때문이고(observed), 앞의 `userinfo` 403 과 원인이 같다.
```sh label="[탐침 파드] ② 토큰을 변수에 담고 길이로만 확인한다"
R=$(curl -s -X POST "http://$K0:8080$TOK" \
-d grant_type=password -d client_id=admin-cli \
-d username=admin -d "password=$PW")
RT=$(echo "$R" | sed -n 's/.*"refresh_token":"\([^"]*\)".*/\1/p')
AT=$(echo "$R" | sed -n 's/.*"access_token":"\([^"]*\)".*/\1/p')
echo "refresh=${#RT}자 access=${#AT}자"
```
`refresh=1187자 access=2043자` 같은 모양이 나온다. **그 두 수를 기준값으로 삼지 않는다** — 2026-09-17 에 다시 세운 실험대에서는 `refresh=612자 access=758자` 였다(observed). 담긴 클레임과 서명 길이에 따라 달라지므로 **보는 것은 `0자` 가 아니라는 것 하나**다. `0자` 면 로그인이 실패한 것이고 `echo "$R"` 로 에러 본문을 본다.
JWT 의 가운데 토막이 클레임이다. 먼저 통째로 디코드해 눈으로 보고 그다음에 sid 만 잘라낸다. **두 줄 다 2026-09-17 에 쳐서 확인했다**(observed).
```sh label="[탐침 파드] ③ 클레임을 통째로 디코드해 본다"
echo "$AT" | cut -d. -f2 | tr '_-' '/+' | base64 -d 2>/dev/null; echo
```
```sh label="[탐침 파드] ④ sid 만 뽑는다"
SID=$(echo "$AT" | cut -d. -f2 | tr '_-' '/+' | base64 -d 2>/dev/null \
| sed -n 's/.*"sid":"\([^"]*\)".*/\1/p')
echo "SID=$SID"
```
base64 패딩 때문에 끝이 깨져 보일 수 있고(`2>/dev/null` 이 그 불평을 지운다), `sid` 는 앞쪽에 있어서 대개 보인다. 2026-09-17 실측에서는 마지막 `"}` 두 글자가 잘렸다(observed).
```text
0EPyjFf8PwNJ-1q7","scope":"profile email
```
끝까지 보려면 패딩을 채운다. 이 형태로 디코드하면 클레임이 온전히 나온다(observed).
```sh label="[탐침 파드] ③b 패딩을 채워 끝까지 디코드한다"
P=$(echo "$AT" | cut -d. -f2)
case $(( ${#P} % 4 )) in 2) P="$P==";; 3) P="$P=";; esac
echo "$P" | tr '_-' '/+' | base64 -d; echo
```
```text
{"exp":1789620347,"iat":1789620287,"jti":"onltro:ba0c11cf-5e4a-a378-7268-4efd5cef32b8","iss":"https://auth.hyeonworks.com/realms/master","typ":"Bearer","azp":"admin-cli","sid":"jbFsOn6E0EPyjFf8PwNJ-1q7","scope":"profile email"}
```
클레임 이름이 `azp exp iat iss jti scope sid typ` 여덟이고 `sub` 이 없다는 것도 이 형태로 확인했다(observed).
같은 sid 가 두 노드 모두에서 보이는지 물으려면 `admin-cli` 의 내부 id 가 필요하다. 응답을 한 번 그대로 보고 무엇을 자르는지 눈으로 본 다음 잘라낸다. **잘라내는 줄도 2026-09-17 에 쳐서 확인했다**(observed).
```sh label="[탐침 파드] ⑤ 클라이언트 목록 응답을 그대로 본다"
curl -s -H "Authorization: Bearer $AT" \
"http://$K0:8080/admin/realms/master/clients?clientId=admin-cli"
```
```sh label="[탐침 파드] ⑥ 첫 번째 id 만 잘라낸다"
CID=$(curl -s -H "Authorization: Bearer $AT" \
"http://$K0:8080/admin/realms/master/clients?clientId=admin-cli" \
| tr ',' '\n' | grep -m1 '"id"' | cut -d'"' -f4)
echo "CID=$CID"
```
`sed -n 's/.*"id":"\([^"]*\)".*/\1/p'` 로 뽑으면 뒤쪽의 다른 `id` 를 잡을 수 있다. `.*` 가 탐욕적이라 줄에서 마지막 `"id":"` 를 고르기 때문이고, `tr ',' '\n' | grep -m1` 은 첫 번째 것을 고르므로 안전하다.
```sh label="[탐침 파드] ⑦ 같은 질문을 두 노드에 던진다"
for H in "$K0" "$K1"; do
echo -n "$H : "
curl -s -H "Authorization: Bearer $AT" \
"http://$H:8080/admin/realms/master/clients/$CID/user-sessions?max=100" \
| grep -c "$SID"
done
```
**이 `for` 루프도 2026-09-17 에 쳐서 확인했다**(observed). 그때는 양쪽이 `1` 을 냈다.
```text
10.42.1.7 : 1
10.42.0.13 : 1
```
원래 실행의 실측은 이렇다(observed, `01-cross-node-session.txt`).
```text
=== [3] 같은 sid 가 두 노드 모두에서 보이는가 ===
keycloak-0 (발급 노드) 세션 2개 중 대상 sid → 보임 ✔
ipAddress=10.42.1.44 start=1788483164000 lastAccess=1788483164000
keycloak-1 (반대편) 세션 2개 중 대상 sid → 보임 ✔
ipAddress=10.42.1.44 start=1788483164000 lastAccess=1788483164000
```
세션이 2개인 것은 실험 도구가 만든 잡음이고 판정에 안 쓴다. 여기까지는 (a) 와 (b) 를 구별하지 못한다.
시험군은 회전 때문에 반대편에 먼저 쓴다.
```sh label="[탐침 파드] ⑧ 반대편 노드에서 refresh 한다"
R=$(curl -s -w '\n%{http_code}' -X POST "http://$K1:8080$TOK" \
-d grant_type=refresh_token -d client_id=admin-cli -d "refresh_token=$RT")
echo "$R" | tail -1
RT=$(echo "$R" | sed -n 's/.*"refresh_token":"\([^"]*\)".*/\1/p')
```
`200`, 그리고 새 토큰의 sid 가 같은 값이어야 한다. sid 가 바뀌었다면 세션을 이어받지 않고 새로 만들었다는 뜻이다. 매번 `RT` 를 다시 담는다 — 옛 것을 계속 쓰면 나중에 나오는 400 이 무효화 때문인지 재사용 때문인지 알 수 없게 된다.
무효화가 반대 방향으로도 가는지 본다.
```sh label="[탐침 파드] ⑨ 반대편에서 로그아웃하고 발급 노드에서 다시 갱신해 본다"
curl -s -o /dev/null -w '%{http_code}\n' -X POST \
"http://$K1:8080/realms/master/protocol/openid-connect/logout" \
-d client_id=admin-cli -d "refresh_token=$RT"
curl -s -w '\n%{http_code}\n' -X POST "http://$K0:8080$TOK" \
-d grant_type=refresh_token -d client_id=admin-cli -d "refresh_token=$RT"
```
실측은 이렇다(observed).
```text
=== [6] keycloak-1 을 통해 로그아웃 ===
http_code=204
=== [7] 로그아웃 후 keycloak-0 에서 갱신 시도 (무효화 전파) ===
HTTP 400 ← 기대대로
error invalid_grant
error_description Session not active
```
이 `400` 을 적어 둔다. A-1 에서 7800 을 막으면 같은 곳이 `200` 으로 바뀌고, 그것이 A-1 의 결론이다.
### 시험 0b — 복제인가, 같은 DB 를 본 것인가
로그인 한 번을 사이에 두고 양쪽 노드의 캐시 계수기를 잰다. 복제라면 반대편도 같이 늘고, 같은 DB 를 보는 것뿐이라면 반대편은 안 움직인다. 전값을 재고, `keycloak-0` 에만 로그인 한 번을 넣고, 30초 기다렸다가 후값을 같은 명령으로 잰다.
```sh label="[탐침 파드] 발급 노드에만 로그인 한 번을 넣고 나간다"
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"
exit
```
실측은 이렇다(observed, `02-cache-delta.txt`).
```text
=== keycloak-0 (로그인을 받은 노드) ===
계수기 캐시 전 후 증가
rpc.replication_count clientSessions 1 1 +0
rpc.replication_count sessions 1 1 +0
approximate_entries_unique clientSessions 1 2 +1 ←
approximate_entries_unique sessions 1 2 +1 ←
hits clientSessions 2 2 +0
hits sessions 2 2 +0
misses clientSessions 2 3 +1 ←
misses sessions 3 4 +1 ←
stores clientSessions 2 3 +1 ←
stores sessions 2 3 +1 ←
=== keycloak-1 (아무 요청도 받지 않은 노드) ===
계수기 캐시 전 후 증가
rpc.replication_count clientSessions 7 7 +0
rpc.replication_count sessions 7 7 +0
approximate_entries_unique clientSessions 0 0 +0
approximate_entries_unique sessions 0 0 +0
hits clientSessions 4 4 +0
hits sessions 4 4 +0
misses clientSessions 0 0 +0
misses sessions 0 0 +0
stores clientSessions 1 1 +0
stores sessions 1 1 +0
```
`keycloak-1` 열이 전부 `+0` 이다. 엔트리도 0, 저장도 0 이고 `keycloak-1` 의 `sessions` 엔트리는 처음부터 끝까지 0 이다. `rpc.replication_count` 가 `1`·`7` 로 0 이 아닌 것에 속으면 안 된다 — 이 계수기는 세션 캐시만의 것이 아니라 클러스터가 다른 용무로 주고받은 것까지 센다. 판정은 증가분이 0 이라는 것으로 한다.
### 시험 0c — 엔트리는 어느 노드에 있는가
반대편 노드에 로그인을 몰아주면 분산 캐시(owners=1)와 로컬 캐시가 갈린다.
0b 에서 `exit` 했으므로 `--rm` 이 탐침 파드를 이미 지웠다. 0c 와 0d 는 파드 안에서 치므로 같은 명령으로 다시 띄운다.
```bash label="[lab host] 탐침 파드를 다시 띄운다"
kubectl -n keycloak-lab run kc-probe --rm -it --restart=Never \
--image=curlimages/curl:8.11.1 \
--env="K0=$K0" --env="K1=$K1" \
--env="PW=$(kubectl -n keycloak-lab get secret keycloak-lab-secrets \
-o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
--command -- sh
```
```sh label="[탐침 파드] ① 반대편 노드에 로그인 5회를 몰아준다"
for i in 1 2 3 4 5; do
curl -s -o /dev/null -w '%{http_code} ' -X POST \
"http://$K1:8080/realms/master/protocol/openid-connect/token" \
-d grant_type=password -d client_id=admin-cli \
-d username=admin -d "password=$PW"
done; echo
```
30초 기다렸다가 관찰용 터미널에서 엔트리를 잰다. 「주입 전에」 §6 의 `tr`·`grep` 형태를 그대로 쓰고, `cache":"sessions"` 인 두 줄의 값을 적어 둔다. 스크레이프 간격이 15초라 바로 물으면 옛 값이 나온다.
그다음 같은 루프를 `$K1` 만 `$K0` 로 바꿔 한 번 더 친다. 원 가이드는 이 두 번째 루프를 「`$K1` 을 `$K0` 로 바꿔 5회 더」라고 문장으로만 적었다.
```sh label="[탐침 파드] ② 이번엔 발급 노드에 5회를 몰아준다"
for i in 1 2 3 4 5; do
curl -s -o /dev/null -w '%{http_code} ' -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"
done; echo
```
30초 기다렸다 같은 방법으로 다시 잰다. 실측은 이렇다(observed, `03-cache-ownership.txt`).
```text
keycloak-0 = 10.42.1.43 (kc-lab-2)
keycloak-1 = 10.42.0.35 (kc-lab-1)
단계 k0 entries k1 entries
시작 2.0 0.0
keycloak-1 에 로그인 5회 2.0 5.0
keycloak-0 에 로그인 5회 7.0 5.0
=== 대조: PostgreSQL 에는 몇 건인가 ===
online 세션 12
```
대각선이다. 한 번에 한 쪽만 늘고, `7 + 5 = 12` 로 DB 총계와 맞으므로 어느 엔트리도 두 번 세어지지 않았다.
```bash label="[lab host] DB 총계를 센다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "select count(*) from offline_user_session where offline_flag='0'"
```
캐시 설정은 파일에서 읽을 수 없다. 파드의 `/opt/keycloak/conf/cache-ispn.xml` 은 `<cache-container name="keycloak"><transport/></cache-container>` 뿐이고 Keycloak 26 은 캐시를 코드에서 만든다. 위 결론은 설정을 읽어서가 아니라 동작을 측정해서 얻었다.
### 시험 0d — SQL 을 직접 잡는다
0b·0c 까지는 추론이다. 여기서 둘째 주입인 문장 로깅을 켠다. 앞의 세 시험이 끝난 지금 켜는 것이고, 시험 0d 가 끝나면 이 절의 마지막에서 곧바로 끈다.
```bash label="[lab host] ① 문장 로깅과 클라이언트 주소 접두사를 켜고 같은 명령에서 reload 한다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "alter system set log_statement='all'" \
-c "alter system set log_line_prefix='%m [%p] %h '" \
-c "select pg_reload_conf()"
```
`pg_reload_conf` 가 `t` 를 돌려준다. `%h` 가 클라이언트 주소를 로그 줄 앞에 남기는데, 이것이 없으면 어느 파드가 보낸 질의인지 구별할 수 없어 이 시험의 판정이 성립하지 않는다.
```bash label="[lab host] ② 두 설정이 실제로 적용됐는지 읽는다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "show log_statement" -c "show log_line_prefix"
```
실측은 이렇다(observed, `04-read-path-sql.txt`).
```text
log_statement = all
log_line_prefix = %m [%p] %h
```
`log_statement` 가 아직 `none` 이면 `alter system` 이 `postgresql.auto.conf` 에 쓰기만 하고 `pg_reload_conf()` 가 안 돈 상태다.
이제 요청을 딱 한 번 보낸다. 여러 번 보내면 로그에서 어느 트랜잭션이 어느 요청인지 구별하기 어려워진다.
```sh label="[탐침 파드] ③ 로그인 한 번 · 반대편에서 refresh 한 번"
TOK=/realms/master/protocol/openid-connect/token
R=$(curl -s -X POST "http://$K0:8080$TOK" \
-d grant_type=password -d client_id=admin-cli \
-d username=admin -d "password=$PW")
RT=$(echo "$R" | sed -n 's/.*"refresh_token":"\([^"]*\)".*/\1/p')
SID=$(echo "$R" | sed -n 's/.*"access_token":"\([^"]*\)".*/\1/p' \
| cut -d. -f2 | tr '_-' '/+' | base64 -d 2>/dev/null \
| sed -n 's/.*"sid":"\([^"]*\)".*/\1/p')
echo "SID=$SID"
curl -s -o /dev/null -w '%{http_code}\n' -X POST "http://$K1:8080$TOK" \
-d grant_type=refresh_token -d client_id=admin-cli -d "refresh_token=$RT"
```
실측은 이렇다(observed).
```text
=== 요청 ===
SID=jSt9GEPVQLJsO-1CeJjVgltg
K1_ENTRIES_BEFORE=5.0
REFRESH_ON_K1=200
K1_ENTRIES_AFTER=5.0
```
`%h` 가 남긴 IP 로 걸러 `keycloak-1` 이 보낸 것만 본다. 거르는 명령은 관찰용 터미널에서 치는데 거기에는 `K0`·`K1` 이 없다. 두 값은 「주입 검증」에서 잡았는데 그 터미널을 지금 탐침 파드 셸이 붙잡고 있으므로, 관찰용 터미널에서 두 줄을 다시 친다.
```bash label="[lab host] 관찰용 터미널에서도 파드 IP 를 잡는다"
K0=$(kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
K1=$(kubectl -n keycloak-lab get pod keycloak-1 -o jsonpath='{.status.podIP}')
echo "$K0 $K1"
```
두 값이 「주입 검증」에서 본 것과 같아야 한다. 이 두 줄을 건너뛰고 다음 블록을 치면 `grep "$K1"` 이 `grep ""` 가 되어 모든 줄이 통과하므로, 두 파드가 날린 문장을 `keycloak-1` 만 걸러 낸 것으로 읽게 되고 뒤에서 세는 건수도 양쪽이 같은 값으로 나온다. 화면에는 아무 경고도 안 뜬다.
```bash label="[lab host] 반대편 노드가 날린 문장만 추린다"
kubectl -n keycloak-lab logs deploy/postgres --since=60s \
| grep "$K1" | grep 'LOG: execute'
```
:::warning
**요청을 보내자마자 이 명령을 치면 한 줄도 안 나온다.** 이 트랜잭션은 마지막에서 두 번째 문장이 `SET LOCAL synchronous_commit TO OFF` 라 커밋이 미뤄지고, 로그 줄도 그만큼 늦게 나온다. 2026-09-17 에 요청 직후에 쳤더니 `keycloak-1` 쪽에서는 디스커버리 질의 한 줄만 나왔고, 같은 필터를 몇 초 뒤에 다시 치니 아래 여덟 줄이 다 나왔다(observed). **그 첫 화면을 그대로 읽으면 「반대편은 DB 를 안 읽었다 = 복제였다」는 정반대 결론이 나온다.** 몇 초 기다렸다 친다.
:::
실측은 이렇다(observed, `04-read-path-sql.txt`).
```text
select puse1_0.OFFLINE_FLAG,puse1_0.USER_SESSION_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.VERSION from OFFLINE_CLIENT_SESSION pcse1_0 where (...) in (($1,$2,$3,$4,$5))
select pcse1_0.VERSION from OFFLINE_CLIENT_SESSION pcse1_0 where ... for no key update of pcse1_0 skip locked
update OFFLINE_CLIENT_SESSION set TIMESTAMP=$1,VERSION=$2 where CLIENT_ID=$3 and ... 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
```
`keycloak-1` 은 세션을 DB 에서 읽고 DB 에 쓴다. 파라미터는 `DETAIL` 줄에 있다. sid 는 ③ 이 `SID=` 로 화면에 찍은 값을 옮겨 넣는다 — 그 변수는 탐침 파드 안에만 있어서 `[lab host]` 셸에서는 `$SID` 가 빈 문자열이다. 로그인할 때마다 새로 생기는 값이기도 하다.
```bash label="[lab host] 그 sid 가 들어간 줄만 앞에서 120자씩 본다"
kubectl -n keycloak-lab logs deploy/postgres --since=60s \
| grep '{{SID}}' | cut -c1-120
```
이 실험대의 값은 `jSt9GEPVQLJsO-1CeJjVgltg` 였다(observed).
실측은 이렇다(observed).
```text
2026-09-04 01:12:32.851 UTC [81407] [keycloak-0] DETAIL: parameters: $1 = '0', $2 = 'jSt9GEPVQLJsO-1CeJjVgltg'
...
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.944 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '1788484354', $2 = '1', $3 = '131a9912-...', ...
2026-09-04 01:12:34.946 UTC [81376] [keycloak-1] DETAIL: parameters: $1 = '1788484354', $2 = '1', $3 = '0', $4 = 'jSt9GEPVQLJsO-1CeJjVgltg', $5 = '0'
```
증거 파일에는 IP 대신 `[keycloak-0]` `[keycloak-1]` 이 적혀 있다. 원래 실행 스크립트가 `sed` 로 IP 를 파드 이름으로 바꿔 놓은 것이고, 따라 하는 화면에는 `10.42.0.35` 같은 IP 가 그대로 나온다. pid 도 본다 — `81407` 은 `keycloak-0` 의 연결, `81376` 은 `keycloak-1` 의 연결이며 pid 가 트랜잭션의 경계를 가른다.
이 갱신 트랜잭션은 `01:12:34.934` 의 `BEGIN` 에서 `01:12:34.947` 의 `COMMIT` 까지 13밀리초다. `BEGIN` 과 `COMMIT` 은 sid 를 파라미터로 달지 않아서 위 `grep` 에 안 걸린다. 그래서 화면에 남는 마지막 줄이 `.946` 이고, 거기까지만 세면 12 가 나온다. 경계 두 줄은 같은 pid `81376` 연결에서 나왔고, 실험 기록에 `pid=… |` 꼴로 옮겨 적힌 것으로만 남아 있다(observed). 자기 화면에서 그 둘을 보려면 sid 필터를 빼고 로그에 찍힌 그 pid 로 다시 거른다. 원 가이드에는 그 명령이 없어서 2026-09-17 에 만들어 쳐 봤다(observed).
```bash label="[lab host] 그 pid 의 트랜잭션 경계만 본다"
kubectl -n keycloak-lab logs deploy/postgres --since=5m \
| grep '{{PID}}' | grep -E 'BEGIN|COMMIT|synchronous_commit'
```
`{{PID}}` 는 위 `DETAIL` 줄의 대괄호 안 숫자다 — 그 실험대에서는 `[915]` 였다. 같은 pid 의 `BEGIN` 과 `COMMIT` 사이에 여덟 문장이 들어 있는 것이 보인다. 그 두 줄이 하는 일은 트랜잭션의 경계를 긋는 것이다. 뒤에 나오는 `SET LOCAL synchronous_commit TO OFF` 가 같은 트랜잭션 안에서 `COMMIT` 직전에 나왔다는 판정이 거기서 나오고, 원 가이드는 그 확인을 「pid 로 경계를 확인했다」로 적는다.
파드별 질의 건수는 미검증 형태로 센다(unknown). 여기서도 sid 는 ③ 이 찍은 자기 값이다.
```bash label="[lab host] 두 파드가 각각 몇 줄을 날렸는지 센다"
kubectl -n keycloak-lab logs deploy/postgres --since=60s \
| grep '{{SID}}' | grep -c "$K0"
kubectl -n keycloak-lab logs deploy/postgres --since=60s \
| grep '{{SID}}' | grep -c "$K1"
```
실측은 `6 [keycloak-1]` 과 `6 [keycloak-0]` 이다(observed). sid 하나에 대해 `keycloak-0` 이 6건(로그인), `keycloak-1` 이 6건(갱신)을 날렸다.
위 실측의 `K1_ENTRIES_BEFORE=5.0` 과 `K1_ENTRIES_AFTER=5.0` 이 같다. `keycloak-1` 은 남의 세션을 DB 에서 읽어 처리하고도 캐시에 담지 않았다. 캐시에 담기는 것은 그 노드가 로그인시켜 만든 세션뿐이고 남의 세션은 매번 DB 에서 읽는다. 세션 어피니티가 정확성이 아니라 성능 문제인 까닭이 여기 있다.
같은 로그에 jdbc-ping 하트비트도 보인다(observed).
```text
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 가 다르다)에서 주기적으로 자기 행을 지우고 다시 넣는다. 디스커버리와 트랜스포트가 다른 경로라는 것이 로그에서 눈으로 확인되고, A-1 이 그 둘을 갈라 끊는다.
13밀리초짜리 그 트랜잭션에는 셋이 들어 있었다. 낙관적 락(`VERSION` 컬럼), `FOR NO KEY UPDATE ... SKIP LOCKED`, 그리고 `SET LOCAL synchronous_commit TO OFF` 다. 전역 설정은 다르다.
```bash label="[lab host] 전역 설정을 읽는다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "show synchronous_commit"
```
전역은 `on` 이고 Keycloak 이 세션 트랜잭션에만 `SET LOCAL` 로 끈다. `SET LOCAL` 은 그 트랜잭션이 끝나면 되돌아간다. PostgreSQL 이 갑자기 죽으면 직전 수백 밀리초의 세션 쓰기가 사라질 수 있고, A-3 이 그 숫자를 잰다.
여기까지가 탐침 파드에서 칠 것의 마지막이다. 파드 셸을 붙잡고 있던 터미널에서 나온다. 나가지 않으면 `--rm` 이 파드를 안 지우고 원상복구 확인표의 `kc-probe` 줄이 `NotFound` 가 아니게 된다.
```sh label="[탐침 파드] 나온다. --rm 이 파드를 지운다"
exit
```
문장 로깅은 곧바로 끈다.
```bash label="[lab host] 문장 로깅을 끄고 꺼졌는지 읽는다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "alter system reset log_statement" -c "alter system reset log_line_prefix" \
-c "select pg_reload_conf()"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "show log_statement"
```
켜 둔 채로 다음 실험에 들어가면 안 된다. 로그인 루프를 도는 A-3 에서 `log_statement='all'` 을 켜 두면 로그가 폭주한다.
## 복구와 원상복구 확인표
이 실험은 세션을 만들 뿐 클러스터를 부수지 않는다. 되돌릴 것은 둘이다.
### 1. 문장 로깅을 끈 상태로 되돌린다
**목적** — 다음 실험이 옛 설정 위에서 돌지 않게 한다.
```bash label="[lab host] ① 두 설정을 읽는다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "show log_statement" -c "show log_line_prefix"
```
```bash label="[lab host] ② none 이 아니면 두 설정을 되돌리고 reload 한다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "alter system reset log_statement" -c "alter system reset log_line_prefix" \
-c "select pg_reload_conf()"
```
**예상 결과** — `log_statement` 가 `none` 이다.
**왜 필요한가** — A-3 은 초당 14건으로 로그인을 도는데 문장 로깅이 켜져 있으면 로그가 폭주하고 디스크 I/O 가 늘어 크래시 타이밍 자체가 달라진다.
**문제가 생기면** — `pg_reload_conf()` 를 다시 친다. `alter system` 만으로는 적용되지 않는다.
### 2. 실험이 만든 세션을 정리한다
**목적** — DB 행과 캐시 엔트리를 함께 비워 다음 실험의 출발값을 0 으로 만든다.
```bash label="[lab host] ① 세션 행을 지운다"
kubectl -n keycloak-lab exec deploy/postgres -- psql -U keycloak -d keycloak \
-c "delete from offline_user_session"
```
```bash label="[lab host] ② 파드를 갈아 끼워 캐시를 비운다"
kubectl -n keycloak-lab rollout restart statefulset/keycloak
kubectl -n keycloak-lab rollout status statefulset/keycloak --timeout=300s
```
**예상 결과** — 두 파드가 새로 뜨고 세션 캐시가 양쪽 다 0 이 된다.
**왜 필요한가** — 재시작을 빼면 DB 만 비워지고 캐시가 남아 다음 실험의 출발값이 어긋난다.
**문제가 생기면** — 아래 확인표의 항목을 위에서부터 하나씩 친다.
| 항목 | 명령 | 돌아왔을 때 |
|---|---|---|
| 파드 | `kubectl -n keycloak-lab get pods -o wide` | `keycloak` 둘 다 `1/1 Running` |
| 클러스터 뷰 | `kubectl -n keycloak-lab logs keycloak-0 \| grep ISPN000094 \| tail -1` | 멤버 `(2)` |
| 디스커버리 | `psql -c "select name, ip, coord from jgroups_ping order by name"` | `coord = t` 가 **하나** |
| DB 세션 | `psql -c "select count(*) from offline_user_session"` | `0` |
| 캐시 | `vendor_statistics_approximate_entries_unique` | `sessions` 두 줄 다 `0` |
| 문장 로깅 | `psql -c "show log_statement"` | `none` |
| 탐침 파드 | `kubectl -n keycloak-lab get pod kc-probe` | `NotFound` (없어야 정상) |
| 밖 | `curl -s -o /dev/null -w '%{http_code}\n' https://auth.hyeonworks.com/realms/master` | `200` |
탐침 파드가 지워지지 않았으면 직접 지운다.
```bash label="[lab host] --rm 이 안 먹었을 때"
kubectl -n keycloak-lab delete pod kc-probe --ignore-not-found
```
## 막히면
아래는 전부 이 실험대가 실제로 겪은 증상이다.
| 증상 | 원인 | 확인 |
|---|---|---|
| `kubectl exec keycloak-0 -- curl` 이 `exit 127` | **Keycloak 이미지에 curl 도 wget 도 없다** | 탐침 파드를 띄우거나 Prometheus 에 묻는다 |
| 재시작 뒤 아무 데도 안 닿는다 | **파드 IP 가 바뀌었다** | `get pod -o jsonpath='{.status.podIP}'` 를 다시 |
| 로그인이 `401`/`400` | 비밀번호가 안 넘어갔다 | 파드 안에서 `echo ${#PW}` — `0` 이면 `--env` 가 빈 값 |
| 반대편 응답만 보고 「복제 실패」로 읽었다 | **대조군이 없다** | 발급 노드에 같은 요청을 나란히 |
| `userinfo` 가 양쪽 다 `403` | **`openid` scope 가 없다.** 복제와 무관 | 본문의 `insufficient_scope` |
| 세션 개수가 계속 어긋난다 | **관리 API 호출도 세션을 만든다** | 개수 말고 **sid** 로 본다 |
| 캐시 합계와 DB 총계가 안 맞는다 | **DB 만 지우고 파드를 재시작 안 했다** | `rollout restart statefulset/keycloak` |
| 로그인했는데 지표가 안 움직인다 | Prometheus 스크레이프는 15초 간격 | 30초 기다렸다 다시 |
| `rpc.replication_count` 가 0 이 아니라 당황 | 세션 캐시만의 계수기가 아니다 | 절대값이 아니라 **증가분**으로 본다 |
| `CID` 가 엉뚱한 값이다 | `sed` 의 `.*` 가 탐욕적이라 **마지막** `"id"` 를 잡는다 | `tr ',' '\n' \| grep -m1 '"id"'` |
| 문장 로깅을 켰는데 SQL 이 안 보인다 | `pg_reload_conf()` 를 안 했다 | `show log_statement` 가 `all` 인지 |
| 로그에 어느 파드인지 안 나온다 | `log_line_prefix` 에 `%h` 가 없다 | `show log_line_prefix` |
| 다음 실험에서 postgres 로그가 폭주한다 | **문장 로깅을 껐는지 확인 안 했다** | `show log_statement` 가 `none` |
## 무엇이 관측이고 무엇이 아닌가
이 절차의 숫자는 `2026-09-04 09:5210:14 KST` 에 돈 한 번의 실행에서 나왔다(observed).
- (observed) 파드 IP `10.42.1.43`·`10.42.0.35`, 뷰 ID `5` 와 멤버 `(2)`, `jgroups_ping` 의 `coord = t` 하나, 캐시 델타 전량, `7 + 5 = 12`, `keycloak-1` 이 날린 SQL 여덟 줄, pid `81407`/`81376`, 비밀번호 길이 `19`.
- (observed) 2026-09-17 에 기반 가이드 7단계로 실험대를 새로 세우고 이 절차를 처음부터 다시 밟았다. 가이드가 미검증으로 표시했던 줄이 전부 돌았다 — `tr ',' '\n' | grep -E` 로 자른 Prometheus 출력, JWT 를 디코드해 sid 를 뽑는 `sed` 줄, `CID` 를 뽑는 줄, 두 노드에 `grep -c` 를 도는 `for` 루프.
- (observed) 같은 날 다시 나온 판정 — 반대편 노드의 refresh 가 `200` 이고 sid 가 같은 것, 반대편 로그아웃 뒤 발급 노드가 `400 invalid_grant / Session not active` 를 내는 것, 로그인 한 번에 발급 노드만 `+1` 이고 반대편은 `+0` 인 것, 로그인을 몰아준 쪽만 늘어 `9 + 5 = 14` 가 DB 총계 `14` 와 맞는 것, 반대편이 날린 SQL 여덟 줄이 같은 순서로 나온 것.
- (observed) 같은 날 새로 드러난 것 — 요청 직후에 로그를 거르면 반대편 문장이 한 줄도 안 나온다는 것, pid 로 거르면 `BEGIN`~`COMMIT` 경계가 보인다는 것, 토큰 길이가 `612자`·`758자` 로 원래 실행과 다르다는 것.
- (unknown) 파드별 질의 건수를 세는 두 줄은 이번에도 그대로 치지 않았다. 원래 실행은 스크립트로 했다.
- 트랜잭션 경계 시각 `01:12:34.934` 와 `01:12:34.947` 은 실험 기록 한 벌에만 있다. `04-read-path-sql.txt` 에 보존된 것은 sid 가 걸린 `DETAIL` 줄과 시각 없는 문장 목록이라 타임스탬프가 붙은 `BEGIN`/`COMMIT` 이 없다. 그래서 13밀리초를 증거 원문으로 다시 확인할 수는 없다.
- 캐시 설정은 파일에서 읽을 수 없다. `cache-ispn.xml` 에는 `<transport/>` 뿐이고, 「세션은 DB 로 공유된다」는 판정은 설정을 읽어서가 아니라 동작을 측정해서 얻었다.
- 스크립트를 안 쓰는 까닭도 측정 실패에서 나왔다(observed). `kubectl run --rm -i ... | grep` 로 받았더니 중간 조각이 통째로 사라져 `keycloak-1` 의 스냅샷과 다음 마커가 함께 없어졌고, 전값이 0 으로 잡히면서 가짜 델타가 만들어졌다. 그때 리포트는 `keycloak-1` 이 `+9`, `+7` 증가한 것처럼 보였다 — 없는 복제가 있는 것처럼 보이는 오류다. 다른 하나는 중첩 인용이다. `ssh host '... $VAR ...'` 안에 다시 `sh -c "..."` 를 넣으면 인용이 세 겹이 되어 치환이 조용히 깨졌고, 첫 시도에서 파드 IP 가 빈 문자열이 되어 아무 출력도 나오지 않았다.
<!-- body:end -->