From 4cd5fb7dd8b58385ce875c8b682aa50336b15f99 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Sat, 3 Oct 2026 14:51:27 +0000 Subject: [PATCH] docs(buglog): bug-1683, bug-1485, bug-1725 fixed with corrected root causes; log bug-1913 Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 64 +++++++++++++++++++++++++++++++----------- .wolf/bugs/bug-1485.md | 17 ++++++----- .wolf/bugs/bug-1683.md | 17 ++++++----- .wolf/bugs/bug-1725.md | 13 +++++---- .wolf/bugs/bug-1913.md | 59 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 133 insertions(+), 37 deletions(-) create mode 100644 .wolf/bugs/bug-1913.md diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 3900a9e1..702d5898 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -6084,9 +6084,9 @@ }, { "id": "bug-1485", - "status": "investigating", + "status": "fixed", "status_updated": "2026-10-03", - "status_note": "2026-10-03, controller-peers-env-fallback task 4.2 review: one run of 'bash src/tools/xce-build.sh xceadmin --incremental' failed this test with a NEW symptom, assert version_tag > 0 got 0 (not a refused connection); passed on the immediate re-run and on a run with XCE_CONTROLLER_PEERS exported. The diff under test touched only xceadmin cli.py/test_cli.py and this test passes --controller explicitly, so unrelated.", + "status_note": "", "component": "xceadmin", "severity": "unknown", "timestamp": "2026-07-30T14:35:00Z", @@ -6094,8 +6094,8 @@ "occurrences": 26, "error_message": "test_e2e_live_ha_push.py::test_live_config_push_against_primary_reaches_success_path flaky…\n\ntest_e2e_live_ha_push.py::test_live_config_push_against_primary_reaches_success_path flaky (near-100% fail rate across ~25 live runs during admin-config-tool task 6.3 round-2 remediation): TimeoutError: controller never opened localhost:: [Errno 111] Connection refused, raised from a fresh wait_for_port re-probe of the elected primary's own address performed AFTER _wait_for_primary (CTRL_PRIMARY marker) + a new _wait_for_standbys (both other nodes show CTRL_STANDBY) + a 3s settle sleep all already succeeded.", "file": "src/xceadmin/tests/test_e2e_live_ha_push.py (live_ha_cluster fixture); root cause is in src/controller (exact site not yet isolated -- C-side investigation out of this task's boundary)", - "root_cause": "NOT a pure test-side readiness race as round-1 review assumed. Live forensic capture (ps aux mid-run) caught the freshly-elected ctrl-1 as a zombie process moments after its own log recorded the full raft_cb_become_leader promotion sequence ending at 'HA: repl registered standby ep[1] (slot 1, ...)' -- the log then goes silent (no crash trace, no further lines) and the process is gone. stderr was DEVNULL'd in the fixture so no ASAN/signal diagnostic was captured from a real failing pytest run. Confusingly, 3 separate standalone (non-pytest) repro scripts using byte-identical spawn code (same xce_controller build.dbg binary, same deploy-ha.sh cluster, same peers/certs/workdir args) ran the exact same primary-promotion sequence successfully every single time with the primary staying alive and the port reachable for 20-30s post-election -- while pytest-invoked runs of the identical fixture code failed roughly 24/25 times. Ruled out during investigation: pytest's default fd-capture (reproduced with -s / capturing disabled, still failed 3/3), ulimits (NPROC/NOFILE/AS/STACK identical between nix-develop plain-shell and pytest-invoked-via-python contexts), and orphaned-process port contention (ps aux clean before each batch). True root cause not isolated -- prime suspects are a genuine timing-sensitive controller-side crash/race in the CTRL_STANDBY->CTRL_PRIMARY raft promotion path (raft_cb_become_leader / repl registration) that pytest's process tree somehow makes far more likely to trigger, or a process-group/session/signal-mask difference inherited by subprocess.Popen children when the parent is pytest vs a bare python3 script.", - "fix": "UPDATE 2026-08-01 -- investigated per this entry's own \"next step\" (capture stderr instead of DEVNULL, re-attempt). Redirected each node's stderr to deploy_dir/logs/.stderr.log (permanent change to test_e2e_live_ha_push.py, replacing the DEVNULL redirect that left this entry's original investigation with no diagnostic) and added an XCE_KEEP_DEPLOY_DIR=1 debug env var to preserve deploy_dir across the fixture's own cleanup for inspection. Ran the live test 40 times total in this environment: 25 baseline (idle sandbox, load avg ~2/22 cores) + 15 more with a concurrent `xce-build.sh controller debug` compile racing for CPU (separate build.dbg dir, so it could not clobber the xce.build controller binary the test depends on -- unlike bug-1486's same-dir clobber shape). Result: 40/40 PASSED, 0/120 captured stderr logs (3 nodes x 40 runs) non-empty -- no crash, no ASAN report, in any run. Could NOT reproduce the ~24/25 failure rate from the original investigation despite matching the documented repro shape exactly (same binaries, same fixture code, same pytest invocation).\n\nNOT marking fixed -- absence of reproduction here is not proof of absence of the underlying bug, and this session's single concurrent compile is a much lighter contention scenario than the real multi-session sandbox reality bug-1486 documents (several concurrent AGENT SESSIONS, potentially each running their own live 3-node cluster). Leading hypothesis (unconfirmed): the original ~24/25 failure rate was itself a symptom of resource contention from OTHER concurrent sessions on the shared sandbox during that investigation (CPU starvation delaying the primary's post-election warmup past _POST_ELECTION_SETTLE_S, or an OOM-adjacent condition killing the freshly-forked primary outright) rather than a bug in the promotion path reachable in isolation -- consistent with the original investigation's own \"pytest's process tree somehow makes far more likely\" framing, since pytest's subprocess tree carries more memory/fd overhead than the bare python3 scripts that never reproduced it there either.\n\nDowngraded to low-priority/environment-flake, left OPEN. The stderr-capture infrastructure is now permanently in place (not reverted) so the next real live failure -- in pytest, in a genuinely contended multi-session sandbox, or in CI -- captures an actual ASAN report or signal instead of DEVNULL silence, which is what would actually close this out.", + "root_cause": "Corrected 2026-10-03, superseding the earlier zombie-primary / CPU-starvation hypotheses (kept in git history; the zombie symptom was never reproduced). The 2026-10-03 symptom `version_tag == 0` is an error reply, not a bad success: `push.py` maps any non-zero status to `versionTag=0 ackedCount=0`, and the controller rejected the push with -110 (`config_repl.c` ~1839-1845, `repl_wait_majority_ack` 500 ms). It happens after a \"late-joiner\" election: the own-term no-op (lsn 1) is appended before any standby is registered (ha.c ~5178, repl.c ~306-311), the standbys register later via `on_standby_connected` (ha.c ~9643-9660) without the no-op being resent, and heartbeat-driven catch-up commits it only ~6 s (two 3 s cycles) after the election. A push in that window is NACKed by both standbys and times out. The fixture's readiness check (role markers + 3 s settle) did not cover that window. The controller behaviour itself (fail-loud rejection) is correct; its ~6 s write-unavailability is tracked as bug-1913.", + "fix": "Test-side (`src/xceadmin/tests`): new `wait_for_primary_write_ready()` / `primary_write_ready()` in `_live_e2e_common.py` wait until a commit logged after the latest \"own-term noop appended lsn=N\" reaches N; the `live_ha_cluster` fixture calls it (30 s) after waiting for standbys; versionTag assertions now print the CLI's stdout/stderr. Fix commit 362098b1.\n\nVerification:\n- Test: `test_live_config_push_against_primary_reaches_success_path` in `src/xceadmin/tests/test_e2e_live_ha_push.py` — RED before under CPU load (40 busy loops): 7/28 runs failed with `expected a non-zero versionTag, got 0 (... stderr='Error: controller returned status -110')`, all late-joiner elections; GREEN after: 95 looped runs incl. 24 under the same load (7 late-joiner elections, all passed). Helper unit tests in `test_live_e2e_common.py` (no-op not committed → not ready; latest no-op only; commits before the latest no-op ignored).\n- Suites: xceadmin 373 passed, 2026-10-03.\n- Live: residual, different mechanism: under heavy oversubscription a normally-elected primary can miss the 500 ms marker barrier (1/70 HA loops).", "tags": [ "flaky-test", "ha", @@ -6112,7 +6112,9 @@ "bug-1479", "bug-606" ], - "fix_commits": [], + "fix_commits": [ + "362098b1" + ], "record": ".wolf/bugs/bug-1485.md", "repro_attempts": "0/40 repro attempts (2026-08-01)" }, @@ -9658,18 +9660,18 @@ }, { "id": "bug-1683", - "status": "open", + "status": "fixed", "status_updated": "2026-10-03", - "status_note": "2026-10-03, controller-peers-env-fallback task 4.1: xce-build.sh xceadmin --incremental run 1 failed test_wire.py::test_send_frame_writes_exact_known_good_byte_sequence (header captured, xce! payload missing); run 2 immediately after passed (314 passed). Diff under test touched only discovery.py/errors.py/test_discovery.py, so unrelated.", + "status_note": "", "component": "xceadmin", "severity": "unknown", "timestamp": "2026-08-25T00:05:00Z", "last_seen": "2026-10-03T07:27:36Z", "occurrences": 3, - "error_message": "xceadmin pytest failure: test_send_frame_writes_exact_known_good_byte_sequence…\n\nxceadmin pytest failure: test_send_frame_writes_exact_known_good_byte_sequence (src/xceadmin/tests/test_wire.py:200). Test sends a 4-byte payload b'xce!' via wire.send_frame() over a real TLS socket to a raw capture handler that reads exactly 12 bytes (8-byte length header + 4-byte payload) directly off the wire, bypassing this module's own recv_frame() decoder. Expected the captured bytes to be struct.pack('=Q', 4) + b'xce!' (header correctly encodes length=4, followed by the literal payload bytes). Actual captured bytes: the 8-byte header is correct (b'\\x04\\x00\\x00\\x00\\x00\\x00\\x00\\x00', i.e. length=4 little-endian native uint64_t), but the trailing 4 bytes are all zero (b'\\x00\\x00\\x00\\x00') instead of b'xce!' -- the real payload bytes never reached the wire. 1 failed, 266 passed, 3 skipped -- isolated to this one test.", + "error_message": "xceadmin pytest failure: test_send_frame_writes_exact_known_good_byte_sequence…\n\nxceadmin pytest failure: test_send_frame_writes_exact_known_good_byte_sequence (src/xceadmin/tests/test_wire.py:200). Test sends a 4-byte payload b'xce!' via wire.send_frame() over a real TLS socket to a raw capture handler that reads exactly 12 bytes (8-byte length header + 4-byte payload) directly off the wire, bypassing this module's own recv_frame() decoder. Expected the captured bytes to be struct.pack('=Q', 4) + b'xce!' (header correctly encodes length=4, followed by the literal payload bytes). Actual captured bytes: the 8-byte header is correct (b'\\x04\\x00\\x00\\x00\\x00\\x00\\x00\\x00', i.e. length=4 little-endian native uint64_t), but the trailing 4 bytes are all zero (b'\\x00\\x00\\x00\\x00') instead of b'xce!' -- the real payload bytes never reached the wire. 1 failed, 266 passed, 3 skipped -- isolated to this one test.\n\nUPDATE (2026-10-03): Correction: the trailing bytes were never zeroed -- pytest's truncated diff showed the 8-byte header alone. See Root cause (test-harness TLS RST race).", "file": "src/xceadmin/src/xcecommon/wire.py", - "root_cause": "UNRESOLVED -- not reproducible. send_frame() (wire.py:102-113) is two sequential sock.sendall() calls (header, then payload) -- nothing in it, or in the test's _TlsEchoServer/_capture_handler harness (test_wire.py), or conftest.py's session-scoped tls_certs fixture, could zero out payload bytes; all reviewed and found correct. Confirmed only bare pytest 8.4.2 is installed (no pytest-xdist, no pytest-randomly, no addopts) -- test order is deterministic, ruling out parallel-worker/reordering interference.\n\n45+ reproduction attempts (2026-08-25), zero failures: isolated run x5, full test_wire.py x3, full 270-test suite x3 (ad-hoc PYTHONPATH), full meson-driven build+test pipeline (xce-build.sh xceadmin, the project's real test-running convention) x1 clean (267 passed, 3 skipped), isolated via the meson-built venv x15, full suite via meson-built venv x5, full suite under artificial CPU stress (20x `yes` spinners, load 11+) x5, 8-way concurrent parallel execution of the exact test x8 -- all clean. TCP/TLS cannot spontaneously zero application bytes mid-stream, so a genuine code defect producing this exact symptom (correct 8-byte header, real zeroed 4-byte payload) should be deterministically reproducible, and it isn't.", - "fix": "Not a code fix -- treating as a suspected ONE-OFF ENVIRONMENTAL/INFRASTRUCTURE artifact, not a defect in current source. This project is documented (.wolf/cerebrum.md, bug-1604) to run many concurrent automated sessions that race on shared build directories -- e.g. a concurrent xce-build.sh/meson-build.sh invocation's `rm -rf \"$WORK_DIR\"` + `cp -r` mirror step, if raced by another concurrent invocation touching the same build dir, is a plausible analogous corruption mechanism (already confirmed for other components under bug-1604's pattern) -- but no direct evidence this happened for bug-1683 specifically, since it has not recurred. No code changes made. If this recurs, capture `ps aux` (or similar) for a concurrent xce-build.sh/meson-build.sh run racing the same build directory at failure time, per the bug-1604 precedent -- that is the most useful missing evidence right now.", + "root_cause": "Corrected 2026-10-03, superseding the earlier \"not reproducible / build-dir race (bug-1604)\" analysis (kept in git history). Test-harness race in `src/xceadmin/tests/test_wire.py` `test_send_frame_writes_exact_known_good_byte_sequence`: the client called `send_frame()` and then `sock.close()` immediately. Under TLS 1.3 the server sends NewSessionTicket records after the handshake that the client never reads; closing a TCP socket with unread inbound data makes Linux send RST instead of FIN. Each `sendall()` is its own TLS record, so when the RST lands between the server's read of the 8-byte header record and the 4-byte payload record, the unread payload is discarded and `recv()` raises ConnectionResetError/BrokenPipeError, which `_TlsEchoServer._run` swallowed with a bare `pass` -- leaving `captured` = header only. The \"4 zero bytes\" in the original description was a misreading of pytest's truncated diff of the 8-byte header. `wire.send_frame()` is correct; production paths read the reply before closing and are not exposed.", + "fix": "`test_wire.py` only: the client waits on a `capture_done` Event (set in the handler's `finally`) before `sock.close()`; `_TlsEchoServer` records the handler's OSError in `handler_error` (asserted None) instead of discarding it; the test is parametrized with `settle_s` [0.0, 0.05] (`immediate` / `tickets-pending`), the 0.05 case being a deterministic regression for the RST path. Fix commit 362098b1.\n\nVerification:\n- Test: `test_send_frame_writes_exact_known_good_byte_sequence[tickets-pending]` in `src/xceadmin/tests/test_wire.py` — RED before the fix (`assert b'\\x04\\x00...\\x00' == b'\\x04\\x00...xce!'`; reviewer's scratch copy without the wait: 5/5 ConnectionResetError 104), GREEN after; 200 looped runs 0 failures; scratch harness 8/2000 natural failures before vs 0/2000 after.\n- Suites: `bash src/tools/xce-build.sh xceadmin --incremental` 373 passed, 2026-10-03.\n- Live: n/a", "tags": [ "xceadmin", "xcecommon", @@ -9682,7 +9684,9 @@ "related_bugs": [ "bug-1604" ], - "fix_commits": [], + "fix_commits": [ + "362098b1" + ], "record": ".wolf/bugs/bug-1683.md" }, { @@ -11051,9 +11055,9 @@ }, { "id": "bug-1725", - "status": "open", + "status": "fixed", "status_updated": "2026-10-03", - "status_note": "2026-10-03, controller-peers-env-fallback task 4.2 (RED run): test_e2e_live_push.py::test_live_config_push_against_real_single_node_controller failed once — 'config activated from committed marker tag=...' not yet in the controller log after the push returned; passed on the next two full xceadmin runs. Diff under test touched only xceadmin cli.py/test_cli.py and the test passes --controller explicitly, so unrelated.", + "status_note": "", "component": "xceadmin", "severity": "unknown", "timestamp": "2026-08-28T00:00:00Z", @@ -11061,8 +11065,8 @@ "occurrences": 2, "error_message": "After bug-1724's fix made…\n\nAfter bug-1724's fix made test_live_config_push_against_standby_returns_standby_rejection_not_redirect actually execute (previously always skipped), it FAILED for real: pushing config to a standby now redirects to the primary and succeeds, contradicting the test's own hard-coded 'standby flatly rejects, no redirect' assertions. Separately, the rewritten success-path test's reused _assert_primary_committed() helper intermittently failed its 4th assertion ('config activated from committed marker tag=...' not found in the primary's log immediately after the push CLI returned success).", "file": "src/xceadmin/tests/test_e2e_live_ha_push.py", - "root_cause": "(1) The test's assumption was stale, not wrong test infra: bug-1700/1701 (fixed 2026-08-26) closed the exact standby-redirect gap this test was written to regression-lock, at the generic ha_dispatch_gate() rejection level in cluster.c -- the test's own docstring had explicitly predicted this exact failure as the correct signal to replace it with a success-path assertion. design.md ('Boundary Commitments'/'Revalidation Triggers') and roadmap.md still described the gap as open. (2) config_activate_committed() on the primary runs off the WAL apply-pump dispatch (persist.c ~5111, the bug-1469 fix), asynchronously relative to the majority-ack-gated client reply (commitIndex vs lastApplied are distinct steps) -- the CLI can legitimately return success before the primary's own local apply of that marker has logged its activation line, a latent race in the existing single-shot log read shared by the direct-to-primary test too.", - "fix": "Renamed and rewrote the test as test_live_config_push_against_standby_redirects_and_succeeds, asserting the redirect line IS present and the push succeeds (same success bar as the direct-to-primary test: positive ackedCount, exit 0, primary commit evidence). Updated the module docstring, design.md (Boundary Commitments, Revalidation Triggers, sequence-diagram note, redirect-implementation rationale, Testing Strategy), and roadmap.md's corresponding item to describe the gap as closed instead of open -- also corrected an adjacent, independently-verified stale claim (bug-1468, fixed 2026-07-25, already resolved but never reflected in design.md) that no controller role could reach the upgradeConfig handler at all. For the activation race, changed _assert_primary_committed() from a single-shot log_text argument to a Path-based helper that polls (up to 5s, 0.2s interval) for the activation line instead of assuming synchronous ordering, and updated both call sites. Verified end-to-end: full xce-build.sh xceadmin run now passes 288/288 with zero skips/failures.", + "root_cause": "Corrected 2026-10-03. Part (1) of the original entry (stale standby-redirect assertion) was fixed earlier. Part (2), the recurring flake: the controller replies to the push before two of the lines the tests assert are logged — \"Config upgraded to tag=\" is logged right after `xce_reply()` (`config_repl.c` ~1865-1873) and \"config activated from committed marker\" comes from `config_activate_committed()` (`config_repl.c` ~376) on the asynchronous WAL apply pump. `test_e2e_live_push.py` read the log once with no polling (the 2026-10-03 recurrence), and the HA helper polled only for the activation line, not \"Config upgraded\".", + "fix": "Shared `assert_primary_committed()` in `src/xceadmin/tests/_live_e2e_common.py` polls (5 s) until the commit, upgrade and activation lines are all present, then asserts each; both live tests use it. Fix commit 362098b1.\n\nVerification:\n- Test: helper unit tests in `src/xceadmin/tests/test_live_e2e_common.py` (lines logged after the reply are waited for; missing activation line fails; missing \"Config upgraded\" line fails) — the old single-read and activation-only patterns fail deterministically when the late lines are written 0.3 s after the read; GREEN after. Live tests looped 95 runs (incl. heavy CPU load) with 0 bug-1725 failures.\n- Suites: xceadmin 373 passed, 2026-10-03.\n- Live: n/a", "tags": [ "xceadmin", "config-push", @@ -11083,7 +11087,9 @@ "bug-1701", "bug-1468" ], - "fix_commits": [], + "fix_commits": [ + "362098b1" + ], "record": ".wolf/bugs/bug-1725.md" }, { @@ -17117,6 +17123,32 @@ "ef6e562c" ], "record": ".wolf/bugs/bug-1912.md" + }, + { + "id": "bug-1913", + "status": "open", + "status_updated": "2026-10-03", + "status_note": "newly logged", + "component": "controller", + "severity": "wrong-result", + "timestamp": "2026-10-03T14:18:58Z", + "last_seen": "2026-10-03T14:18:58Z", + "occurrences": 1, + "error_message": "after a late-joiner election the primary cannot commit client writes for ~2 heartbeat cycles\n\n**Observed:**\n```\nrepl_broadcast: no standbys registered ... not replicated\n...\nWAL NACK from standby lsn=2 ... marking catch-up\nrepl_wait_majority_ack: timeout ... OP_upgradeConfig rejected (status=-110)\n```\nIn some elections the vote connections are not converted into standby channels (`raft_cb_become_leader`), so both standbys register later through `on_standby_connected` (ha.c ~9643-9660). `ha_arm_own_term_gate` (ha.c ~5178) has already appended the own-term WAL_NOOP (lsn 1) while no standby was registered (repl.c ~306-311), and `repl_add_standby` does not resend it. Catch-up then runs from the 3 s heartbeat, one action per standby per cycle (config push first, WAL stream on the next cycle), so `committed_lsn` stays 0 for ~6 s. Any client write in that window (e.g. `OP_upgradeConfig`) is NACKed by both standbys and fails with -ETIMEDOUT after the 500 ms majority wait.\n\n**Expected:** a newly elected primary commits its own-term no-op, and so accepts client writes, promptly after its standbys register, not two heartbeat cycles later.\n**Impact:** for ~6 s after such an election every client write is rejected with -110 (fail-loud, no data loss, no false success). Clients retry, but tests and operators see spurious failures right after failover (the root cause of bug-1485's versionTag=0 flake). A fix must respect the async-I/O rules (no blocking on the delaymgr/heartbeat path; streaming offloaded) in `.kiro/steering/ha-async-io.md`.\n**Found by:** test (root cause of bug-1485)", + "file": "src/controller/ha.c, src/controller/repl.c, src/controller/config_repl.c", + "root_cause": "TODO: required for fixed/partial", + "fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "tags": [ + "ha", + "raft", + "replication", + "latency" + ], + "related_bugs": [ + "bug-1485" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1913.md" } ] } diff --git a/.wolf/bugs/bug-1485.md b/.wolf/bugs/bug-1485.md index de8dc6b1..9739f589 100644 --- a/.wolf/bugs/bug-1485.md +++ b/.wolf/bugs/bug-1485.md @@ -1,8 +1,8 @@ --- id: "bug-1485" -status: "investigating" +status: "fixed" status_updated: "2026-10-03" -status_note: "2026-10-03, controller-peers-env-fallback task 4.2 review: one run of 'bash src/tools/xce-build.sh xceadmin --incremental' failed this test with a NEW symptom, assert version_tag > 0 got 0 (not a refused connection); passed on the immediate re-run and on a run with XCE_CONTROLLER_PEERS exported. The diff under test touched only xceadmin cli.py/test_cli.py and this test passes --controller explicitly, so unrelated." +status_note: "" component: "xceadmin" severity: "unknown" timestamp: "2026-07-30T14:35:00Z" @@ -11,6 +11,7 @@ occurrences: 26 files: ["src/xceadmin/tests/test_e2e_live_ha_push.py (live_ha_cluster fixture); root cause is in src/controller (exact site not yet isolated -- C-side investigation out of this task's boundary)"] tags: ["flaky-test", "ha", "raft-election", "controller-crash", "admin-config-tool", "task-6.3", "e2e-live", "unresolved", "pytest-specific"] related: ["bug-1477", "bug-1479", "bug-606"] +fix_commits: ["362098b1"] repro_attempts: "0/40 repro attempts (2026-08-01)" legacy: true --- @@ -27,17 +28,15 @@ _Not recorded (migrated from buglog.json)._ - Attempts: 0/40 repro attempts (2026-08-01) ## Root cause -NOT a pure test-side readiness race as round-1 review assumed. Live forensic capture (ps aux mid-run) caught the freshly-elected ctrl-1 as a zombie process moments after its own log recorded the full raft_cb_become_leader promotion sequence ending at 'HA: repl registered standby ep[1] (slot 1, ...)' -- the log then goes silent (no crash trace, no further lines) and the process is gone. stderr was DEVNULL'd in the fixture so no ASAN/signal diagnostic was captured from a real failing pytest run. Confusingly, 3 separate standalone (non-pytest) repro scripts using byte-identical spawn code (same xce_controller build.dbg binary, same deploy-ha.sh cluster, same peers/certs/workdir args) ran the exact same primary-promotion sequence successfully every single time with the primary staying alive and the port reachable for 20-30s post-election -- while pytest-invoked runs of the identical fixture code failed roughly 24/25 times. Ruled out during investigation: pytest's default fd-capture (reproduced with -s / capturing disabled, still failed 3/3), ulimits (NPROC/NOFILE/AS/STACK identical between nix-develop plain-shell and pytest-invoked-via-python contexts), and orphaned-process port contention (ps aux clean before each batch). True root cause not isolated -- prime suspects are a genuine timing-sensitive controller-side crash/race in the CTRL_STANDBY->CTRL_PRIMARY raft promotion path (raft_cb_become_leader / repl registration) that pytest's process tree somehow makes far more likely to trigger, or a process-group/session/signal-mask difference inherited by subprocess.Popen children when the parent is pytest vs a bare python3 script. +Corrected 2026-10-03, superseding the earlier zombie-primary / CPU-starvation hypotheses (kept in git history; the zombie symptom was never reproduced). The 2026-10-03 symptom `version_tag == 0` is an error reply, not a bad success: `push.py` maps any non-zero status to `versionTag=0 ackedCount=0`, and the controller rejected the push with -110 (`config_repl.c` ~1839-1845, `repl_wait_majority_ack` 500 ms). It happens after a "late-joiner" election: the own-term no-op (lsn 1) is appended before any standby is registered (ha.c ~5178, repl.c ~306-311), the standbys register later via `on_standby_connected` (ha.c ~9643-9660) without the no-op being resent, and heartbeat-driven catch-up commits it only ~6 s (two 3 s cycles) after the election. A push in that window is NACKed by both standbys and times out. The fixture's readiness check (role markers + 3 s settle) did not cover that window. The controller behaviour itself (fail-loud rejection) is correct; its ~6 s write-unavailability is tracked as bug-1913. ## Fix -UPDATE 2026-08-01 -- investigated per this entry's own "next step" (capture stderr instead of DEVNULL, re-attempt). Redirected each node's stderr to deploy_dir/logs/.stderr.log (permanent change to test_e2e_live_ha_push.py, replacing the DEVNULL redirect that left this entry's original investigation with no diagnostic) and added an XCE_KEEP_DEPLOY_DIR=1 debug env var to preserve deploy_dir across the fixture's own cleanup for inspection. Ran the live test 40 times total in this environment: 25 baseline (idle sandbox, load avg ~2/22 cores) + 15 more with a concurrent `xce-build.sh controller debug` compile racing for CPU (separate build.dbg dir, so it could not clobber the xce.build controller binary the test depends on -- unlike bug-1486's same-dir clobber shape). Result: 40/40 PASSED, 0/120 captured stderr logs (3 nodes x 40 runs) non-empty -- no crash, no ASAN report, in any run. Could NOT reproduce the ~24/25 failure rate from the original investigation despite matching the documented repro shape exactly (same binaries, same fixture code, same pytest invocation). - -NOT marking fixed -- absence of reproduction here is not proof of absence of the underlying bug, and this session's single concurrent compile is a much lighter contention scenario than the real multi-session sandbox reality bug-1486 documents (several concurrent AGENT SESSIONS, potentially each running their own live 3-node cluster). Leading hypothesis (unconfirmed): the original ~24/25 failure rate was itself a symptom of resource contention from OTHER concurrent sessions on the shared sandbox during that investigation (CPU starvation delaying the primary's post-election warmup past _POST_ELECTION_SETTLE_S, or an OOM-adjacent condition killing the freshly-forked primary outright) rather than a bug in the promotion path reachable in isolation -- consistent with the original investigation's own "pytest's process tree somehow makes far more likely" framing, since pytest's subprocess tree carries more memory/fd overhead than the bare python3 scripts that never reproduced it there either. - -Downgraded to low-priority/environment-flake, left OPEN. The stderr-capture infrastructure is now permanently in place (not reverted) so the next real live failure -- in pytest, in a genuinely contended multi-session sandbox, or in CI -- captures an actual ASAN report or signal instead of DEVNULL silence, which is what would actually close this out. +Test-side (`src/xceadmin/tests`): new `wait_for_primary_write_ready()` / `primary_write_ready()` in `_live_e2e_common.py` wait until a commit logged after the latest "own-term noop appended lsn=N" reaches N; the `live_ha_cluster` fixture calls it (30 s) after waiting for standbys; versionTag assertions now print the CLI's stdout/stderr. Fix commit 362098b1. ## Verification -_Not recorded (migrated from buglog.json)._ +- Test: `test_live_config_push_against_primary_reaches_success_path` in `src/xceadmin/tests/test_e2e_live_ha_push.py` — RED before under CPU load (40 busy loops): 7/28 runs failed with `expected a non-zero versionTag, got 0 (... stderr='Error: controller returned status -110')`, all late-joiner elections; GREEN after: 95 looped runs incl. 24 under the same load (7 late-joiner elections, all passed). Helper unit tests in `test_live_e2e_common.py` (no-op not committed → not ready; latest no-op only; commits before the latest no-op ignored). +- Suites: xceadmin 373 passed, 2026-10-03. +- Live: residual, different mechanism: under heavy oversubscription a normally-elected primary can miss the 500 ms marker barrier (1/70 HA loops). ## References - Related: bug-1477, bug-1479, bug-606 diff --git a/.wolf/bugs/bug-1683.md b/.wolf/bugs/bug-1683.md index d5851506..5c40a877 100644 --- a/.wolf/bugs/bug-1683.md +++ b/.wolf/bugs/bug-1683.md @@ -1,8 +1,8 @@ --- id: "bug-1683" -status: "open" +status: "fixed" status_updated: "2026-10-03" -status_note: "2026-10-03, controller-peers-env-fallback task 4.1: xce-build.sh xceadmin --incremental run 1 failed test_wire.py::test_send_frame_writes_exact_known_good_byte_sequence (header captured, xce! payload missing); run 2 immediately after passed (314 passed). Diff under test touched only discovery.py/errors.py/test_discovery.py, so unrelated." +status_note: "" component: "xceadmin" severity: "unknown" timestamp: "2026-08-25T00:05:00Z" @@ -11,6 +11,7 @@ occurrences: 3 files: ["src/xceadmin/src/xcecommon/wire.py"] tags: ["xceadmin", "xcecommon", "wire-protocol", "python", "framing", "test-failure", "unreproducible"] related: ["bug-1604"] +fix_commits: ["362098b1"] legacy: true --- @@ -19,6 +20,8 @@ legacy: true ## Description xceadmin pytest failure: test_send_frame_writes_exact_known_good_byte_sequence (src/xceadmin/tests/test_wire.py:200). Test sends a 4-byte payload b'xce!' via wire.send_frame() over a real TLS socket to a raw capture handler that reads exactly 12 bytes (8-byte length header + 4-byte payload) directly off the wire, bypassing this module's own recv_frame() decoder. Expected the captured bytes to be struct.pack('=Q', 4) + b'xce!' (header correctly encodes length=4, followed by the literal payload bytes). Actual captured bytes: the 8-byte header is correct (b'\x04\x00\x00\x00\x00\x00\x00\x00', i.e. length=4 little-endian native uint64_t), but the trailing 4 bytes are all zero (b'\x00\x00\x00\x00') instead of b'xce!' -- the real payload bytes never reached the wire. 1 failed, 266 passed, 3 skipped -- isolated to this one test. +UPDATE (2026-10-03): Correction: the trailing bytes were never zeroed -- pytest's truncated diff showed the 8-byte header alone. See Root cause (test-harness TLS RST race). + ## Environment _Not recorded (migrated from buglog.json)._ @@ -26,15 +29,15 @@ _Not recorded (migrated from buglog.json)._ _Not recorded (migrated from buglog.json)._ ## Root cause -UNRESOLVED -- not reproducible. send_frame() (wire.py:102-113) is two sequential sock.sendall() calls (header, then payload) -- nothing in it, or in the test's _TlsEchoServer/_capture_handler harness (test_wire.py), or conftest.py's session-scoped tls_certs fixture, could zero out payload bytes; all reviewed and found correct. Confirmed only bare pytest 8.4.2 is installed (no pytest-xdist, no pytest-randomly, no addopts) -- test order is deterministic, ruling out parallel-worker/reordering interference. - -45+ reproduction attempts (2026-08-25), zero failures: isolated run x5, full test_wire.py x3, full 270-test suite x3 (ad-hoc PYTHONPATH), full meson-driven build+test pipeline (xce-build.sh xceadmin, the project's real test-running convention) x1 clean (267 passed, 3 skipped), isolated via the meson-built venv x15, full suite via meson-built venv x5, full suite under artificial CPU stress (20x `yes` spinners, load 11+) x5, 8-way concurrent parallel execution of the exact test x8 -- all clean. TCP/TLS cannot spontaneously zero application bytes mid-stream, so a genuine code defect producing this exact symptom (correct 8-byte header, real zeroed 4-byte payload) should be deterministically reproducible, and it isn't. +Corrected 2026-10-03, superseding the earlier "not reproducible / build-dir race (bug-1604)" analysis (kept in git history). Test-harness race in `src/xceadmin/tests/test_wire.py` `test_send_frame_writes_exact_known_good_byte_sequence`: the client called `send_frame()` and then `sock.close()` immediately. Under TLS 1.3 the server sends NewSessionTicket records after the handshake that the client never reads; closing a TCP socket with unread inbound data makes Linux send RST instead of FIN. Each `sendall()` is its own TLS record, so when the RST lands between the server's read of the 8-byte header record and the 4-byte payload record, the unread payload is discarded and `recv()` raises ConnectionResetError/BrokenPipeError, which `_TlsEchoServer._run` swallowed with a bare `pass` -- leaving `captured` = header only. The "4 zero bytes" in the original description was a misreading of pytest's truncated diff of the 8-byte header. `wire.send_frame()` is correct; production paths read the reply before closing and are not exposed. ## Fix -Not a code fix -- treating as a suspected ONE-OFF ENVIRONMENTAL/INFRASTRUCTURE artifact, not a defect in current source. This project is documented (.wolf/cerebrum.md, bug-1604) to run many concurrent automated sessions that race on shared build directories -- e.g. a concurrent xce-build.sh/meson-build.sh invocation's `rm -rf "$WORK_DIR"` + `cp -r` mirror step, if raced by another concurrent invocation touching the same build dir, is a plausible analogous corruption mechanism (already confirmed for other components under bug-1604's pattern) -- but no direct evidence this happened for bug-1683 specifically, since it has not recurred. No code changes made. If this recurs, capture `ps aux` (or similar) for a concurrent xce-build.sh/meson-build.sh run racing the same build directory at failure time, per the bug-1604 precedent -- that is the most useful missing evidence right now. +`test_wire.py` only: the client waits on a `capture_done` Event (set in the handler's `finally`) before `sock.close()`; `_TlsEchoServer` records the handler's OSError in `handler_error` (asserted None) instead of discarding it; the test is parametrized with `settle_s` [0.0, 0.05] (`immediate` / `tickets-pending`), the 0.05 case being a deterministic regression for the RST path. Fix commit 362098b1. ## Verification -_Not recorded (migrated from buglog.json)._ +- Test: `test_send_frame_writes_exact_known_good_byte_sequence[tickets-pending]` in `src/xceadmin/tests/test_wire.py` — RED before the fix (`assert b'\x04\x00...\x00' == b'\x04\x00...xce!'`; reviewer's scratch copy without the wait: 5/5 ConnectionResetError 104), GREEN after; 200 looped runs 0 failures; scratch harness 8/2000 natural failures before vs 0/2000 after. +- Suites: `bash src/tools/xce-build.sh xceadmin --incremental` 373 passed, 2026-10-03. +- Live: n/a ## References - Related: bug-1604 diff --git a/.wolf/bugs/bug-1725.md b/.wolf/bugs/bug-1725.md index bcd5748f..311e8a0b 100644 --- a/.wolf/bugs/bug-1725.md +++ b/.wolf/bugs/bug-1725.md @@ -1,8 +1,8 @@ --- id: "bug-1725" -status: "open" +status: "fixed" status_updated: "2026-10-03" -status_note: "2026-10-03, controller-peers-env-fallback task 4.2 (RED run): test_e2e_live_push.py::test_live_config_push_against_real_single_node_controller failed once — 'config activated from committed marker tag=...' not yet in the controller log after the push returned; passed on the next two full xceadmin runs. Diff under test touched only xceadmin cli.py/test_cli.py and the test passes --controller explicitly, so unrelated." +status_note: "" component: "xceadmin" severity: "unknown" timestamp: "2026-08-28T00:00:00Z" @@ -11,6 +11,7 @@ occurrences: 2 files: ["src/xceadmin/tests/test_e2e_live_ha_push.py"] tags: ["xceadmin", "config-push", "redirect", "OPCode_upgradeConfig", "stale-test", "design-doc-sync", "roadmap-sync", "race-condition", "config_activate_committed", "found-live", "root-caused", "live-verified"] related: ["bug-1724", "bug-1700", "bug-1701", "bug-1468"] +fix_commits: ["362098b1"] legacy: true --- @@ -26,13 +27,15 @@ _Not recorded (migrated from buglog.json)._ _Not recorded (migrated from buglog.json)._ ## Root cause -(1) The test's assumption was stale, not wrong test infra: bug-1700/1701 (fixed 2026-08-26) closed the exact standby-redirect gap this test was written to regression-lock, at the generic ha_dispatch_gate() rejection level in cluster.c -- the test's own docstring had explicitly predicted this exact failure as the correct signal to replace it with a success-path assertion. design.md ('Boundary Commitments'/'Revalidation Triggers') and roadmap.md still described the gap as open. (2) config_activate_committed() on the primary runs off the WAL apply-pump dispatch (persist.c ~5111, the bug-1469 fix), asynchronously relative to the majority-ack-gated client reply (commitIndex vs lastApplied are distinct steps) -- the CLI can legitimately return success before the primary's own local apply of that marker has logged its activation line, a latent race in the existing single-shot log read shared by the direct-to-primary test too. +Corrected 2026-10-03. Part (1) of the original entry (stale standby-redirect assertion) was fixed earlier. Part (2), the recurring flake: the controller replies to the push before two of the lines the tests assert are logged — "Config upgraded to tag=" is logged right after `xce_reply()` (`config_repl.c` ~1865-1873) and "config activated from committed marker" comes from `config_activate_committed()` (`config_repl.c` ~376) on the asynchronous WAL apply pump. `test_e2e_live_push.py` read the log once with no polling (the 2026-10-03 recurrence), and the HA helper polled only for the activation line, not "Config upgraded". ## Fix -Renamed and rewrote the test as test_live_config_push_against_standby_redirects_and_succeeds, asserting the redirect line IS present and the push succeeds (same success bar as the direct-to-primary test: positive ackedCount, exit 0, primary commit evidence). Updated the module docstring, design.md (Boundary Commitments, Revalidation Triggers, sequence-diagram note, redirect-implementation rationale, Testing Strategy), and roadmap.md's corresponding item to describe the gap as closed instead of open -- also corrected an adjacent, independently-verified stale claim (bug-1468, fixed 2026-07-25, already resolved but never reflected in design.md) that no controller role could reach the upgradeConfig handler at all. For the activation race, changed _assert_primary_committed() from a single-shot log_text argument to a Path-based helper that polls (up to 5s, 0.2s interval) for the activation line instead of assuming synchronous ordering, and updated both call sites. Verified end-to-end: full xce-build.sh xceadmin run now passes 288/288 with zero skips/failures. +Shared `assert_primary_committed()` in `src/xceadmin/tests/_live_e2e_common.py` polls (5 s) until the commit, upgrade and activation lines are all present, then asserts each; both live tests use it. Fix commit 362098b1. ## Verification -_Not recorded (migrated from buglog.json)._ +- Test: helper unit tests in `src/xceadmin/tests/test_live_e2e_common.py` (lines logged after the reply are waited for; missing activation line fails; missing "Config upgraded" line fails) — the old single-read and activation-only patterns fail deterministically when the late lines are written 0.3 s after the read; GREEN after. Live tests looped 95 runs (incl. heavy CPU load) with 0 bug-1725 failures. +- Suites: xceadmin 373 passed, 2026-10-03. +- Live: n/a ## References - Related: bug-1724, bug-1700, bug-1701, bug-1468 diff --git a/.wolf/bugs/bug-1913.md b/.wolf/bugs/bug-1913.md new file mode 100644 index 00000000..6d9cb285 --- /dev/null +++ b/.wolf/bugs/bug-1913.md @@ -0,0 +1,59 @@ +--- +id: "bug-1913" +status: "open" +status_updated: "2026-10-03" +status_note: "newly logged" +component: "controller" +severity: "wrong-result" +timestamp: "2026-10-03T14:18:58Z" +last_seen: "2026-10-03T14:18:58Z" +occurrences: 1 +files: ["src/controller/ha.c", "src/controller/repl.c", "src/controller/config_repl.c"] +tags: ["ha", "raft", "replication", "latency"] +related: ["bug-1485"] +--- + +# bug-1913: after a late-joiner election the primary cannot commit client writes for ~2 heartbeat cycles + +## Description +**Observed:** +``` +repl_broadcast: no standbys registered ... not replicated +... +WAL NACK from standby lsn=2 ... marking catch-up +repl_wait_majority_ack: timeout ... OP_upgradeConfig rejected (status=-110) +``` +In some elections the vote connections are not converted into standby channels (`raft_cb_become_leader`), so both standbys register later through `on_standby_connected` (ha.c ~9643-9660). `ha_arm_own_term_gate` (ha.c ~5178) has already appended the own-term WAL_NOOP (lsn 1) while no standby was registered (repl.c ~306-311), and `repl_add_standby` does not resend it. Catch-up then runs from the 3 s heartbeat, one action per standby per cycle (config push first, WAL stream on the next cycle), so `committed_lsn` stays 0 for ~6 s. Any client write in that window (e.g. `OP_upgradeConfig`) is NACKed by both standbys and fails with -ETIMEDOUT after the 500 ms majority wait. + +**Expected:** a newly elected primary commits its own-term no-op, and so accepts client writes, promptly after its standbys register, not two heartbeat cycles later. +**Impact:** for ~6 s after such an election every client write is rejected with -110 (fail-loud, no data loss, no false success). Clients retry, but tests and operators see spurious failures right after failover (the root cause of bug-1485's versionTag=0 flake). A fix must respect the async-I/O rules (no blocking on the delaymgr/heartbeat path; streaming offloaded) in `.kiro/steering/ha-async-io.md`. +**Found by:** test (root cause of bug-1485) + +## Environment +- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64 +- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2) +- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1 +- Build: asan (xce.build) +- Code: scheduler-framework @ 91782e40-dirty +- Deployment: local 3-node HA (xceadmin live e2e fixture), CPU-loaded sandbox (40 busy loops on 32 cores) makes late-joiner elections frequent + +## Reproduction +1. Start a 3-node HA cluster (e.g. the `live_ha_cluster` fixture in `src/xceadmin/tests/test_e2e_live_ha_push.py`) under CPU load. +2. In the primary log, find an election with no "promoted" standby channels and a later "repl_add_standby"/late registration; push a config (`xceadmin config push ... --controller `) within ~6 s. +3. The push fails with `controller returned status -110`; the log shows the NACK and majority-ack timeout above. +- Frequency: 7/28 runs of the HA push test under 40-spinner CPU load, 0/6 idle (2026-10-03); all 7 failures were late-joiner elections. +- Evidence: not kept (scratchpad loop logs from the bug-1485 investigation). + +## Root cause +TODO: required for fixed/partial + +## Fix +TODO: required for fixed/partial + +## Verification +- Test: TODO: name + file; RED before the fix, GREEN after +- Suites: TODO: suite results and build profile +- Live: TODO: soak/deploy run, or n/a and why + +## References +- Related: none