From 82a8414ffafb0ac967f5a19bd8fbbc386866dff4 Mon Sep 17 00:00:00 2001 From: admin Date: Wed, 5 Aug 2026 13:37:15 -0700 Subject: [PATCH] cutover.sh: interactive stale-state cleanup prompt before Phase 0 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Real incident: a run had both patroni-0 and patroni-1 stuck forever on "waiting for standby_leader to bootstrap", never even attempting to race for the role. Root cause was leftover etcd/patroni data on disk from a prior interrupted run (operator stopped it short) — the postgresqlha stack itself was gone, but etcd-1/2/3-data still had persisted raft state including a real /service/postgres-ha/initialize key and old replication slot records. Fresh Patroni nodes booting against that non-fresh etcd correctly concluded the cluster already existed and deferred forever waiting for a leader that could never appear, since nobody actually held the lock. rollback.sh's own data-dir wipe only fires when it detects the HA stack IS currently present (Case D/E) — if the stack was already gone by the time cleanup ran, its Case A path never touches the data dirs, leaving exactly this trap. Added a "Pre-Phase-0" check that runs before preflight.sh's ~6+ minute pg_dumpall: detects a still-present postgresqlha stack OR non-empty etcd-*/patroni-*-data left over from a prior run, and — since this is destructive and the operator explicitly wants this to be a deliberate choice, not silent automatic cleanup — prompts interactively before tearing down/wiping. Non-interactive sessions (no tty) hard-fail with a clear message rather than guessing; AUTO_CLEANUP=yes in the environment skips the prompt for deliberate unattended re-runs. Legacy production data is never touched by any of this. --- postgresql/cutover/cutover.sh | 154 ++++++++++++++++++++++++++++++---- 1 file changed, 136 insertions(+), 18 deletions(-) diff --git a/postgresql/cutover/cutover.sh b/postgresql/cutover/cutover.sh index d55357e..0573072 100644 --- a/postgresql/cutover/cutover.sh +++ b/postgresql/cutover/cutover.sh @@ -101,23 +101,21 @@ # 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. +# auto-rollback mid-copy. FIXED: both windows extended (and later +# re-tuned further by direct operator edits in git — see commit +# history for exact current values of PHASE1_MAX_WAIT/ +# PHASE2_MAX_WAIT) 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. # # 2026 run #3 follow-up (operator request, no new failure observed yet): # Phase 2's cascade-replica bootstrap adds an EXTRA network/streaming # hop on top of the same basebackup workload Phase 1 already does # (patroni-0/1's loser bootstraps FROM the winner, not from legacy # directly) — plausibly slower than Phase 1's copy, not just equal to -# it. Phase 2's window is extended further, from 1200s (20 min) to -# 2100s (35 min), specifically to give more margin on this second hop. -# Phase 1's window is intentionally left at 1200s (20 min) — it -# already matches the directly-observed 8-11 min precedent with -# comfortable headroom, and its bootstrap source (legacy directly) is -# the case we actually have real timing data for. +# it. Phase 2's window was extended further than Phase 1's for this +# reason (see current PHASE2_MAX_WAIT value below). # # 2026 run #4 — Phase 2's lag check was a SILENT NO-OP; found after a # real run passed Phase 1/2 cleanly (patroni-0 reached standby_leader, @@ -149,6 +147,35 @@ # ADR-0001 note), not just "field happened to be empty because we asked # the wrong node." Phase 4's (informational, non-gating) lag log line # updated to use the same corrected function for consistency. +# +# 2026 run #5 — BOTH nodes stuck forever on "waiting for standby_leader +# to bootstrap", never even attempting to race for the role, on a run +# that started completely fresh (operator confirmed no other changes). +# Root cause: a PRIOR run had been interrupted (operator stopped it +# short) without a clean rollback.sh pass, leaving the etcd data +# directories (etcd-1/2/3-data) non-empty on disk even though the +# postgresqlha STACK itself was already gone. etcd's own persisted raft +# state still had /service/postgres-ha/initialize set (a real system +# identifier from the earlier attempt) plus a /service/postgres-ha/status +# key listing old replication slots — so when the new run's patroni-0/1 +# containers (with genuinely fresh, empty PGDATA) came up against this +# NOT-actually-fresh etcd, Patroni correctly concluded "this cluster +# already exists, someone else must already be the leader" and both +# nodes deferred forever waiting for a leader that could never appear +# (nobody actually holds the lock). rollback.sh's own data-dir wipe only +# runs when it detects the postgresqlha stack IS currently present (its +# Case D/E paths) — if the stack was already gone by the time rollback +# logic ran (e.g. an operator-initiated stop before rollback.sh got a +# chance to run), its Case A path does NOT wipe data dirs, leaving +# exactly this trap for the next run. FIXED: added a "Pre-Phase-0" check +# (below, before preflight.sh even runs) that detects a still-present +# postgresqlha stack OR non-empty etcd-*/patroni-*-data directories left +# over from a prior run, and — since this is destructive (wipes data) and +# the operator explicitly asked for this to be an interactive decision, +# not silently automatic — PROMPTS before cleaning up. See that section +# for the exact detection logic, the prompt itself, and the +# AUTO_CLEANUP=yes escape hatch for unattended re-runs where the operator +# has already decided cleanup is always wanted. set -uo pipefail # NOTE: deliberately not -e — every phase below checks # its own command's exit status explicitly so we can @@ -311,6 +338,98 @@ log "a consumer of the DB being migrated. If this script exits nonzero" log "before completing rollback, follow RUNBOOK.md section 4 manually via" log "direct SSH — do not assume this chat will remain usable to help." +# ── Pre-Phase-0: stale-state detection & optional interactive cleanup ── +# See header "FIX LOG", 2026 run #5, for the full incident this addresses: +# a prior interrupted run can leave etcd-*/patroni-*-data non-empty on +# disk (or the postgresqlha stack itself still deployed) even after the +# stack is gone — and a fresh Patroni bootstrap against non-fresh etcd +# state hangs BOTH nodes forever waiting for a leader that will never +# appear, since etcd already "remembers" the cluster as initialized. +# This check runs BEFORE preflight.sh's ~6+ minute pg_dumpall so a +# doomed run doesn't waste that time before the operator gets a chance +# to intervene. Destructive (wipes data dirs) — per explicit operator +# request, this is an INTERACTIVE prompt, not silent automatic cleanup. +# For unattended re-runs where cleanup should always happen without a +# human present, set AUTO_CLEANUP=yes in the environment beforehand. +log "--- Pre-Phase-0: checking for stale state from a prior interrupted run ---" + +STALE_FOUND=0 +STALE_DETAILS=() + +if docker stack ls --format '{{.Name}}' 2>/dev/null | grep -qx "${HA_STACK}"; then + STALE_FOUND=1 + STALE_DETAILS+=("the ${HA_STACK} stack is already deployed (a previous run may still be in progress, or was stopped without a clean rollback.sh pass)") +fi + +for d in etcd-1-data etcd-2-data etcd-3-data patroni-0-data patroni-1-data; do + DIR="/volume1/docker/PostgreSQL/${d}" + if [ -d "$DIR" ] && [ -n "$(ls -A "$DIR" 2>/dev/null)" ]; then + STALE_FOUND=1 + STALE_DETAILS+=("${DIR} is non-empty (leftover from a prior run — etcd in particular will remember the old cluster as already-initialized and cause both Patroni nodes to hang forever waiting for a leader)") + fi +done + +if [ "$STALE_FOUND" -eq 1 ]; then + warn "Detected possible stale state from a previous cutover attempt:" + for detail in "${STALE_DETAILS[@]}"; do + warn " - ${detail}" + done + warn "Proceeding without cleaning this up is very likely to reproduce the" + warn "2026-08-05 incident where BOTH patroni-0 and patroni-1 sat forever" + warn "on 'waiting for standby_leader to bootstrap', never even attempting" + warn "to race for the role — see the ADR-0001 note, Session Update 9." + + AUTO_CLEANUP="${AUTO_CLEANUP:-}" + DO_CLEANUP="" + if [ "$AUTO_CLEANUP" = "yes" ]; then + log "AUTO_CLEANUP=yes set in environment — cleaning up automatically, no prompt." + DO_CLEANUP="y" + elif [ -t 0 ]; then + read -rp "[cutover] Clean up this stale state now before proceeding? This tears down any existing ${HA_STACK} stack and wipes etcd-*/patroni-*-data. Legacy production data (postgresql_postgresql, data-17) is NEVER touched by this. [y/N] " DO_CLEANUP + else + trigger_rollback "Stale state detected from a prior run and this session is non-interactive (no tty to prompt) — refusing to guess. Re-run interactively to be prompted, set AUTO_CLEANUP=yes beforehand to skip the prompt, or clean up manually first (see ADR-0001 note, Session Update 9)." + fi + + if [[ "$DO_CLEANUP" =~ ^[Yy] ]]; then + log "Operator confirmed — cleaning up stale state..." + if docker stack ls --format '{{.Name}}' 2>/dev/null | grep -qx "${HA_STACK}"; then + log "Tearing down existing ${HA_STACK} stack..." + docker stack rm "${HA_STACK}" + log "Waiting for tasks to actually finish shutting down (docker stack rm returns immediately)..." + for i in $(seq 1 24); do + REMAINING=$(docker stack ps "${HA_STACK}" 2>/dev/null | grep -c . || true) + if [ "$REMAINING" -eq 0 ]; then + break + fi + sleep 5 + done + REMAINING=$(docker stack ps "${HA_STACK}" 2>/dev/null | grep -c . || true) + if [ "$REMAINING" -gt 0 ]; then + trigger_rollback "${HA_STACK} still shows ${REMAINING} task(s) after 120s wait during stale-state cleanup — unsafe to wipe data dirs while tasks may still be shutting down." + fi + log "Confirmed: ${HA_STACK} stack fully removed." + fi + for d in etcd-1-data etcd-2-data etcd-3-data patroni-0-data patroni-1-data; do + DIR="/volume1/docker/PostgreSQL/${d}" + if [ -d "$DIR" ]; then + rm -rf "$DIR" + mkdir -p "$DIR" + log " wiped and recreated: ${DIR}" + fi + done + log "Stale-state cleanup complete — proceeding with a genuinely clean slate." + else + warn "Proceeding WITHOUT cleanup, per operator choice." + warn "If Phase 1 hangs with both nodes stuck on 'waiting for standby_leader" + warn "to bootstrap' and never attempting to race for the role, this stale" + warn "state is almost certainly why — stop this run and re-run choosing" + warn "cleanup, or run manually: docker stack rm ${HA_STACK}; then wipe" + warn "etcd-*/patroni-*-data under /volume1/docker/PostgreSQL/ before retrying." + fi +else + log "No stale state detected from a prior run — proceeding." +fi + # ── Phase 0: preflight ──────────────────────────────────────────────── log "--- Phase 0: preflight ---" if ! bash "${CUTOVER_DIR}/preflight.sh"; then @@ -346,11 +465,11 @@ fi # 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. +# FIXED (see header "FIX LOG" item b): window extended — 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="" @@ -387,8 +506,7 @@ log "--- Phase 2: confirm streaming lag = 0 (cascade replica: ${REPLICA_HOST}) - # FURTHER EXTENDED (see header "FIX LOG", 2026 run #3 follow-up, operator # request): this cascade-replica bootstrap adds an EXTRA network/streaming # hop on top of the same basebackup workload, so its window is now longer -# than Phase 1's rather than merely equal to it — extended from 1200s -# (20 min) to 2100s (35 min), with per-poll data-dir size logging. +# than Phase 1's rather than merely equal to it. # FIXED (see header "FIX LOG", 2026 run #4): the lag check itself was a # silent no-op — see cluster_member_lag_state() above for the real fix. # This gate now queries ${LEADER_HOST}'s /cluster view of ${REPLICA_HOST}