cutover.sh: fix Phase 2's lag check — was a silent no-op
ci/woodpecker/push/deploy Pipeline was successful

Root cause of a real run's failure: Phase 2 passed (patroni-0 reached
standby_leader, patroni-1's basebackup completed, role flipped to
"replica"), but Phase 3's canary write then failed to propagate within
5s moments later. patroni_lag() queried the REPLICA's own /patroni
endpoint for lag data — but that field only exists on the LEADER side
(derived from pg_stat_replication); a replica's own /patroni response
never has it. So $LAG_INFO was always empty, and Phase 2's gate
`[ -z "$LAG_INFO" ] || ...` short-circuited permanently true — the lag
check never actually ran. Phase 2 degraded to "did role flip to replica
3x in a row", which can be true before the replica has genuinely caught
up on WAL backlog from its own basebackup.

Fixed by replacing patroni_lag() with cluster_member_lag_state(), which
queries the LEADER's /cluster endpoint (real pg_stat_replication-backed
data, same shape verified in the original dry run) and extracts the
specific replica's state/lag fields from its member object. Phase 2 now
requires literal state=streaming AND (lag=0 or absent), not just "field
was empty because we asked the wrong node." Phase 4's informational lag
log line updated to match.
This commit is contained in:
2026-08-05 08:11:15 -07:00
parent 8f860ab14d
commit b2b86a668d
+64 -14
View File
@@ -68,8 +68,8 @@
# docker node inspect {} --format '{{.Spec.Labels.pg-role}}' # docker node inspect {} --format '{{.Spec.Labels.pg-role}}'
# — Go's template engine cannot parse a bare `.pg-role` field reference # — Go's template engine cannot parse a bare `.pg-role` field reference
# (the hyphen is invalid in that position), so the command errored # (the hyphen is invalid in that position), so the command errored
# silently (stderr was redirected to /dev/null) and returned empty every # silently (stderr redirected to /dev/null) and always returned empty,
# time, regardless of actual label state. FIXED below by switching to # regardless of actual label state. FIXED below by switching to
# `docker node ls --filter "node.label=pg-role=primary"`, which uses # `docker node ls --filter "node.label=pg-role=primary"`, which uses
# Docker's own filter syntax instead of Go template field access and # Docker's own filter syntax instead of Go template field access and
# sidesteps the hyphen problem entirely. # sidesteps the hyphen problem entirely.
@@ -118,6 +118,37 @@
# already matches the directly-observed 8-11 min precedent with # already matches the directly-observed 8-11 min precedent with
# comfortable headroom, and its bootstrap source (legacy directly) is # comfortable headroom, and its bootstrap source (legacy directly) is
# the case we actually have real timing data for. # 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 set -uo pipefail # NOTE: deliberately not -e — every phase below checks
# its own command's exit status explicitly so we can # 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/"$//' http_get_via_legacy "$host" 8008 "/patroni" | grep -o '"role"[^,}]*' | sed 's/.*: *"//;s/"$//'
} }
# Poll a Patroni node's /patroni endpoint for streaming lag against # FIXED (see header "FIX LOG", 2026 run #4): a plain replica's OWN
# whichever host it's replicating from. Returns the numeric lag if found, # /patroni endpoint has NO lag/replication_state field — that data only
# empty otherwise (some responses omit it when lag is genuinely 0/absent). # exists on the LEADER/standby_leader side (derived from
patroni_lag() { # pg_stat_replication). Query the LEADER's /cluster endpoint instead and
local host="$1" # extract ONE SPECIFIC member's "state"/"lag" fields from its member
http_get_via_legacy "$host" 8008 "/patroni" | grep -o '"replication_state"[^,}]*\|"lag"[^,}]*' | head -1 # 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=<value> lag=<value>" (either may be <none> 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=<none> lag=<none>"
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:-<none>} lag=${lag:-<none>}"
} }
wait_for_stack_running() { 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 # 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 # 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. # (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." 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 CONSECUTIVE_ZERO=0
PHASE2_MAX_WAIT=2100 PHASE2_MAX_WAIT=2100
@@ -352,10 +402,10 @@ REPLICA_ROLE=""
LAG_INFO="" LAG_INFO=""
while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do
REPLICA_ROLE="$(patroni_role "$REPLICA_HOST")" 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")")" 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)" log "${REPLICA_HOST} role=${REPLICA_ROLE:-<none>} ${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 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)) CONSECUTIVE_ZERO=$((CONSECUTIVE_ZERO + 1))
else else
CONSECUTIVE_ZERO=0 CONSECUTIVE_ZERO=0
@@ -365,9 +415,9 @@ while [ "$waited" -lt "$PHASE2_MAX_WAIT" ]; do
waited=$((waited + PHASE2_POLL_INTERVAL)) waited=$((waited + PHASE2_POLL_INTERVAL))
done done
if [ "$CONSECUTIVE_ZERO" -lt 3 ]; then 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 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 ───────────── # ── Phase 3: pre-promotion canary write/propagation check ─────────────
log "--- Phase 3: pre-promotion canary (legacy -> ${REPLICA_HOST} cascade replica) ---" log "--- Phase 3: pre-promotion canary (legacy -> ${REPLICA_HOST} cascade replica) ---"
@@ -406,7 +456,7 @@ if [ "$RO_STATE" != "on" ]; then
fi fi
log "Legacy confirmed read-only. Draining one more lag poll to confirm quiescence..." log "Legacy confirmed read-only. Draining one more lag poll to confirm quiescence..."
sleep 5 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 "Post-read-only lag check (${REPLICA_HOST}): ${LAG_INFO}"
log "PASS: Phase 4 — legacy is read-only, no further writes possible there" log "PASS: Phase 4 — legacy is read-only, no further writes possible there"