From 29cd73eabc55904b4010daaad602560b75171f52 Mon Sep 17 00:00:00 2001 From: admin Date: Tue, 4 Aug 2026 00:40:20 -0700 Subject: [PATCH] cutover.sh: dynamic standby_leader detection + extended bootstrap wait windows MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two real-run bugs found and fixed: 1. Phase 1 hardcoded patroni-1 as the expected standby_leader. The bootstrap-race winner is actually nondeterministic (Patroni/etcd lock race) — the original prod attempt had patroni-0 win it instead, which the dry run never exercised. Fixed by polling BOTH patroni-0 and patroni-1 each iteration and capturing whichever wins into $LEADER_HOST, with the other becoming $REPLICA_HOST. Every later phase (2,3,4,5,6,8,10) now references $LEADER_HOST/$REPLICA_HOST instead of hardcoded hostnames. 2. Phase 1's wait window (240s) and Phase 2's (300s) were both far shorter than the observed real basebackup duration for a ~42GB cluster (8-11 minutes per prior dry-run/live polling). The role only flips to standby_leader/replica AFTER the full copy completes, so both timeouts could fire — and did — while a legitimate basebackup was still in-progress, triggering a false-negative rollback. Both windows extended to 1200s (20 min), with per-poll data-dir size logging (timeout-guarded du -sh) so progress is observable instead of a silent binary wait. --- postgresql/cutover/cutover.sh | 176 +++++++++++++++++++++++++--------- 1 file changed, 130 insertions(+), 46 deletions(-) diff --git a/postgresql/cutover/cutover.sh b/postgresql/cutover/cutover.sh index 3171558..8daf1eb 100644 --- a/postgresql/cutover/cutover.sh +++ b/postgresql/cutover/cutover.sh @@ -79,6 +79,33 @@ # "healthy, no content" response for that kind of endpoint. The health # checks below (and the matching ones in rollback.sh) now accept any 2xx # status code, not just literal 200. +# +# 2026 run #2 hit TWO further real bugs in Phase 1/2, both fixed below: +# a) Phase 1 hardcoded patroni-1 as the expected standby_leader. The +# Patroni/etcd bootstrap-race winner is actually nondeterministic — +# it's a lock race, not something the compose file controls. The +# ADR-0001 dry run happened to have patroni-1 win it, but the +# earlier real production attempt (see ADR-0001 note) had patroni-0 +# win instead — proof both outcomes genuinely occur. A check that +# only ever accepts patroni-1 fails outright half the time even when +# the cluster is perfectly healthy. FIXED by polling BOTH patroni-0 +# AND patroni-1 every iteration; whichever reports standby_leader +# first is captured as $LEADER_HOST, the other becomes +# $REPLICA_HOST. Every phase from here on (2,3,4,5,6,8,10) uses +# these two variables instead of a hardcoded hostname. +# b) Phase 1's wait window (240s) and Phase 2's (300s) were both far +# shorter than the real observed basebackup duration for this +# cluster's ~42GB dataset — prior polling (both the dry run and the +# earlier real attempt) showed a full basebackup_fast_xlog copy +# takes roughly 8-11 minutes. The role only flips to +# standby_leader/replica AFTER the copy fully completes, so both +# timeouts could fire (and did) while a completely legitimate +# basebackup was still in progress, triggering a false-negative +# auto-rollback mid-copy. FIXED: both windows extended to 1200s +# (20 min) with a per-poll `du -sh` (timeout-guarded, since du has +# been observed to hang on CephFS under heavy concurrent write load) +# logged on every iteration, so progress is directly observable +# instead of a silent binary wait. set -uo pipefail # NOTE: deliberately not -e — every phase below checks # its own command's exit status explicitly so we can @@ -142,6 +169,26 @@ legacy_cid() { docker ps -q --filter "name=${LEGACY_SERVICE}" | head -1 } +# Maps a Patroni hostname to its bind-mounted data directory on the host, +# used for progress logging during basebackup (a full ~42GB copy has been +# observed to take 8-11 minutes — see Phase 1/2 comments above and below). +patroni_data_dir() { + case "$1" in + patroni-0) echo "/volume1/docker/PostgreSQL/patroni-0-data" ;; + patroni-1) echo "/volume1/docker/PostgreSQL/patroni-1-data" ;; + *) echo "" ;; + esac +} + +# timeout-guarded `du -sh` — du has been observed to hang on CephFS while +# a basebackup is writing heavily to the same volume. Returns "?" rather +# than blocking the whole polling loop if it doesn't return quickly. +data_dir_size() { + local dir="$1" out + out=$(timeout 10 du -sh "$dir" 2>/dev/null | awk '{print $1}') + echo "${out:-?}" +} + # Raw-socket HTTP GET via /dev/tcp, executed inside the legacy container. # Avoids assuming curl exists in the legacy postgres:17 image. # Args: host port path @@ -237,40 +284,77 @@ if ! wait_for_stack_running "${HA_STACK}" 6 180; then trigger_rollback "postgresqlha stack did not reach 6 running tasks within 180s." fi -log "Confirming patroni-1 reaches standby_leader..." -ROLE="" -for i in $(seq 1 24); do - ROLE="$(patroni_role patroni-1)" - [ "$ROLE" = "standby_leader" ] && break - sleep 10 +# FIXED (see header "FIX LOG" item a): the standby_leader bootstrap race +# winner is nondeterministic — poll BOTH nodes, whichever wins becomes +# $LEADER_HOST, the other becomes $REPLICA_HOST. Every later phase uses +# these two variables instead of a hardcoded hostname. +# FIXED (see header "FIX LOG" item b): window extended from 240s to 1200s +# (20 min) — a full ~42GB basebackup has been observed to take 8-11 +# minutes, and the role only flips AFTER it fully completes. Each poll +# logs both nodes' role AND data-dir size so progress is directly +# observable instead of a silent binary wait. +log "Confirming standby_leader bootstrap completes (winner is nondeterministic — polling BOTH patroni-0 and patroni-1; a full ~42GB basebackup has been observed to take 8-11 minutes, so this window is generous)..." +LEADER_HOST="" +REPLICA_HOST="" +PHASE1_MAX_WAIT=1200 +PHASE1_POLL_INTERVAL=15 +waited=0 +ROLE0="" +ROLE1="" +while [ "$waited" -lt "$PHASE1_MAX_WAIT" ]; do + ROLE0="$(patroni_role patroni-0)" + ROLE1="$(patroni_role patroni-1)" + SIZE0="$(data_dir_size "$(patroni_data_dir patroni-0)")" + SIZE1="$(data_dir_size "$(patroni_data_dir patroni-1)")" + log "patroni-0 role=${ROLE0:-} data_dir=${SIZE0} | patroni-1 role=${ROLE1:-} data_dir=${SIZE1} (${waited}s/${PHASE1_MAX_WAIT}s elapsed)" + if [ "$ROLE0" = "standby_leader" ]; then + LEADER_HOST="patroni-0"; REPLICA_HOST="patroni-1"; break + fi + if [ "$ROLE1" = "standby_leader" ]; then + LEADER_HOST="patroni-1"; REPLICA_HOST="patroni-0"; break + fi + sleep "$PHASE1_POLL_INTERVAL" + waited=$((waited + PHASE1_POLL_INTERVAL)) done -if [ "$ROLE" != "standby_leader" ]; then - trigger_rollback "patroni-1 did not reach standby_leader role within 240s (last observed: '${ROLE}')." +if [ -z "$LEADER_HOST" ]; then + trigger_rollback "Neither patroni-0 nor patroni-1 reached standby_leader role within ${PHASE1_MAX_WAIT}s. Last observed: patroni-0='${ROLE0}' patroni-1='${ROLE1}'." fi -log "PASS: Phase 1 — patroni-1 is standby_leader" +log "PASS: Phase 1 — ${LEADER_HOST} is standby_leader (bootstrap winner determined dynamically); ${REPLICA_HOST} will be the cascade replica" # ── Phase 2: wait for streaming lag = 0 ──────────────────────────────── -log "--- Phase 2: confirm streaming lag = 0 ---" +log "--- Phase 2: confirm streaming lag = 0 (cascade replica: ${REPLICA_HOST}) ---" +# FIXED (see header "FIX LOG" item b): ${REPLICA_HOST} is itself +# bootstrapping via a full basebackup from ${LEADER_HOST} — same +# 8-11-min-for-~42GB precedent as Phase 1. Window extended from 300s to +# 1200s (20 min), with per-poll data-dir size logging. +log "Note: ${REPLICA_HOST} is bootstrapping via a full basebackup from ${LEADER_HOST} — same basebackup precedent as Phase 1, so this window is generous." CONSECUTIVE_ZERO=0 -for i in $(seq 1 30); do - P0_ROLE="$(patroni_role patroni-0)" - LAG_INFO="$(patroni_lag patroni-0)" - log "patroni-0 role=${P0_ROLE} lag_info=${LAG_INFO}" - if [ "$P0_ROLE" = "replica" ] && { [ -z "$LAG_INFO" ] || echo "$LAG_INFO" | grep -q '"lag": *0\b\|streaming'; }; then +PHASE2_MAX_WAIT=1200 +PHASE2_POLL_INTERVAL=15 +waited=0 +REPLICA_ROLE="" +LAG_INFO="" +while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do + REPLICA_ROLE="$(patroni_role "$REPLICA_HOST")" + LAG_INFO="$(patroni_lag "$REPLICA_HOST")" + SIZE="$(data_dir_size "$(patroni_data_dir "$REPLICA_HOST")")" + log "${REPLICA_HOST} role=${REPLICA_ROLE:-} lag_info=${LAG_INFO} data_dir=${SIZE} (${waited}s/${PHASE2_MAX_WAIT}s elapsed)" + if [ "$REPLICA_ROLE" = "replica" ] && { [ -z "$LAG_INFO" ] || echo "$LAG_INFO" | grep -q '"lag": *0\b\|streaming'; }; then CONSECUTIVE_ZERO=$((CONSECUTIVE_ZERO + 1)) else CONSECUTIVE_ZERO=0 fi [ "$CONSECUTIVE_ZERO" -ge 3 ] && break - sleep 10 + sleep "$PHASE2_POLL_INTERVAL" + waited=$((waited + PHASE2_POLL_INTERVAL)) done if [ "$CONSECUTIVE_ZERO" -lt 3 ]; then - trigger_rollback "Streaming lag never reached 3 consecutive zero/streaming polls on patroni-0. Last state: role=${P0_ROLE} lag_info=${LAG_INFO}" + trigger_rollback "Streaming lag never reached 3 consecutive zero/streaming polls on ${REPLICA_HOST} within ${PHASE2_MAX_WAIT}s. Last state: role=${REPLICA_ROLE} lag_info=${LAG_INFO}" fi -log "PASS: Phase 2 — streaming confirmed, lag=0 for 3 consecutive polls" +log "PASS: Phase 2 — streaming confirmed, lag=0 for 3 consecutive polls on ${REPLICA_HOST}" # ── Phase 3: pre-promotion canary write/propagation check ───────────── -log "--- Phase 3: pre-promotion canary (legacy -> patroni-0 cascade replica) ---" +log "--- Phase 3: pre-promotion canary (legacy -> ${REPLICA_HOST} cascade replica) ---" LEGACY_CID="$(legacy_cid)" if [ -z "$LEGACY_CID" ]; then trigger_rollback "Could not find legacy container for canary write." @@ -282,7 +366,7 @@ if [ $? -ne 0 ]; then fi FOUND=0 for i in $(seq 1 5); do - RESULT=$(docker exec "$LEGACY_CID" bash -c "psql -h patroni-0 -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY_VAL}';\"" 2>/dev/null) + RESULT=$(docker exec "$LEGACY_CID" bash -c "psql -h ${REPLICA_HOST} -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY_VAL}';\"" 2>/dev/null) if [ "$RESULT" = "1" ]; then FOUND=1 break @@ -290,9 +374,9 @@ for i in $(seq 1 5); do sleep 1 done if [ "$FOUND" -ne 1 ]; then - trigger_rollback "Canary row did not propagate to patroni-0 within 5s. standby_cluster streaming is not working as expected." + trigger_rollback "Canary row did not propagate to ${REPLICA_HOST} within 5s. standby_cluster streaming is not working as expected." fi -log "PASS: Phase 3 — canary write propagated to patroni-0 within 5s" +log "PASS: Phase 3 — canary write propagated to ${REPLICA_HOST} within 5s" # ── Phase 4: flip legacy to read-only ─────────────────────────────────── log "--- Phase 4: flip legacy read-only ---" @@ -306,35 +390,35 @@ if [ "$RO_STATE" != "on" ]; then fi log "Legacy confirmed read-only. Draining one more lag poll to confirm quiescence..." sleep 5 -LAG_INFO="$(patroni_lag patroni-0)" -log "Post-read-only lag check: ${LAG_INFO}" +LAG_INFO="$(patroni_lag "$REPLICA_HOST")" +log "Post-read-only lag check (${REPLICA_HOST}): ${LAG_INFO}" log "PASS: Phase 4 — legacy is read-only, no further writes possible there" # ── Phase 5: promote Patroni ───────────────────────────────────────── -log "--- Phase 5: promote patroni-1 (remove standby_cluster from DCS config) ---" +log "--- Phase 5: promote ${LEADER_HOST} (remove standby_cluster from DCS config) ---" log "⚠️ Highest-scrutiny phase — see script header for the documented deviation from the dry-run's proven method (using Patroni's official REST PATCH /config instead). Manual etcdctl fallback documented above and in RUNBOOK.md if needed." PATRONI_PASS=$(docker exec "$LEGACY_CID" cat /run/secrets/postgresql_patroni_password 2>/dev/null) if [ -z "$PATRONI_PASS" ]; then - # legacy container may not have this secret mounted — fall back to reading via patroni-1 itself if reachable, else hard-fail before touching anything + # legacy container may not have this secret mounted — fall back to reading via the leader host itself if reachable, else hard-fail before touching anything trigger_rollback "Could not read postgresql_patroni_password secret needed for the promotion PATCH call. Nothing promoted yet." fi -log "Smoke-test: GET /config on patroni-1 before attempting the PATCH..." -CONFIG_CHECK=$(http_get_via_legacy patroni-1 8008 "/config") +log "Smoke-test: GET /config on ${LEADER_HOST} before attempting the PATCH..." +CONFIG_CHECK=$(http_get_via_legacy "$LEADER_HOST" 8008 "/config") if ! echo "$CONFIG_CHECK" | grep -qi "standby_cluster"; then - trigger_rollback "GET /config on patroni-1 did not show a standby_cluster key as expected before promotion — refusing to PATCH against an unexpected state. Raw response logged above for review." + trigger_rollback "GET /config on ${LEADER_HOST} did not show a standby_cluster key as expected before promotion — refusing to PATCH against an unexpected state. Raw response logged above for review." fi log "Smoke-test passed — standby_cluster key confirmed present pre-promotion." -PATCH_RESPONSE=$(http_patch_via_legacy patroni-1 8008 "/config" "patroni" "$PATRONI_PASS" '{"standby_cluster": null}') +PATCH_RESPONSE=$(http_patch_via_legacy "$LEADER_HOST" 8008 "/config" "patroni" "$PATRONI_PASS" '{"standby_cluster": null}') log "PATCH /config response: ${PATCH_RESPONSE}" -log "Waiting for patroni-1 to transition standby_leader -> leader (expect ~15-30s per dry-run drills)..." +log "Waiting for ${LEADER_HOST} to transition standby_leader -> leader (expect ~15-30s per dry-run drills)..." PROMOTED=0 for i in $(seq 1 12); do - ROLE="$(patroni_role patroni-1)" - log "patroni-1 role: ${ROLE}" + ROLE="$(patroni_role "$LEADER_HOST")" + log "${LEADER_HOST} role: ${ROLE}" if [ "$ROLE" = "leader" ]; then PROMOTED=1 break @@ -342,22 +426,22 @@ for i in $(seq 1 12); do sleep 5 done if [ "$PROMOTED" -ne 1 ]; then - trigger_rollback "patroni-1 did not reach 'leader' role within 60s of the promotion PATCH. Last observed role: '${ROLE}'. Manual etcdctl fallback is documented in this script's header / RUNBOOK.md if the operator wants to investigate before accepting the automatic rollback." + trigger_rollback "${LEADER_HOST} did not reach 'leader' role within 60s of the promotion PATCH. Last observed role: '${ROLE}'. Manual etcdctl fallback is documented in this script's header / RUNBOOK.md if the operator wants to investigate before accepting the automatic rollback." fi -IN_RECOVERY=$(docker exec "$LEGACY_CID" bash -c 'psql -h patroni-1 -U "$POSTGRES_USER" -tAc "SELECT pg_is_in_recovery();"' 2>/dev/null | tr -d '[:space:]') +IN_RECOVERY=$(docker exec "$LEGACY_CID" bash -c "psql -h ${LEADER_HOST} -U \"\$POSTGRES_USER\" -tAc \"SELECT pg_is_in_recovery();\"" 2>/dev/null | tr -d '[:space:]') if [ "$IN_RECOVERY" != "f" ]; then - trigger_rollback "patroni-1 reports role=leader but pg_is_in_recovery() = '${IN_RECOVERY}' (expected 'f'). Not trusting this as a genuine promotion." + trigger_rollback "${LEADER_HOST} reports role=leader but pg_is_in_recovery() = '${IN_RECOVERY}' (expected 'f'). Not trusting this as a genuine promotion." fi -log "PASS: Phase 5 — patroni-1 is genuine writable leader, pg_is_in_recovery=f" +log "PASS: Phase 5 — ${LEADER_HOST} is genuine writable leader, pg_is_in_recovery=f" # ── Phase 6: confirm HAProxy would see a healthy backend ────────────── log "--- Phase 6: confirm healthy backend before touching DNS ---" -PRIMARY_CHECK=$(http_get_via_legacy patroni-1 8008 "/primary") +PRIMARY_CHECK=$(http_get_via_legacy "$LEADER_HOST" 8008 "/primary") if ! echo "$PRIMARY_CHECK" | grep -q "200 OK"; then - trigger_rollback "patroni-1 does not answer 200 on GET /primary post-promotion. Raw response: ${PRIMARY_CHECK}" + trigger_rollback "${LEADER_HOST} does not answer 200 on GET /primary post-promotion. Raw response: ${PRIMARY_CHECK}" fi -log "PASS: Phase 6 — patroni-1 answers 200 on /primary, HAProxy's healthcheck will pass" +log "PASS: Phase 6 — ${LEADER_HOST} answers 200 on /primary, HAProxy's healthcheck will pass" # ── Phase 7: deploy final HAProxy with postgresql/db aliases ────────── log "--- Phase 7: deploy postgresql-ha-final.yaml (adds postgresql/db aliases) ---" @@ -398,11 +482,11 @@ done if [ "$ALIAS_WRITE_OK" -ne 1 ]; then trigger_rollback "Never succeeded writing through the 'postgresql' alias after 10 attempts (~20s). See /tmp/cutover_phase8_attempt_*.log on docker-2 for the read-only/connection errors encountered." fi -log "Alias write succeeded on attempt ${i}. Confirming visibility on BOTH patroni-0 and patroni-1..." -V0=$(docker exec "$LEGACY_CID" bash -c "psql -h patroni-0 -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY2_VAL}';\"" 2>/dev/null) -V1=$(docker exec "$LEGACY_CID" bash -c "psql -h patroni-1 -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY2_VAL}';\"" 2>/dev/null) -if [ "$V0" != "1" ] || [ "$V1" != "1" ]; then - trigger_rollback "Alias-written canary row not visible on both nodes (patroni-0='${V0}' patroni-1='${V1}')." +log "Alias write succeeded on attempt ${i}. Confirming visibility on BOTH ${LEADER_HOST} and ${REPLICA_HOST}..." +VLEADER=$(docker exec "$LEGACY_CID" bash -c "psql -h ${LEADER_HOST} -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY2_VAL}';\"" 2>/dev/null) +VREPLICA=$(docker exec "$LEGACY_CID" bash -c "psql -h ${REPLICA_HOST} -U \"\$POSTGRES_USER\" -tAc \"SELECT 1 FROM _cutover_canary WHERE val = '${CANARY2_VAL}';\"" 2>/dev/null) +if [ "$VLEADER" != "1" ] || [ "$VREPLICA" != "1" ]; then + trigger_rollback "Alias-written canary row not visible on both nodes (${LEADER_HOST}='${VLEADER}' ${REPLICA_HOST}='${VREPLICA}')." fi log "PASS: Phase 8 — real client-path write through the alias succeeded and is visible on both nodes" @@ -439,7 +523,7 @@ if [ $? -ne 0 ]; then fi sleep 10 log "Confirming HAProxy backend still healthy post-legacy-stop..." -PRIMARY_CHECK2=$(http_get_via_legacy patroni-1 8008 "/primary" 2>/dev/null || true) +PRIMARY_CHECK2=$(http_get_via_legacy "$LEADER_HOST" 8008 "/primary" 2>/dev/null || true) # Note: legacy is now stopped, so http_get_via_legacy (which proxies via # the legacy container) will start failing itself shortly — this is # EXPECTED and is why this is the last check that uses that proxy method.