cutover: surface stderr in Phase 3's canary-propagation check (diagnostic fix)

Phase 3's "Canary row did not propagate to <replica> 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_<N>.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

@@ -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_<N>.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
+# FIXED (see header "FIX LOG", 2026 run #7): this write's stderr used to
-if [ $? -ne 0 ]; then
+# be discarded entirely; now captured and logged on failure so a genuine
-  trigger_rollback "Failed to write pre-promotion canary row to legacy."
+# 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:-<empty>}' stderr: ${CANARY_CHECK_ERR}"
+    LAST_CANARY_CHECK_ERR="$CANARY_CHECK_ERR"
+  else
+    log "  attempt ${i}/5 on ${REPLICA_HOST}: result='${RESULT:-<empty>}' (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"