From dbabc69c2a898a22b7799cb648b7d694e37bcd09 Mon Sep 17 00:00:00 2001 From: admin Date: Sat, 8 Aug 2026 13:07:53 -0700 Subject: [PATCH] cutover: surface stderr in Phase 3's canary-propagation check (diagnostic fix) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase 3's "Canary row did not propagate to within 5s" failure has now recurred twice (2026 run #4, root-caused as the Phase 2 lag-check bug; and the run immediately after the Ceph IOPS fix, cause unconfirmed) with genuinely healthy Phase 1/2 beforehand both times. The per-attempt SELECT against the replica was discarding stderr entirely (2>/dev/null), so a real connection/auth error and a genuine multi-second replication delay were indistinguishable in the log — both just showed "row not found". Each of the 5 propagation-check attempts now captures stderr to /tmp/cutover_phase3_attempt_.stderr (mirrors the existing Phase 8 pattern) and echoes result+stderr into the log per-attempt. The final trigger_rollback() message on failure includes the last non-empty stderr seen directly in the FAIL line. The initial canary write's stderr is also no longer discarded. No behavior change to timing/retry counts — purely additive diagnostics. See ADR-0001 note, Session Update 10 (to be added). --- postgresql/cutover/cutover.sh | 64 ++++++++++++++++++++++++++++++++--- 1 file changed, 59 insertions(+), 5 deletions(-) diff --git a/postgresql/cutover/cutover.sh b/postgresql/cutover/cutover.sh index f631cf6..4bdfea9 100644 --- a/postgresql/cutover/cutover.sh +++ b/postgresql/cutover/cutover.sh @@ -194,6 +194,33 @@ # so the backup and the transcript of the run that produced/needed it are # always sitting right next to each other. See "SESSION LOGGING" comment # below for implementation detail. See ADR-0001 note, Session Update 9. +# +# 2026 run #7 — After the underlying Ceph IOPS problem (tracked/fixed +# separately, not a script issue) was resolved, a real run finally got +# CLEANLY past Phase 1 AND Phase 2 (basebackup ~690s, streaming lag=0 +# confirmed) but failed Phase 3 within 6 seconds of Phase 2 passing: +# "Canary row did not propagate to patroni-1 within 5s." This is the +# SECOND time this exact Phase 3 failure has been seen with Phase 1/2 +# genuinely healthy beforehand (see 2026 run #4 above for the first, +# which had a different — since-fixed — root cause in the lag check +# itself). Investigating this run's session log revealed a diagnostic +# gap: the per-attempt `psql -h ${REPLICA_HOST} ... SELECT 1 FROM +# _cutover_canary ...` check discarded stderr entirely (`2>/dev/null`), +# so when the row failed to appear, the log showed only "row not found" +# with NO indication of WHY — a genuine multi-second replication delay +# on this specific DDL+INSERT and an outright connection/auth/permission +# error to patroni-1 look IDENTICAL in that log, and there was no way to +# tell them apart after the fact. FIXED: each attempt's stderr is now +# captured to /tmp/cutover_phase3_attempt_.stderr (mirrors the +# existing Phase 8 pattern below) AND echoed into the log per-attempt +# alongside the (possibly empty) result, so a future failure's log alone +# should show definitively whether this is a genuine propagation delay +# or a real connection-level error. The final trigger_rollback() message +# on failure also now includes the last non-empty stderr seen, so it's +# visible directly in the FAIL line without needing to scroll back. +# NOT yet re-validated by an actual failure recurrence — this fix has +# not yet been exercised for real; if Phase 3 fails again, the log should +# finally explain why. set -uo pipefail # NOTE: deliberately not -e — every phase below checks # its own command's exit status explicitly so we can @@ -604,21 +631,48 @@ if [ -z "$LEGACY_CID" ]; then trigger_rollback "Could not find legacy container for canary write." fi CANARY_VAL="cutover-$(date +%s)" -docker exec "$LEGACY_CID" bash -c "psql -U \"\$POSTGRES_USER\" -c \"CREATE TABLE IF NOT EXISTS _cutover_canary (val text, ts timestamptz default now()); INSERT INTO _cutover_canary(val) VALUES ('${CANARY_VAL}');\"" >/dev/null 2>&1 -if [ $? -ne 0 ]; then - trigger_rollback "Failed to write pre-promotion canary row to legacy." +# FIXED (see header "FIX LOG", 2026 run #7): this write's stderr used to +# be discarded entirely; now captured and logged on failure so a genuine +# write error to LEGACY (as opposed to a downstream propagation issue) +# is visible instead of only surfacing as a generic "failed to write". +CANARY_WRITE_OUT=$(docker exec "$LEGACY_CID" bash -c "psql -U \"\$POSTGRES_USER\" -c \"CREATE TABLE IF NOT EXISTS _cutover_canary (val text, ts timestamptz default now()); INSERT INTO _cutover_canary(val) VALUES ('${CANARY_VAL}');\"" 2>&1) +CANARY_WRITE_RC=$? +if [ "$CANARY_WRITE_RC" -ne 0 ]; then + log "Canary write to legacy — psql output: ${CANARY_WRITE_OUT}" + trigger_rollback "Failed to write pre-promotion canary row to legacy. psql output logged above this FAIL line." fi +# FIXED (see header "FIX LOG", 2026 run #7): the propagation check below +# used to discard stderr entirely (2>/dev/null) — this made a genuine +# replication delay and an outright connection/auth error to +# ${REPLICA_HOST} indistinguishable in the log, and this exact failure +# ("Canary row did not propagate ... within 5s") had already been seen +# TWICE (2026 run #4, root-caused as the lag-check bug; this run, cause +# still unconfirmed at the time of this fix) with no way to tell which +# kind of failure either one actually was after the fact. Each attempt's +# stderr is now captured to a numbered file (same pattern already used by +# Phase 8 below) AND echoed into the log per-attempt, so a future failure +# should be self-explanatory from the log alone. FOUND=0 +LAST_CANARY_CHECK_ERR="" for i in $(seq 1 5); do - 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) + rm -f "/tmp/cutover_phase3_attempt_${i}.stderr" + 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>"/tmp/cutover_phase3_attempt_${i}.stderr") + CANARY_CHECK_ERR="$(cat "/tmp/cutover_phase3_attempt_${i}.stderr" 2>/dev/null)" + if [ -n "$CANARY_CHECK_ERR" ]; then + log " attempt ${i}/5 on ${REPLICA_HOST}: result='${RESULT:-}' stderr: ${CANARY_CHECK_ERR}" + LAST_CANARY_CHECK_ERR="$CANARY_CHECK_ERR" + else + log " attempt ${i}/5 on ${REPLICA_HOST}: result='${RESULT:-}' (no stderr)" + fi if [ "$RESULT" = "1" ]; then FOUND=1 + rm -f /tmp/cutover_phase3_attempt_*.stderr break fi sleep 1 done if [ "$FOUND" -ne 1 ]; then - trigger_rollback "Canary row did not propagate to ${REPLICA_HOST} 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. Last psql stderr seen (empty means every attempt connected cleanly and simply found no row yet — a genuine propagation delay, not a connection error): '${LAST_CANARY_CHECK_ERR}'. Full per-attempt detail logged above; raw files also left at /tmp/cutover_phase3_attempt_*.stderr on docker-2 for inspection." fi log "PASS: Phase 3 — canary write propagated to ${REPLICA_HOST} within 5s"