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) <noreply@anthropic.com>
This commit is contained in:
parent
362098b12a
commit
4cd5fb7dd8
GPG key ID:
80533536B0EB651C
5 changed files with 133 additions and 37 deletions
|
|
@ -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:<port>: [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 <defunct> 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/<name>.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"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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 <defunct> 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/<name>.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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
59
.wolf/bugs/bug-1913.md
Normal file
59
.wolf/bugs/bug-1913.md
Normal file
|
|
@ -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 <primary>`) 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
|
||||
Loading…
Add table
Add a link
Reference in a new issue