cutover.sh: dynamic standby_leader detection + extended bootstrap wait windows

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

@@ -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..."
+# FIXED (see header "FIX LOG" item a): the standby_leader bootstrap race
-ROLE=""
+# winner is nondeterministic — poll BOTH nodes, whichever wins becomes
-for i in $(seq 1 24); do
+# $LEADER_HOST, the other becomes $REPLICA_HOST. Every later phase uses
-  ROLE="$(patroni_role patroni-1)"
+# these two variables instead of a hardcoded hostname.
-  [ "$ROLE" = "standby_leader" ] && break
+# FIXED (see header "FIX LOG" item b): window extended from 240s to 1200s
-  sleep 10
+# (20 min) — a full ~42GB basebackup has been observed to take 8-11
-done
+# minutes, and the role only flips AFTER it fully completes. Each poll
-if [ "$ROLE" != "standby_leader" ]; then
+# logs both nodes' role AND data-dir size so progress is directly
-  trigger_rollback "patroni-1 did not reach standby_leader role within 240s (last observed: '${ROLE}')."
+# 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:-<none>} data_dir=${SIZE0} | patroni-1 role=${ROLE1:-<none>} 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
-log "PASS: Phase 1 — patroni-1 is standby_leader"
+  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 [ -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 — ${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
+PHASE2_MAX_WAIT=1200
-  P0_ROLE="$(patroni_role patroni-0)"
+PHASE2_POLL_INTERVAL=15
-  LAG_INFO="$(patroni_lag patroni-0)"
+waited=0
-  log "patroni-0 role=${P0_ROLE} lag_info=${LAG_INFO}"
+REPLICA_ROLE=""
-  if [ "$P0_ROLE" = "replica" ] && { [ -z "$LAG_INFO" ] || echo "$LAG_INFO" | grep -q '"lag": *0\b\|streaming'; }; then
+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:-<none>} 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)"
+LAG_INFO="$(patroni_lag "$REPLICA_HOST")"
-log "Post-read-only lag check: ${LAG_INFO}"
+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..."
+log "Smoke-test: GET /config on ${LEADER_HOST} before attempting the PATCH..."
-CONFIG_CHECK=$(http_get_via_legacy patroni-1 8008 "/config")
+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)"
+  ROLE="$(patroni_role "$LEADER_HOST")"
-  log "patroni-1 role: ${ROLE}"
+  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..."
+log "Alias write succeeded on attempt ${i}. Confirming visibility on BOTH ${LEADER_HOST} and ${REPLICA_HOST}..."
-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)
+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)
-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)
+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 [ "$V0" != "1" ] || [ "$V1" != "1" ]; then
+if [ "$VLEADER" != "1" ] || [ "$VREPLICA" != "1" ]; then
-  trigger_rollback "Alias-written canary row not visible on both nodes (patroni-0='${V0}' patroni-1='${V1}')."
+  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.