Root cause of the "Canary row did not propagate" Phase 3 failure (run
#7): legacy's pg_hba.conf requires scram-sha-256 for any non-local
connection, and every remote `psql -h <patroni-node>` call in this
script had never supplied a password at all. This was masked until the
prior stderr-capture fix (run #7) surfaced the real error:
"fe_sendauth: no password supplied" on every single attempt.
patroni-0/patroni-1 use the SAME PGadmin superuser + SAME
postgresql_password secret as legacy itself (per
postgresql-ha-staging.yaml), so the fix reads that secret once via
`docker exec "$LEGACY_CID" cat /run/secrets/postgresql_password` early
in Phase 3, then passes it to every remote psql call via
`docker exec -e PGPASSWORD=...` (not spliced into the bash -c string,
to avoid quoting hazards).
Found and fixed the identical missing-password pattern in THREE
places, all with the same root cause:
- Phase 3: the canary-propagation SELECT (where it was first caught)
- Phase 5: the post-promotion pg_is_in_recovery() check
- Phase 8: the alias write + both leader/replica visibility checks
Added "2026 run #8" entry to the script's own header FIX LOG. Not yet
re-validated by a run reaching past Phase 3.
See ADR-0001 note, Session Update 11 (to be added).
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).
Persists the ENTIRE multi-phase transcript (Pre-Phase-0 through Phase
11, including Phase 0's preflight.sh output and any automatically
triggered rollback.sh output) to a single timestamped
cutover-session-<TS>.log in BACKUP_DIR (/volume1/SMB-docker/backup) —
the same directory the pg_dumpall backup lands in. Exports
CUTOVER_SESSION_LOG so child preflight.sh/rollback.sh invocations
append to the same file instead of opening their own. Adds an EXIT
trap that always announces final exit code + log path, specifically
so the one scenario RUNBOOK.md flags as needing manual intervention
(rollback.sh itself failing partway) is still fully investigable
after the fact even without a live terminal. Console/SSH output is
unchanged (tee mirrors to both).
See ADR-0001 note, Session Update 9.
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.
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.
Phase 2's cascade-replica bootstrap does its own full basebackup FROM the
new standby_leader (an extra hop beyond Phase 1's legacy-direct copy), so
per operator request its window is extended further than Phase 1's —
from 1200s (20 min, matched to observed 8-11 min legacy-direct timing) to
2100s (35 min), giving more margin for the additional hop. Phase 1's
window is intentionally left unchanged at 1200s since it already has
comfortable headroom against the timing we've actually observed for that
specific bootstrap path.
Two real-run bugs found and fixed:
1. Phase 1 hardcoded patroni-1 as the expected standby_leader. The
bootstrap-race winner is actually nondeterministic (Patroni/etcd lock
race) — the original prod attempt had patroni-0 win it instead, which
the dry run never exercised. Fixed by polling BOTH patroni-0 and
patroni-1 each iteration and capturing whichever wins into
$LEADER_HOST, with the other becoming $REPLICA_HOST. Every later phase
(2,3,4,5,6,8,10) now references $LEADER_HOST/$REPLICA_HOST instead of
hardcoded hostnames.
2. Phase 1's wait window (240s) and Phase 2's (300s) were both far shorter
than the observed real basebackup duration for a ~42GB cluster
(8-11 minutes per prior dry-run/live polling). The role only flips to
standby_leader/replica AFTER the full copy completes, so both timeouts
could fire — and did — while a legitimate basebackup was still
in-progress, triggering a false-negative rollback. Both windows
extended to 1200s (20 min), with per-poll data-dir size logging
(timeout-guarded du -sh) so progress is observable instead of a silent
binary wait.
admin
AVB