diff --git a/postgresql/cutover/cutover.sh b/postgresql/cutover/cutover.sh index 5c478b0..0936af1 100644 --- a/postgresql/cutover/cutover.sh +++ b/postgresql/cutover/cutover.sh @@ -68,8 +68,8 @@ # docker node inspect {} --format '{{.Spec.Labels.pg-role}}' # — Go's template engine cannot parse a bare `.pg-role` field reference # (the hyphen is invalid in that position), so the command errored -# silently (stderr was redirected to /dev/null) and returned empty every -# time, regardless of actual label state. FIXED below by switching to +# silently (stderr redirected to /dev/null) and always returned empty, +# regardless of actual label state. FIXED below by switching to # `docker node ls --filter "node.label=pg-role=primary"`, which uses # Docker's own filter syntax instead of Go template field access and # sidesteps the hyphen problem entirely. @@ -118,6 +118,37 @@ # 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. +# +# 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, +# patroni-1 basebackup completed, role flipped to "replica") but then +# failed Phase 3's canary write with "Canary row did not propagate to +# patroni-1 within 5s" moments later. Root cause: `patroni_lag()` queried +# the REPLICA's OWN `/patroni` endpoint for lag/replication_state — but +# Patroni only exposes per-connection replication lag (derived from +# pg_stat_replication) on the LEADER/standby_leader side; a plain +# replica's own `/patroni` response has no such field at all. So +# $LAG_INFO was ALWAYS empty, and Phase 2's gate: +# [ "$REPLICA_ROLE" = "replica" ] && { [ -z "$LAG_INFO" ] || ... ; } +# short-circuited permanently true on the `[ -z "$LAG_INFO" ]` branch — +# the lag check never actually ran. Phase 2 degraded to "did the role +# flip to replica 3 times in a row?", which can be true BEFORE the +# replica has actually caught up on WAL backlog from its own basebackup, +# especially right after a fresh cascade connection. Phase 3's real +# canary write then landed in exactly that still-catching-up window. +# FIXED: replaced patroni_lag() with cluster_member_lag_state(), which +# queries the LEADER's `/cluster` endpoint (works from either node, +# reflects live DCS state — same endpoint/shape directly verified in the +# original ADR-0001 dry run: member entries look like +# {"name": "patroni-1", "role": "replica", "state": "streaming", "lag": 0}) +# and extracts the SPECIFIC replica's "state"/"lag" fields from its own +# member object (members are flat JSON objects with no nested braces, so +# a bounded grep safely isolates exactly one member's fragment). Phase +# 2's gate now requires literal state=streaming AND (lag=0 or lag field +# absent — some responses omit it when lag is genuinely 0, per the +# 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. set -uo pipefail # NOTE: deliberately not -e — every phase below checks # its own command's exit status explicitly so we can @@ -235,12 +266,27 @@ patroni_role() { http_get_via_legacy "$host" 8008 "/patroni" | grep -o '"role"[^,}]*' | sed 's/.*: *"//;s/"$//' } -# Poll a Patroni node's /patroni endpoint for streaming lag against -# whichever host it's replicating from. Returns the numeric lag if found, -# empty otherwise (some responses omit it when lag is genuinely 0/absent). -patroni_lag() { - local host="$1" - http_get_via_legacy "$host" 8008 "/patroni" | grep -o '"replication_state"[^,}]*\|"lag"[^,}]*' | head -1 +# FIXED (see header "FIX LOG", 2026 run #4): a plain replica's OWN +# /patroni endpoint has NO lag/replication_state field — that data only +# exists on the LEADER/standby_leader side (derived from +# pg_stat_replication). Query the LEADER's /cluster endpoint instead and +# extract ONE SPECIFIC member's "state"/"lag" fields from its member +# object. Member objects are flat (no nested braces), so a bounded grep +# safely isolates exactly one member's JSON fragment before parsing. +# Args: query_host (should be the LEADER/standby_leader) member_name +# (the node whose lag/state you actually want, e.g. the replica) +# Prints: "state= lag=" (either may be if absent) +cluster_member_lag_state() { + local query_host="$1" member_name="$2" cluster_json member_json state lag + cluster_json="$(http_get_via_legacy "$query_host" 8008 "/cluster")" + member_json="$(echo "$cluster_json" | grep -o "{\"name\": *\"${member_name}\"[^}]*}")" + if [ -z "$member_json" ]; then + echo "state= lag=" + return + fi + state="$(echo "$member_json" | grep -o '"state": *"[^"]*"' | sed 's/.*"state": *"//;s/"$//')" + lag="$(echo "$member_json" | grep -o '"lag": *[0-9][0-9]*' | sed 's/.*: *//')" + echo "state=${state:-} lag=${lag:-}" } wait_for_stack_running() { @@ -343,6 +389,10 @@ log "--- Phase 2: confirm streaming lag = 0 (cascade replica: ${REPLICA_HOST}) - # 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. +# 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} +# and requires literal state=streaming AND (lag=0 or lag absent). log "Note: ${REPLICA_HOST} is bootstrapping via a full basebackup from ${LEADER_HOST} — an extra hop beyond Phase 1's basebackup, so this window is deliberately longer than Phase 1's." CONSECUTIVE_ZERO=0 PHASE2_MAX_WAIT=2100 @@ -352,10 +402,10 @@ REPLICA_ROLE="" LAG_INFO="" while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do REPLICA_ROLE="$(patroni_role "$REPLICA_HOST")" - LAG_INFO="$(patroni_lag "$REPLICA_HOST")" + LAG_INFO="$(cluster_member_lag_state "$LEADER_HOST" "$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 + log "${REPLICA_HOST} role=${REPLICA_ROLE:-} ${LAG_INFO} data_dir=${SIZE} (${waited}s/${PHASE2_MAX_WAIT}s elapsed)" + if [ "$REPLICA_ROLE" = "replica" ] && echo "$LAG_INFO" | grep -q "state=streaming" && ! echo "$LAG_INFO" | grep -qE "lag=[1-9]"; then CONSECUTIVE_ZERO=$((CONSECUTIVE_ZERO + 1)) else CONSECUTIVE_ZERO=0 @@ -365,9 +415,9 @@ while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do waited=$((waited + PHASE2_POLL_INTERVAL)) done if [ "$CONSECUTIVE_ZERO" -lt 3 ]; then - 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}" + 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}" fi -log "PASS: Phase 2 — streaming confirmed, lag=0 for 3 consecutive polls on ${REPLICA_HOST}" +log "PASS: Phase 2 — streaming confirmed, lag=0/streaming for 3 consecutive polls on ${REPLICA_HOST}" # ── Phase 3: pre-promotion canary write/propagation check ───────────── log "--- Phase 3: pre-promotion canary (legacy -> ${REPLICA_HOST} cascade replica) ---" @@ -406,7 +456,7 @@ 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 "$REPLICA_HOST")" +LAG_INFO="$(cluster_member_lag_state "$LEADER_HOST" "$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"