From ca121b7dd888d32fad1389071fda5c24142e3594 Mon Sep 17 00:00:00 2001 From: Dimitri Fontaine Date: Mon, 27 Jul 2026 18:36:06 +0200 Subject: [PATCH 1/2] Add pgaftest spec reproducing issue #1168 3-node cluster (node1 primary, node2 sync secondary, node3 async secondary with candidate-priority 50 > 0). node2 fails, zeroing secondaryQuorumNodesCount even though node3 stays healthy (async standbys never count toward it), so node1 gets reassigned wait_primary. node1 then itself goes unhealthy while at that converged wait_primary: the auto-failover trigger in ProceedGroupStateFromContext fires against node3 and hands node1 a goal (draining, then demote_timeout within the same polling cycle) that has no KeeperFSM[] edge from wait_primary. Verified against current origin/main: node1's keeper fatals/retries with "does not know how to reach state" before self-healing via the unrelated, purely time-based drain-timeout mechanism (goal re-targeted straight to demoted). Ran twice locally via 'pgaftest run' against a freshly built pg17 image, both green -- this spec documents the current (buggy) recovery path and will need its assertions updated once #1168 is actually fixed (drop the log-contains check, assert node1 goes straight to demoted without the intermediate fatal). --- tests/tap/schedule | 1 + .../specs/wait_primary_draining_deadlock.pgaf | 84 +++++++++++++++++++ 2 files changed, 85 insertions(+) create mode 100644 tests/tap/specs/wait_primary_draining_deadlock.pgaf diff --git a/tests/tap/schedule b/tests/tap/schedule index f7943bc96..5f2e58b51 100644 --- a/tests/tap/schedule +++ b/tests/tap/schedule @@ -28,6 +28,7 @@ guard_data_loss replication_stall_3dc fast_forward demote_timeout_wait_primary_deadlock +wait_primary_draining_deadlock timeline_fork_report_lsn_deadlock extension_update tablespaces diff --git a/tests/tap/specs/wait_primary_draining_deadlock.pgaf b/tests/tap/specs/wait_primary_draining_deadlock.pgaf new file mode 100644 index 000000000..db2a2ec08 --- /dev/null +++ b/tests/tap/specs/wait_primary_draining_deadlock.pgaf @@ -0,0 +1,84 @@ +# Reproduces https://github.com/hapostgres/pg_auto_failover/issues/1168. +# +# node1 (primary) loses its only quorum-counted standby (node2) and gets +# reassigned wait_primary, even though node3 -- an async standby +# (candidate-priority 50, replication-quorum false) -- stays healthy +# throughout: async standbys never count toward secondaryQuorumNodesCount, +# so losing node2 alone is enough to zero it out. +# +# node1 then itself becomes unhealthy while sitting at (converged) +# wait_primary. The auto-failover trigger in ProceedGroupStateFromContext +# (`IsCurrentState(activeNode, SECONDARY) && IsInPrimaryState(primaryNode) +# && NodeIsUnhealthy(primaryNode) && ...`) fires against node3 and assigns +# node1 "draining" -- a goal state with no KeeperFSM[] edge from +# wait_primary (only PRIMARY/JOIN_PRIMARY/APPLY_SETTINGS -> DRAINING +# exist). node1's keeper fatals and retries forever on that specific +# assignment. The cluster still recovers, but only via the unrelated, +# purely time-based drain-timeout self-heal (goal jumps straight to +# demoted once drain_timeout_ms elapses) -- not because the assignment was +# ever reachable. + +cluster { + monitor + ssl off + formation { + node1 + node2 + node3 async + } +} + +setup { + wait until node1 state is primary + and node2 state is secondary + and node3 state is secondary + timeout 120s +} + +teardown { + compose down +} + +step test_001_losing_the_only_sync_standby_reassigns_wait_primary { + network disconnect node2 + wait until node1 assigned-state is wait_primary timeout 60s + assert node3 state is secondary +} + +step test_002_primary_failure_at_wait_primary_hits_1168 { + network disconnect node1 + + # node3 is the only remaining healthy candidate (async, candidate + # priority 50 > 0); the buggy trigger targets it once node1 is marked + # unhealthy by the monitor's own health checks. node1's goal moves + # draining -> demote_timeout within the same polling cycle (neither + # reachable from wait_primary), so we don't probe that intermediate + # value directly -- the FATAL log below is the stable signature. + wait until node3 assigned-state is prepare_promotion timeout 90s + + network connect node1 + + # Recovers, but only via the unrelated drain-timeout self-heal (goal + # re-targeted straight to demoted once drain_timeout_ms elapses), not + # because "draining"/"demote_timeout" ever became reachable from + # wait_primary. + wait until node1 state is demoted timeout 90s + + # node1 reported back in still at wait_primary along the way, was + # handed one of those unreachable goals, and fataled/retried -- the + # bug this spec documents. + logs node1 contains "does not know how to reach state" +} + +step test_003_cluster_converges_back_after_recovery { + network connect node2 + wait until node3 state is primary + and node1 state is secondary + and node2 state is secondary + timeout 120s +} + +sequence + test_001_losing_the_only_sync_standby_reassigns_wait_primary + test_002_primary_failure_at_wait_primary_hits_1168 + test_003_cluster_converges_back_after_recovery From eb01e226cb4fa1aa79cb050977f1e219cfe13cc9 Mon Sep 17 00:00:00 2001 From: Dimitri Fontaine Date: Mon, 27 Jul 2026 19:54:07 +0200 Subject: [PATCH 2/2] Fix #1168: monitor no longer assigns a primary at wait_primary an unreachable goal state The two-node/general auto-failover trigger in ProceedGroupStateFromContext unconditionally assigned a healthy candidate's primary goal state "draining" (and, one tick later, an unconditional follow-on rule re-assigned it "demote_timeout"), neither of which KeeperFSM[] has an edge for from wait_primary -- only PRIMARY/JOIN_PRIMARY/APPLY_SETTINGS have those edges. The primary's keeper would fatal and retry forever on that specific assignment; the cluster recovered anyway, but only via the unrelated, purely time-based drain-timeout self-heal, drain_timeout_ms late. Root issue was reported against PR #1165 (the #774 fix): https://github.com/hapostgres/pg_auto_failover/pull/1165#issuecomment-5089517363 Fix, in three coordinated parts: 1. The trigger no longer reassigns primaryNode's goal at all when it's already converged to wait_primary -- there is nothing reachable to reassign it to, and no live standby to gracefully drain in the first place (wait_primary never had synchronous quorum). 2. The unconditional prepare_promotion -> stop_replication follow-on rule likewise skips reassigning primaryNode's goal in that case (still unconditionally moves the candidate to stop_replication). 3. A new NodeIsWaitPrimaryPresumedDead() applies the exact same drain_timeout_ms safety margin as NodeIsDrainTimeExpired before the completion rule commits the one real, reachable wait_primary -> demoted transition -- deliberately not shortened to the trigger's own (shorter) unhealthyTimeoutMs, and deliberately not gated on pgIsRunning (the common crash/partition case leaves a stale "running" self-report, so requiring it to be false first would make the wait permanent for exactly that case). Anchoring that safety margin took two attempts: the first version measured elapsed time from primaryNode's own reportTime, which seemed right by analogy to NodeIsDrainTimeExpired -- but reportTime keeps getting refreshed by the primary's own keeper the moment it reconnects and resumes polling, even if it never actually converges on anything, turning the bounded wait into a permanent stall. Caught this by re-running the #1169 repro spec with the primary reconnecting mid-flight (exactly the scenario a real network blip would produce) and watching promotion never complete. Fixed by anchoring on the *candidate's* own stateChangeTime instead, which only moves when the monitor reassigns the candidate's own goal -- untouched by the old primary's unrelated activity, and fixed in place the moment the candidate converges to stop_replication. Verified: pg_regress + isolation suites (13+6 tests, unchanged), multi_async.pgaf (27 tests, including the existing drain-timeout self-heal path at the same ~35s timing), demote_timeout_wait_primary_deadlock.pgaf (3 tests), and the #1169 repro spec updated to assert the fix (no fatal log, cluster still converges within the same safety margin) -- all green, run twice for stability. --- src/monitor/group_state_machine.c | 102 +++++++++++++----- src/monitor/node_metadata.c | 43 ++++++++ src/monitor/node_metadata.h | 3 + .../specs/wait_primary_draining_deadlock.pgaf | 50 +++++---- 4 files changed, 149 insertions(+), 49 deletions(-) diff --git a/src/monitor/group_state_machine.c b/src/monitor/group_state_machine.c index 42a7125e5..85ed020a2 100644 --- a/src/monitor/group_state_machine.c +++ b/src/monitor/group_state_machine.c @@ -698,23 +698,47 @@ ProceedGroupStateFromContext(GroupStateContext *ctx) { char message[BUFSIZE]; - LogAndNotifyMessage( - message, BUFSIZE, - "Setting goal state of " NODE_FORMAT - " to draining and " NODE_FORMAT - " to prepare_promotion " - "after " NODE_FORMAT - " became unhealthy.", - NODE_FORMAT_ARGS(primaryNode), - NODE_FORMAT_ARGS(activeNode), - NODE_FORMAT_ARGS(primaryNode)); + /* + * A primary already converged to wait_primary has no "draining" to + * go through: it never had a synchronous standby to begin with, so + * there's nothing live to gracefully drain, and KeeperFSM[] has no + * wait_primary -> draining edge anyway (issue #1168). Leave its + * goal untouched here; the prepare_promotion/stop_replication rules + * below apply the same drainTimeoutMs safety margin via report + * staleness instead of a goal-state timestamp, then commit the one + * real, reachable wait_primary -> demoted transition once it has + * genuinely expired. + */ + if (IsCurrentState(primaryNode, REPLICATION_STATE_WAIT_PRIMARY)) + { + LogAndNotifyMessage( + message, BUFSIZE, + "Setting goal state of " NODE_FORMAT + " to prepare_promotion after " NODE_FORMAT + " (at wait_primary) became unhealthy.", + NODE_FORMAT_ARGS(activeNode), + NODE_FORMAT_ARGS(primaryNode)); + } + else + { + LogAndNotifyMessage( + message, BUFSIZE, + "Setting goal state of " NODE_FORMAT + " to draining and " NODE_FORMAT + " to prepare_promotion " + "after " NODE_FORMAT + " became unhealthy.", + NODE_FORMAT_ARGS(primaryNode), + NODE_FORMAT_ARGS(activeNode), + NODE_FORMAT_ARGS(primaryNode)); + + /* shut down the primary */ + AssignGoalState(primaryNode, REPLICATION_STATE_DRAINING, message); + } /* keep reading until no more records are available */ AssignGoalState(activeNode, REPLICATION_STATE_PREPARE_PROMOTION, message); - /* shut down the primary */ - AssignGoalState(primaryNode, REPLICATION_STATE_DRAINING, message); - return true; } @@ -854,22 +878,40 @@ ProceedGroupStateFromContext(GroupStateContext *ctx) { char message[BUFSIZE]; - LogAndNotifyMessage( - message, BUFSIZE, - "Setting goal state of " NODE_FORMAT - " to demote_timeout and " NODE_FORMAT - " to stop_replication after " NODE_FORMAT - " converged to prepare_promotion.", - NODE_FORMAT_ARGS(primaryNode), - NODE_FORMAT_ARGS(activeNode), - NODE_FORMAT_ARGS(activeNode)); + /* + * wait_primary has no reachable demote_timeout edge either (issue + * #1168); leave its goal alone here and let the completion rule + * below apply the drainTimeoutMs safety margin via report + * staleness instead. + */ + if (IsCurrentState(primaryNode, REPLICATION_STATE_WAIT_PRIMARY)) + { + LogAndNotifyMessage( + message, BUFSIZE, + "Setting goal state of " NODE_FORMAT + " to stop_replication after it converged to " + "prepare_promotion.", + NODE_FORMAT_ARGS(activeNode)); + } + else + { + LogAndNotifyMessage( + message, BUFSIZE, + "Setting goal state of " NODE_FORMAT + " to demote_timeout and " NODE_FORMAT + " to stop_replication after " NODE_FORMAT + " converged to prepare_promotion.", + NODE_FORMAT_ARGS(primaryNode), + NODE_FORMAT_ARGS(activeNode), + NODE_FORMAT_ARGS(activeNode)); + + /* wait for possibly-alive primary to kill itself */ + AssignGoalState(primaryNode, REPLICATION_STATE_DEMOTE_TIMEOUT, message); + } /* perform promotion to stop replication */ AssignGoalState(activeNode, REPLICATION_STATE_STOP_REPLICATION, message); - /* wait for possibly-alive primary to kill itself */ - AssignGoalState(primaryNode, REPLICATION_STATE_DEMOTE_TIMEOUT, message); - return true; } @@ -926,10 +968,16 @@ ProceedGroupStateFromContext(GroupStateContext *ctx) /* * when drain time expires or primary reports it's drained: * draining -> demoted + * + * NodeIsWaitPrimaryPresumedDead covers the wait_primary equivalent + * (issue #1168): the same drainTimeoutMs safety margin, applied via + * report staleness instead of a demote_timeout goal-state timestamp + * since that state is never reachable from wait_primary. */ if (IsCurrentState(activeNode, REPLICATION_STATE_STOP_REPLICATION) && (IsCurrentState(primaryNode, REPLICATION_STATE_DEMOTE_TIMEOUT) || - NodeIsDrainTimeExpired(primaryNode, ctx))) + NodeIsDrainTimeExpired(primaryNode, ctx) || + NodeIsWaitPrimaryPresumedDead(primaryNode, activeNode, ctx))) { char message[BUFSIZE]; @@ -937,7 +985,7 @@ ProceedGroupStateFromContext(GroupStateContext *ctx) message, BUFSIZE, "Setting goal state of " NODE_FORMAT " to wait_primary and " NODE_FORMAT - " to demoted after the demote timeout expired.", + " to demoted after the primary was presumed dead.", NODE_FORMAT_ARGS(activeNode), NODE_FORMAT_ARGS(primaryNode)); diff --git a/src/monitor/node_metadata.c b/src/monitor/node_metadata.c index c6d4c0eae..2b182ec70 100644 --- a/src/monitor/node_metadata.c +++ b/src/monitor/node_metadata.c @@ -2520,3 +2520,46 @@ NodeIsDrainTimeExpired(const AutoFailoverNode *node, return TimestampDifferenceExceeds(node->stateChangeTime, ctx->now, ctx->drainTimeoutMs); } + + +/* + * NodeIsWaitPrimaryPresumedDead is the wait_primary equivalent of + * NodeIsDrainTimeExpired (issue #1168): a primary already converged to + * wait_primary never had a synchronous standby to begin with, so there is + * nothing "live" to gracefully drain, and KeeperFSM[] has no + * wait_primary -> draining or wait_primary -> demote_timeout edge either. + * + * We still apply the exact same safety margin (drainTimeoutMs, not the + * shorter unhealthyTimeoutMs that triggers a failover attempt in the first + * place) before presuming it dead. NodeIsDrainTimeExpired anchors on + * primaryNode's own stateChangeTime, which only moves when the monitor + * (re)assigns its goal -- a timestamp the primary itself can't refresh + * just by resuming contact. We can't reuse that same trick on primaryNode + * here, because this path deliberately never reassigns its goal (there is + * nothing reachable to reassign it to); if we anchored on primaryNode's + * own reportTime instead, a primary that reconnects and resumes reporting + * wait_primary (without ever converging on the failover) would keep + * resetting the clock forever, even though it never actually completes + * the promotion -- a permanent stall, not a bounded wait. + * + * So we anchor on activeNode's stateChangeTime instead: it is only + * touched by the monitor (re)assigning activeNode's own goal, which stops + * once activeNode converges to stop_replication (no further rule targets + * it while it stays there), giving us the same "fixed once committed, + * immune to the other node's unrelated activity" property that + * NodeIsDrainTimeExpired gets from primaryNode's stateChangeTime. + */ +bool +NodeIsWaitPrimaryPresumedDead(const AutoFailoverNode *primaryNode, + const AutoFailoverNode *activeNode, + const struct GroupStateContext *ctx) +{ + if (primaryNode == NULL || activeNode == NULL || + primaryNode->goalState != REPLICATION_STATE_WAIT_PRIMARY) + { + return false; + } + + return TimestampDifferenceExceeds(activeNode->stateChangeTime, ctx->now, + ctx->drainTimeoutMs); +} diff --git a/src/monitor/node_metadata.h b/src/monitor/node_metadata.h index ccc2eed57..0d336ca61 100644 --- a/src/monitor/node_metadata.h +++ b/src/monitor/node_metadata.h @@ -286,3 +286,6 @@ extern bool NodeIsReporting(const AutoFailoverNode *node, const struct GroupStateContext *ctx); extern bool NodeIsDrainTimeExpired(const AutoFailoverNode *node, const struct GroupStateContext *ctx); +extern bool NodeIsWaitPrimaryPresumedDead(const AutoFailoverNode *primaryNode, + const AutoFailoverNode *activeNode, + const struct GroupStateContext *ctx); diff --git a/tests/tap/specs/wait_primary_draining_deadlock.pgaf b/tests/tap/specs/wait_primary_draining_deadlock.pgaf index db2a2ec08..2246db0c9 100644 --- a/tests/tap/specs/wait_primary_draining_deadlock.pgaf +++ b/tests/tap/specs/wait_primary_draining_deadlock.pgaf @@ -1,4 +1,4 @@ -# Reproduces https://github.com/hapostgres/pg_auto_failover/issues/1168. +# Regression test for https://github.com/hapostgres/pg_auto_failover/issues/1168. # # node1 (primary) loses its only quorum-counted standby (node2) and gets # reassigned wait_primary, even though node3 -- an async standby @@ -9,14 +9,23 @@ # node1 then itself becomes unhealthy while sitting at (converged) # wait_primary. The auto-failover trigger in ProceedGroupStateFromContext # (`IsCurrentState(activeNode, SECONDARY) && IsInPrimaryState(primaryNode) -# && NodeIsUnhealthy(primaryNode) && ...`) fires against node3 and assigns +# && NodeIsUnhealthy(primaryNode) && ...`) used to unconditionally assign # node1 "draining" -- a goal state with no KeeperFSM[] edge from # wait_primary (only PRIMARY/JOIN_PRIMARY/APPLY_SETTINGS -> DRAINING -# exist). node1's keeper fatals and retries forever on that specific -# assignment. The cluster still recovers, but only via the unrelated, -# purely time-based drain-timeout self-heal (goal jumps straight to -# demoted once drain_timeout_ms elapses) -- not because the assignment was -# ever reachable. +# exist). node1's keeper would fatal and retry forever on that specific +# assignment; the cluster still recovered, but only via the unrelated, +# purely time-based drain-timeout self-heal, ~drain_timeout_ms late. +# +# Fixed by never reassigning primaryNode's goal away from wait_primary +# along this path (there is nothing reachable to reassign it to) and +# instead applying the same drain_timeout_ms safety margin via +# NodeIsWaitPrimaryPresumedDead, anchored on the candidate's own +# stateChangeTime rather than the primary's reportTime -- the primary +# reconnecting and resuming reports (without ever converging) must not +# reset that clock, or the promotion would stall forever instead of +# completing on the same bounded timeline as any other primary failure. +# This spec asserts the fatal never happens and the cluster still +# converges within the same safety margin. cluster { monitor @@ -45,29 +54,26 @@ step test_001_losing_the_only_sync_standby_reassigns_wait_primary { assert node3 state is secondary } -step test_002_primary_failure_at_wait_primary_hits_1168 { +step test_002_primary_failure_at_wait_primary_promotes_cleanly { network disconnect node1 # node3 is the only remaining healthy candidate (async, candidate - # priority 50 > 0); the buggy trigger targets it once node1 is marked - # unhealthy by the monitor's own health checks. node1's goal moves - # draining -> demote_timeout within the same polling cycle (neither - # reachable from wait_primary), so we don't probe that intermediate - # value directly -- the FATAL log below is the stable signature. + # priority 50 > 0); the auto-failover trigger targets it once node1 is + # marked unhealthy by the monitor's own health checks. node1's own + # goal stays at wait_primary throughout (issue #1168 fix) instead of + # bouncing through the unreachable draining/demote_timeout states. wait until node3 assigned-state is prepare_promotion timeout 90s network connect node1 - # Recovers, but only via the unrelated drain-timeout self-heal (goal - # re-targeted straight to demoted once drain_timeout_ms elapses), not - # because "draining"/"demote_timeout" ever became reachable from - # wait_primary. + # Recovers within the same drain_timeout_ms safety margin as any other + # primary failure -- not sped up, not stalled by node1 reconnecting and + # resuming (fruitless) reports along the way. wait until node1 state is demoted timeout 90s - # node1 reported back in still at wait_primary along the way, was - # handed one of those unreachable goals, and fataled/retried -- the - # bug this spec documents. - logs node1 contains "does not know how to reach state" + # The fix's whole point: no unreachable assignment was ever made, so + # node1's keeper never fatals. + logs node1 not contains "does not know how to reach state" } step test_003_cluster_converges_back_after_recovery { @@ -80,5 +86,5 @@ step test_003_cluster_converges_back_after_recovery { sequence test_001_losing_the_only_sync_standby_reassigns_wait_primary - test_002_primary_failure_at_wait_primary_hits_1168 + test_002_primary_failure_at_wait_primary_promotes_cleanly test_003_cluster_converges_back_after_recovery