myxce/src/xceadmin/tests/test_e2e_live_ha_push.py
Rongsong Shen 34bd934bc7 wip(admin-config-tool): task 6.3 HA E2E test (blocked, flaky primary-push)
Standby-redirect half is done and correct: OP_upgradeConfig has no
server-side redirect wiring today, matches design.md's own documented
"Out of Boundary" gap, and this test locks in the real current
rejection behavior.

Primary-push success-path half is unreliable (~24/25 live fails in one
investigation round, see bug-1485) -- the elected primary was observed
as a <defunct> zombie shortly after promotion, but a dedicated debug
pass could not reproduce it in 26+ clean runs on an idle host and
captured no crash evidence either way. tasks.md marks 6.3 _Blocked:_
pending re-verification on an idle host with real stderr capture.
2026-07-31 08:09:36 +00:00

496 lines
24 KiB
Python

"""Live 3-node HA E2E coverage for `config push` -- success path + the
standby-contact case (task 6.3; Requirements 2.1, 2.5, 2.6, 3.1, 3.2, 3.3).
Task 6.2's ``test_e2e_live_push.py`` deploys a genuinely single-node
controller (zero HA peers), which structurally cannot exercise a real
positive ``ackedCount`` / exit-0 success path (Requirement 2.6) -- a
peer-less controller has no standbys to ACK, so ``ackedCount`` is always 0
there (see task 6.2's Implementation Notes entry and that file's own module
docstring). This file closes THAT gap against one live 3-node
``xce_controller`` cluster (reusing ``deploy-ha.sh``'s existing multi-node
pattern -- see ``live_ha_cluster`` below):
``test_live_config_push_against_primary_reaches_success_path`` genuinely
exits 0 with a positive ``ackedCount`` from real standby ACKs.
REAL FINDING, not a test bug -- the redirect scenario does NOT close the
way the task text originally anticipated: pushing `config push` to a
*standby* does NOT redirect to the primary against a real controller
today, and this is not something a test-only change can fix. This is an
ALREADY-DOCUMENTED, pre-existing gap in design.md's own "Boundary
Commitments" section (`.kiro/specs/admin-config-tool/design.md`, "Out of
Boundary" -- "Redirect wiring for `OP_upgradeConfig`") and "Revalidation
Triggers" (`fill_redirect_reply()` extended to `OPCode_upgradeConfig` is
listed there as a FUTURE, not-yet-done trigger): `fill_redirect_reply()`
(`join.c:27-31`) is only ever invoked from the `OPCode_join` path
(`join.c:277`); nothing calls it for `OPCode_upgradeConfig`.
`RequestReply.redirectHost`/`redirectPort` are therefore never populated
for an `upgradeConfig` reply. Confirmed directly in `cluster.c`'s
`myreq_handler`: a standby's `OP_upgradeConfig` request is rejected by the
generic `ha_dispatch_gate()` role check (`ha.c`, opcode absent from the
`CTRL_STANDBY` allow-list) BEFORE the opcode-specific `case
OPCode_upgradeConfig:` handler ever runs -- the gate-rejection reply path
(`cluster.c` ~line 273-280) sends `reply.status = -XCE_ERR_STANDBY`
(`errnox.h`: `E_XCE_STANDBY == XCE_ERRNO_BASE + 13 == 10014`) with
`data_which = RequestReply_data_nodata` and never touches
`redirectHost`/`redirectPort` at all. Live-verified against a real 3-node
cluster: pushing to a standby returns `versionTag=0 ackedCount=0`, exit 1,
stderr `"Error: controller returned status -10014"` -- no redirect line,
no success. `xceadmin.discovery.follow_redirects`/`decode_reply` behave
exactly per Requirement 3.1's contract given this reply (both fields
absent/empty => no redirect => the bare rejection is returned as-is); the
gap is entirely server-side and out of this task's test-only boundary to
fix (design.md: "This is a controller defect, not an xceadmin defect;
xceadmin implements the client side of the documented contract... and
cannot itself fix the gate"). Task 5.6 already covers the SUCCESSFUL
redirect-follow path against mocks (`test_config_push_mock.py`), which is
still the only place that path is exercised.
``test_live_config_push_against_standby_returns_standby_rejection_not_redirect``
below live-verifies and regression-locks this REAL current behavior
instead of the hypothetical "redirect then succeed" outcome -- the same
resolution task 6.2 used for its own real-vs-literal-task-text mismatch
(single-node `ackedCount == 0`/exit 1). The moment a future controller-side
task wires `fill_redirect_reply()` for `OPCode_upgradeConfig` (already
tracked as a Revalidation Trigger in design.md), THIS test will start
failing on the "no redirect line" assertion -- that failure is the signal
to replace it with a real success-path assertion, matching what this
docstring originally described before investigation.
Shares binary discovery / port / stdout-parsing helpers with
``test_e2e_live_push.py`` via ``_live_e2e_common`` (extracted there as part
of this task -- see that module's docstring for the extraction rationale).
The multi-node deploy/launch/election-wait/cleanup fixture itself
(``live_ha_cluster``) is NOT shared with task 6.2's ``live_controller``:
staggered 3-process start, per-peer log polling for primary election, and
building the ``ctrl-N=host:port`` peers string for 3 nodes are enough of a
different shape from a single ``deploy-ha.sh`` call + single process launch
that merging them would cost more readability than it would save.
Skip convention: identical to task 6.2 -- an imperative ``pytest.skip``
inside the fixture (no controller binary / no ``openssl``), plus an
in-test skip for a missing ``xceadmin`` binary, both matching this suite's
existing cert-dependent skip precedent (task 5.3). Skipping is the NORMAL
outcome under the fast ``xce-build.sh xceadmin`` / meson path, which runs
pytest from an isolated ``repo-mirror`` with no sibling
``xce.build``/``build.dbg``/``build.release`` controller binaries.
Process-leak fix (task 6.2's own finding, reused here for all 3 nodes):
each controller is launched as the real ``xce_controller`` binary
directly, never through ``deploy-ha.sh``'s generated ``scripts/start.sh``
bash wrapper -- that wrapper runs the binary as bash's non-``exec``'d
child, so ``Popen.terminate()`` on the wrapper does not reach the real
controller process and orphans it.
Election-wait (round-2 remediation -- round-1 review REJECTED the
single-phase version of this gate as flaky, ~75% failure rate over 8 live
runs): polls each of the 3 controller log files for the literal substring
``"CTRL_PRIMARY"`` (``ha.c``'s own election-complete log lines, e.g. ``"HA
FSM: -> CTRL_PRIMARY (term=...)"`` / ``"HA FSM (raft): -> CTRL_PRIMARY
(term=...)"``) rather than a fixed sleep -- the same convention this
repo's own ``test-heartbeat-tolerance.sh`` (``wait_for_primary()``)
already uses, generalized here to check all 3 logs (that script only
checks ``ctrl-1.log``, relying on ctrl-1 usually winning the first
election since it starts first; this test does not assume which node
wins). Round 1 stopped there; that is what made it flaky.
This file now ALSO ports the second half of ``test-heartbeat-tolerance.sh``'s
own readiness gate that round 1 skipped: that script never proceeds past
``wait_for_primary()`` without immediately also calling
``wait_for_standbys()`` (confirming both other nodes' logs show
``CTRL_STANDBY``) -- round 1's fixture treated a single ``CTRL_PRIMARY``
log line, alone, as "cluster ready," which does not prove the cluster has
stopped electing: this repo's 3-node bootstrap starts all 3 nodes
``CTRL_STANDBY`` and self-promotes via a PreVote-triggered failover after a
uniform ~10.2s liveness timeout (``ha.h``: ``HA_DEFAULT_HEARTBEAT_TIMEOUT_MS
= 10000``) against only a 0.5s start stagger -- a genuine 3-way race where a
second, later election can reshuffle who is primary between "detected
primary" and "pushed to it." ``_wait_for_standbys`` below is that missing
half, generalized the same way ``_wait_for_primary`` already was (checking
the two specific non-primary nodes by name, not a fixed ctrl-2/ctrl-3
assumption).
Live reproduction during round-2 remediation (a standalone repro harness,
4 attempts, all with near-identical timing: ports open ~1.2s, CTRL_PRIMARY
~10.2s) surfaced a THIRD failure mode neither round 1 nor the plain
standby-wait alone fully closes: even after both markers are confirmed,
the freshly-promoted primary's own admin port can still be transiently
``ECONNREFUSED`` or accept the TCP connection but reply with an internal
``ETIMEDOUT`` (status -110) for a short window immediately after the
``CTRL_PRIMARY`` log line is written -- consistent with post-promotion
socket/RPC-pipeline warmup that the log line itself does not wait for.
``_POST_ELECTION_SETTLE_S`` (one full ``heartbeat_interval_ms``, ``ha.h``:
``HA_DEFAULT_HEARTBEAT_INTERVAL_MS = 3000`` -- the same constant
``test-heartbeat-tolerance.sh`` keys its own post-election settle sleeps
to) plus a fresh ``wait_for_port`` re-probe of the primary's address right
before the fixture yields (reusing the exact same helper used at initial
boot, not a new one) closes that window: a still-flapping port keeps
retrying inside ``wait_for_port`` instead of racing straight into the
push and surfacing as a confusing ``ConnectionRefusedError``/``ETIMEDOUT``
deep inside the test body.
"""
from __future__ import annotations
import re
import shutil
import subprocess
import time
from dataclasses import dataclass
from pathlib import Path
import pytest
from _live_e2e_common import CONTROLLER_CANDIDATES
from _live_e2e_common import DEPLOY_HA_SH, REPO_CONFIGS_DIR
from _live_e2e_common import READY_TIMEOUT_S
from _live_e2e_common import VERSION_TAG_RE
from _live_e2e_common import XCEADMIN_CANDIDATES
from _live_e2e_common import find_first_executable
from _live_e2e_common import free_tcp_ports
from _live_e2e_common import wait_for_port
_N_NODES = 3
_STAGGER_S = 0.5
_ELECTION_TIMEOUT_S = 30.0
_ELECTION_POLL_S = 1.0
# One full heartbeat_interval_ms (ha.h: HA_DEFAULT_HEARTBEAT_INTERVAL_MS =
# 3000, the same constant test-heartbeat-tolerance.sh's own post-election
# settle sleeps are keyed to) -- see module docstring's "Election-wait"
# section for the live-reproduced failure mode this closes.
_POST_ELECTION_SETTLE_S = 3.0
_PRIMARY_MARKER = "CTRL_PRIMARY"
_STANDBY_MARKER = "CTRL_STANDBY"
# Primary-side evidence that at least one standby genuinely ACKed the push
# (config_repl.c's push_config_to_standbys, on majority ACK):
# "Config committed on majority (tag=..., pushed=X/Y standbys)".
_MAJORITY_ACK_RE = re.compile(
r"Config committed on majority \(tag=([0-9a-f]{16}), pushed=(\d+)/(\d+) standbys\)"
)
# Standby-side evidence that IT received and saved the pushed bytes
# (config_repl.c's handle_repl_config_push, on successful conf_save_config):
# "handle_repl_config_push: config bytes saved out-of-band (pushed tag=...)".
_STANDBY_SAVED_RE = re.compile(
r"handle_repl_config_push: config bytes saved out-of-band \(pushed tag=([0-9a-f]{16})\)"
)
@dataclass(frozen=True)
class HaNode:
name: str
addr: str
log_file: Path
@dataclass(frozen=True)
class HaCluster:
primary: HaNode
standbys: list[HaNode]
def _wait_for_primary(nodes: list[HaNode], timeout_s: float) -> HaNode:
"""Poll every node's log for ``ha.c``'s own election-complete marker
(module docstring) rather than a fixed sleep. Returns whichever node's
log shows it first; raises ``TimeoutError`` if none does within
``timeout_s``.
"""
deadline = time.monotonic() + timeout_s
while time.monotonic() < deadline:
for node in nodes:
if node.log_file.is_file() and _PRIMARY_MARKER in node.log_file.read_text():
return node
time.sleep(_ELECTION_POLL_S)
raise TimeoutError(
f"no node reached {_PRIMARY_MARKER} within {timeout_s}s "
f"(logs: {[str(n.log_file) for n in nodes]})"
)
def _wait_for_standbys(standby_nodes: list[HaNode], timeout_s: float) -> None:
"""Poll each of the (exactly two) non-primary nodes' own logs for
``ha.c``'s ``CTRL_STANDBY`` marker, mirroring
``test-heartbeat-tolerance.sh``'s ``wait_for_standbys()`` (module
docstring) -- that script never treats a cluster as ready on
``wait_for_primary()`` alone. Confirms BOTH other nodes have settled
into steady-state ``CTRL_STANDBY``, closing the round-1 race where a
single ``CTRL_PRIMARY`` log line was treated as sufficient even though
a second, later election could still be in flight. Raises
``TimeoutError`` naming whichever node(s) never got there.
"""
deadline = time.monotonic() + timeout_s
pending = {node.name: node for node in standby_nodes}
while time.monotonic() < deadline and pending:
for name, node in list(pending.items()):
if node.log_file.is_file() and _STANDBY_MARKER in node.log_file.read_text():
del pending[name]
if pending:
time.sleep(_ELECTION_POLL_S)
if pending:
raise TimeoutError(
f"standby node(s) {sorted(pending)} never reached {_STANDBY_MARKER} "
f"within {timeout_s}s "
f"(logs: {[str(n.log_file) for n in pending.values()]})"
)
@pytest.fixture
def live_ha_cluster(tmp_path: Path):
"""Deploy + start a real 3-node ``xce_controller`` HA cluster via the
project's own ``deploy-ha.sh``, wait for a primary to be elected, and
yield an :class:`HaCluster` naming which node is primary and which two
are standbys. Skips cleanly if no controller binary or ``openssl`` is
available (matching task 6.2's convention). Always kills all 3
controller processes and removes the scratch deploy directory, on both
success and failure paths.
"""
controller_bin = find_first_executable(CONTROLLER_CANDIDATES)
if controller_bin is None:
pytest.skip(
"no xce_controller binary found under xce.build/build.release/"
"build.dbg -- run xce-build.sh controller [profile] first to "
"exercise this live E2E test"
)
if shutil.which("openssl") is None:
pytest.skip("openssl not found on PATH -- required by deploy-ha.sh")
deploy_dir = tmp_path / "deploy"
ports = free_tcp_ports(_N_NODES)
bare_peers = ",".join(f"localhost:{p}" for p in ports)
deploy = subprocess.run(
["bash", str(DEPLOY_HA_SH), str(controller_bin), str(deploy_dir), bare_peers],
capture_output=True,
text=True,
)
assert deploy.returncode == 0, f"deploy-ha.sh failed: {deploy.stdout}\n{deploy.stderr}"
names = [f"ctrl-{i + 1}" for i in range(_N_NODES)]
addrs = [f"localhost:{p}" for p in ports]
# Matches deploy-ha.sh's own internal PEERS_STR construction exactly
# (src/tools/deploy-ha.sh) -- rebuilt here because this fixture launches
# each controller binary directly rather than through the generated
# scripts/start.sh wrapper (module docstring: process-leak fix).
peers_str = ",".join(f"{name}={addr}" for name, addr in zip(names, addrs))
procs: list[subprocess.Popen] = []
nodes: list[HaNode] = []
try:
for i, (name, addr) in enumerate(zip(names, addrs)):
log_file = deploy_dir / "logs" / f"{name}.log"
proc = subprocess.Popen(
[
str(controller_bin),
"--myname", name,
"--peers", peers_str,
"--workdir", str(deploy_dir / "controller"),
"--certdir", str(deploy_dir / "certs"),
"--logfile", str(log_file),
"--vcpus", "4",
],
stdout=subprocess.DEVNULL,
stderr=subprocess.DEVNULL,
)
procs.append(proc)
nodes.append(HaNode(name=name, addr=addr, log_file=log_file))
if i < _N_NODES - 1:
time.sleep(_STAGGER_S)
for node, port in zip(nodes, ports):
wait_for_port("localhost", port, READY_TIMEOUT_S)
primary_node = _wait_for_primary(nodes, _ELECTION_TIMEOUT_S)
standby_nodes = [n for n in nodes if n.name != primary_node.name]
_wait_for_standbys(standby_nodes, _ELECTION_TIMEOUT_S)
# Settle window + fresh port reachability recheck (module
# docstring's "Election-wait" section has the full live-repro
# rationale): give the freshly-promoted primary one heartbeat
# interval to finish post-promotion warmup, then re-probe its port
# with the same helper used at initial boot rather than racing
# straight into the push against a still-flapping listener.
time.sleep(_POST_ELECTION_SETTLE_S)
primary_host, primary_port_str = primary_node.addr.rsplit(":", 1)
wait_for_port(primary_host, int(primary_port_str), READY_TIMEOUT_S)
yield HaCluster(primary=primary_node, standbys=standby_nodes)
finally:
for proc in procs:
proc.terminate()
for proc in procs:
try:
proc.wait(timeout=10)
except subprocess.TimeoutExpired:
proc.kill()
proc.wait(timeout=10)
shutil.rmtree(deploy_dir, ignore_errors=True)
def _build_cluster_bin(xceadmin_bin: Path, tmp_path: Path) -> Path:
cluster_bin = tmp_path / "cluster.bin"
build_result = subprocess.run(
[str(xceadmin_bin), "config", "build", str(REPO_CONFIGS_DIR), "-o", str(cluster_bin)],
capture_output=True,
text=True,
)
assert build_result.returncode == 0, build_result.stderr
assert cluster_bin.is_file()
return cluster_bin
def _assert_no_decode_crash(push_result: subprocess.CompletedProcess) -> None:
# Task 6.1's regression lock, same as task 6.2 -- no raw capnp
# exception or unhandled traceback against REAL wire bytes.
assert "KjException" not in push_result.stderr, push_result.stderr
assert "Traceback" not in push_result.stderr, push_result.stderr
def _assert_primary_committed(log_text: str, version_tag_hex: str) -> None:
assert f"tag={version_tag_hex}" in log_text, log_text
assert "Config change committed" in log_text
assert f"Config upgraded to tag={version_tag_hex}" in log_text
assert f"config activated from committed marker tag={version_tag_hex}" in log_text
def test_live_config_push_against_primary_reaches_success_path(
live_ha_cluster: HaCluster, tmp_path: Path
) -> None:
"""Pushing directly to the elected primary of a real 3-node cluster
exits 0 with a genuinely positive ``ackedCount`` (Requirements 2.1,
2.5, 2.6) -- the exact success path task 6.2's single-node topology
cannot reach (no standbys there to ACK). Independently confirms via
log evidence: the primary's own commit/activate lines (same as task
6.2) PLUS the primary's majority-ACK barrier log line naming a
positive per-standby pushed count, AND at least one standby's own log
showing it received and saved the pushed bytes.
"""
xceadmin_bin = find_first_executable(XCEADMIN_CANDIDATES)
if xceadmin_bin is None:
pytest.skip("no xceadmin binary found under xce.build/build.release/build.dbg")
cluster_bin = _build_cluster_bin(xceadmin_bin, tmp_path)
push_result = subprocess.run(
[str(xceadmin_bin), "config", "push", str(cluster_bin), "--controller", live_ha_cluster.primary.addr],
capture_output=True,
text=True,
)
_assert_no_decode_crash(push_result)
match = VERSION_TAG_RE.search(push_result.stdout)
assert match, f"no versionTag/ackedCount found in stdout: {push_result.stdout!r}"
version_tag, acked_count = int(match.group(1)), int(match.group(2))
assert version_tag > 0
# The real, live 3-node success path task 6.2 could not reach: a
# genuine positive ackedCount (real standby ACKs exist now) and exit 0
# (Requirement 2.6's postcondition, cli.py's `acked_count > 0` check).
assert acked_count > 0, (
f"expected a positive ackedCount from real standby ACKs, got {acked_count} "
f"(stdout={push_result.stdout!r} stderr={push_result.stderr!r})"
)
assert push_result.returncode == 0, push_result.stderr
version_tag_hex = f"{version_tag:016x}"
primary_log_text = live_ha_cluster.primary.log_file.read_text()
_assert_primary_committed(primary_log_text, version_tag_hex)
# Majority-ACK barrier evidence on the primary's own log: at least one
# standby genuinely acked this exact tag (push_config_to_standbys).
majority_match = _MAJORITY_ACK_RE.search(primary_log_text)
assert majority_match, primary_log_text
assert majority_match.group(1) == version_tag_hex
pushed, total = int(majority_match.group(2)), int(majority_match.group(3))
assert pushed >= 1, f"expected >=1 standby acked, got pushed={pushed}/{total}"
# Independent standby-side evidence: at least one of the two standbys'
# own logs shows it actually received and saved these exact bytes
# (handle_repl_config_push), not just the primary's report of it.
#
# Each standby receives >1 push over the fixture's lifetime -- an
# automatic bootstrap sync of the primary's already-loaded config fires
# right after election (ha_dispatch_repl_action_for_standby), BEFORE
# this test's own xceadmin push -- so this must check every occurrence
# (re.finditer), not just the first (re.search would silently match the
# earlier bootstrap push's tag instead of this push's tag and always
# fail here, independent of whether the real ACK happened).
standby_saw_it = any(
m.group(1) == version_tag_hex
for standby in live_ha_cluster.standbys
for m in _STANDBY_SAVED_RE.finditer(standby.log_file.read_text())
)
assert standby_saw_it, [s.log_file.read_text() for s in live_ha_cluster.standbys]
# errnox.h: XCE_ERRNO_BASE=10001, E_XCE_STANDBY is the 14th entry (0-indexed
# 13) in that enum => 10001+13=10014. "Controller in CTRL_STANDBY; op is
# primary-only" -- exactly the rejection a standby's OP_upgradeConfig hits
# (module docstring). Named here instead of a bare magic number per this
# project's error-handling convention of surfacing XCE's own error
# vocabulary rather than an unexplained literal.
_E_XCE_STANDBY = 10014
def test_live_config_push_against_standby_returns_standby_rejection_not_redirect(
live_ha_cluster: HaCluster, tmp_path: Path
) -> None:
"""Pushing `config push` directly to a standby node against a REAL
controller today does NOT redirect to the primary -- it is flatly
rejected with ``E_XCE_STANDBY`` (module docstring: a pre-existing,
already-documented controller-side gap, `fill_redirect_reply()` never
wired for `OPCode_upgradeConfig`; out of this test-only task's
boundary to fix). This test live-verifies and regression-locks that
REAL current behavior: no redirect line, no success, and specifically
the `E_XCE_STANDBY` status rather than some other/unexpected failure
mode, so a future change to the rejection path itself would also be
caught here even before the redirect gap is closed.
Confirms via ``discovery.py``'s own stderr line (`follow_redirects`:
"redirected: host:port -> host:port") being ABSENT -- direct evidence
no redirect was attempted, not an inference from the push merely
failing for some other reason.
"""
xceadmin_bin = find_first_executable(XCEADMIN_CANDIDATES)
if xceadmin_bin is None:
pytest.skip("no xceadmin binary found under xce.build/build.release/build.dbg")
cluster_bin = _build_cluster_bin(xceadmin_bin, tmp_path)
standby_addr = live_ha_cluster.standbys[0].addr
primary_addr = live_ha_cluster.primary.addr
push_result = subprocess.run(
[str(xceadmin_bin), "config", "push", str(cluster_bin), "--controller", standby_addr],
capture_output=True,
text=True,
)
_assert_no_decode_crash(push_result)
# No redirect was attempted -- the standby's reply never carries
# redirectHost/redirectPort for this opcode (module docstring), so
# discovery.py's follow_redirects has nothing to follow and never
# prints its "redirected: ..." line.
unexpected_redirect_line = f"redirected: {standby_addr} -> {primary_addr}"
assert unexpected_redirect_line not in push_result.stderr, (
"a redirect line appeared -- if the controller-side redirect gap "
"documented in this file's module docstring (design.md 'Boundary "
"Commitments' / 'Revalidation Triggers') has been closed, this "
"test is stale and should be replaced with a real success-path "
f"assertion: {push_result.stderr!r}"
)
match = VERSION_TAG_RE.search(push_result.stdout)
assert match, f"no versionTag/ackedCount found in stdout: {push_result.stdout!r}"
version_tag, acked_count = int(match.group(1)), int(match.group(2))
# Real, live-verified standby-contact behavior today: the reply is a
# bare gate rejection (versionTag=0 ackedCount=0), not a redirect or a
# partial success.
assert version_tag == 0
assert acked_count == 0
assert push_result.returncode == 1
assert f"controller returned status -{_E_XCE_STANDBY}" in push_result.stderr, push_result.stderr
# The rejected push never reached the primary at all -- its log shows
# no upgrade activity from this attempt (independent confirmation this
# is a clean gate rejection, not a landed-then-lost push).
primary_log_text = live_ha_cluster.primary.log_file.read_text()
assert "Config marker failed to reach committed prefix" not in primary_log_text