docs: capture the SQL the other node actually runs, and correct the replication claim

PostgreSQL statement logging shows keycloak-1 reading and updating the session created on keycloak-0. The same transaction reveals optimistic locking via VERSION, SKIP LOCKED, and synchronous_commit turned off. Fixes the earlier concept note that credited Infinispan with cross-node propagation.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
DongHyeonka
2026-09-04 10:14:45 +09:00
co-authored by Claude Opus 5
parent e5ebaeb623
commit 22d873eb4f
5 changed files with 359 additions and 23 deletions
+108
View File
@@ -0,0 +1,108 @@
#!/usr/bin/env bash
# Experiment 0d — capture the actual SQL that the OTHER node runs.
#
# Experiments 0b/0c showed that session entries never appear in keycloak-1's
# memory, yet keycloak-1 can use a session keycloak-0 created. The conclusion
# "keycloak-1 reads it from PostgreSQL" was an inference, not an observation.
#
# This script turns on statement logging in PostgreSQL for a few seconds, sends
# ONE refresh request to keycloak-1 for a session born on keycloak-0, and greps
# the database log for that session id. If the inference is right, the SQL is
# there, issued from keycloak-1's pod IP.
#
# It also checks whether serving that request makes keycloak-1 cache the session
# — which sharpens "each node caches what it handled" from "what it logged in"
# to "what it touched".
set -uo pipefail
NS="${NS:-keycloak-lab}"
PSQL="kubectl -n $NS exec deploy/postgres -- psql -U keycloak -d keycloak -tAc"
K0_IP=$(kubectl -n "$NS" get pod keycloak-0 -o jsonpath='{.status.podIP}')
K1_IP=$(kubectl -n "$NS" get pod keycloak-1 -o jsonpath='{.status.podIP}')
ADMIN_PW=$(kubectl -n "$NS" get secret keycloak-lab-secrets \
-o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)
echo "수집 시각: $(date '+%Y-%m-%d %H:%M:%S %Z')"
echo " keycloak-0 = $K0_IP (세션을 만드는 노드)"
echo " keycloak-1 = $K1_IP (읽기만 하는 노드)"
echo
# %h 를 넣어야 어느 파드가 보낸 질의인지 로그에서 구분된다.
echo "=== PostgreSQL 문장 로깅을 켠다 ==="
$PSQL "alter system set log_statement='all'" >/dev/null 2>&1
$PSQL "alter system set log_line_prefix='%m [%p] %h '" >/dev/null 2>&1
$PSQL "select pg_reload_conf()" >/dev/null 2>&1
echo " log_statement = $($PSQL 'show log_statement' 2>/dev/null)"
echo " log_line_prefix = $($PSQL 'show log_line_prefix' 2>/dev/null)"
echo
# 로그 커서를 잡아둔다. 이 줄 수 이후만 본다.
LOG_BEFORE=$(kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null | wc -l)
RESULT=$(kubectl -n "$NS" run kc-readpath --rm -i --restart=Never \
--image=curlimages/curl:8.11.1 --quiet --command -- sh -c "
O=/tmp/o; : > \$O
TOKEN_EP='/realms/master/protocol/openid-connect/token'
jget() { sed -n \"s/.*\\\"\$1\\\":\\\"\\([^\\\"]*\\)\\\".*/\\1/p\"; }
ent() {
curl -s --retry 3 --max-time 20 http://\$1:9000/metrics \
| grep -E '^vendor_statistics_approximate_entries_unique.cache=.sessions' | awk '{print \$NF}'
}
# keycloak-0 에서 로그인한다
L=\$(curl -s -X POST \"http://$K0_IP:8080\$TOKEN_EP\" -d grant_type=password \
-d client_id=admin-cli -d username=admin -d 'password=$ADMIN_PW')
SID=\$(echo \"\$L\" | jget access_token | cut -d. -f2 | sed 's/\$/==/' | base64 -d 2>/dev/null | jget sid)
RT=\$(echo \"\$L\" | jget refresh_token)
echo \"SID=\$SID\" >> \$O
echo \"K1_ENTRIES_BEFORE=\$(ent $K1_IP)\" >> \$O
sleep 2
# 반대편 노드에 refresh 를 딱 한 번 보낸다
# 인용을 한 겹 더 쌓으면 curl 이 URL 을 통째로 못 읽는다. 실제로 000 이 나왔다.
CODE=\$(curl -s -o /dev/null -w '%{http_code}' -X POST \
\"http://$K1_IP:8080\$TOKEN_EP\" \
-d grant_type=refresh_token -d client_id=admin-cli -d \"refresh_token=\$RT\")
echo \"REFRESH_ON_K1=\$CODE\" >> \$O
sleep 3
echo \"K1_ENTRIES_AFTER=\$(ent $K1_IP)\" >> \$O
cat \$O
" 2>&1 | grep -v '^pod .* deleted$')
echo "=== 요청 ==="
echo "$RESULT" | sed 's/^/ /'
SID=$(echo "$RESULT" | sed -n 's/^SID=//p')
echo
echo "=== PostgreSQL 문장 로깅을 끈다 ==="
$PSQL "alter system reset log_statement" >/dev/null 2>&1
$PSQL "alter system reset log_line_prefix" >/dev/null 2>&1
$PSQL "select pg_reload_conf()" >/dev/null 2>&1
echo " log_statement = $($PSQL 'show log_statement' 2>/dev/null)"
echo
echo "=== keycloak-1 이 실제로 보낸 SQL 문장 ==="
echo " (파라미터가 \$1 로 묶여 있어, sid 는 바로 아래 DETAIL 줄에 있다)"
echo
kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \
| tail -n +$((LOG_BEFORE + 1)) \
| grep -F "$K1_IP" | grep -E "LOG: execute" \
| sed 's/.*execute [^:]*: //' | sed 's/^/ /' | head -12
echo
echo "=== 그 sid 를 언급한 SQL — 누가 보냈는가 ==="
echo " 찾는 sid: $SID"
echo
kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \
| tail -n +$((LOG_BEFORE + 1)) \
| grep -F "$SID" \
| sed -e "s/$K0_IP/[keycloak-0]/g" -e "s/$K1_IP/[keycloak-1]/g" \
| cut -c1-220 \
| head -20
echo
echo "=== 요약: 파드별 질의 건수 ==="
kubectl -n "$NS" logs deploy/postgres --tail=-1 2>/dev/null \
| tail -n +$((LOG_BEFORE + 1)) \
| grep -F "$SID" \
| grep -oE "^[0-9-]+ [0-9:.]+ [A-Z]+ \[[0-9]+\] [0-9.]+" \
| awk '{print $NF}' | sort | uniq -c \
| sed -e "s/$K0_IP/[keycloak-0]/" -e "s/$K1_IP/[keycloak-1]/" -e 's/^/ /'