save wolf state and document

.wolf/cerebrum.md

@@ -7,8 +7,12 @@
 ## User Preferences
 
 <!-- How the user likes things done. Code style, tools, patterns, communication. -->
+- Run soak tests with specific round counts and deploy directories for precise regression tracking
+- Prefer parallel agent runs for independent analysis work; sequential for dependent tasks
+- Keep test logs for analysis, don't skip intermediate output even if a test hangs
 
 ## Key Learnings
+- (2026-07-08, HA soak test sequential vs chaotic modes) Sequential mode soak validates clean failover lifecycle: 10 rounds, 36 jobs, zero loss, all 3 nodes led primary — deterministic validation of promotion + catch-up + reapply paths working as designed. Chaotic mode deliberately overlaps kills across election/catch-up windows to surface edge cases: rounds 1-4 pass verification, round 5 hits primary-discovery lag (bug-854 root-caused earlier, excluded from verdict), rounds 6-7 stall from election convergence lag + duplicate-node-guard (bug-1418, pre-existing guard). The election stall in chaotic round 6 is likely compound: (a) tight overlapping kill cadence outpaces election+restart timing (heartbeat-timeout bounds ~500ms but nix shell spinup adds latency), (b) a node restarted but not fully converged rejoins before the prior kill round's primary finishes its term tenure. Sequential mode PASS verdict is solid baseline. Chaotic mode needs either slower kill spacing OR a real-fs host deploy (current sandbox has overlayfs fdatasync EIO bug-924) to distinguish fault-tolerance (still holds) from environment-induced timing collapse.
 - (2026-07-04, raft-apply-decoupling task 6.1 round 2 — job-state merge-staleness fix) Round 1's `apply_committed_entry` wired the live pump but left a real corruption: `record_job_fail_fact`/`record_job_update_fact` (job.c) precomputed a FINAL absolute state at RECEIPT time (a scratch-copy merge for FAIL, an inline backstop+PDONE merge for postdone) and baked it into `wal_jobstate_t.state`; under deferred apply, a second fact for the same job (e.g. FINISH) could apply BETWEEN receipt and this fact's own apply, making the baked snapshot stale — a POST_EXEC-stage FAIL received while a job is still `RUN` (FINISH not yet applied) bakes `RUN|EXIT|PERR`, and when FINISH applies first (`DONE`) then FAIL's blind absolute overwrite clobbers it back to `RUN|EXIT|PERR` — DONE silently lost. FIX PATTERN: `wal_jobstate_t._pad` (previously always-zero, unused) is repurposed as a discriminator — `_pad==0` still means "legacy absolute state, safe" (job_ctrl's mark_job_fail/mark_job_update paths, which mutate+capture state synchronously under one lock, no staleness window); a nonzero `_pad` (`WAL_JOB_FAIL_STAGE_FLAG|stage` for FAIL, `WAL_JOB_UPDATE_POSTDONE_MARK` for postdone) marks "recompute at apply time against ACTUAL current state" — `apply_committed_entry` (persist.c) dispatches on this bit per WAL type, calling the REAL `apply_job_fail_transition`/new `apply_job_postdone_transition` (job.c, mirrors the existing guard-core family) instead of `apply_job_update_transition`'s blind overwrite. New low-level `persist_submit_job_fact_ex(p, type, jobid, state, pad)` added as the primitive; `persist_submit_job_fact` becomes a pad=0 thin wrapper — ZERO existing call sites (including ~20 in test_commit_barrier_reply.c) needed touching. GENERAL PATTERN for "wire format has 2 producers, one safe one not": don't change the safe producer's shape — add a discriminator field/flag so the consumer can tell them apart, and make "0"/"absent" mean exactly the old/safe behavior so every existing writer keeps working unchanged.
 - (2026-07-04, same task) Fixing a wire-format bug INSIDE a task's own scope can break pre-existing tests that assert the wire format directly (not just behavior) — 2 tests in test_commit_barrier_reply.c (`test_guard_forward_update_on_terminal_preserved`, `test_guard_fail_after_finish_preserves_perr_merge`) read the raw on-disk `wal_jobstate_t.state` via a helper (`cbrp_count_jobstate_entries`) and asserted DONE/PDONE/PERR bits directly on it — exactly the field this fix stops populating for FAIL/postdone. These are NOT the "old apply-before-commit ordering" tests task 7.3 owns (a different axis — ordering vs wire-format) — they are a DIRECT, in-scope, mechanical consequence of the wire-format fix itself, so I fixed them here rather than deferring: extended the helper to a `_ex` variant returning `_pad` too (existing helper becomes a thin wrapper, zero other call sites touched — same pattern as persist_submit_job_fact_ex), changed the wire-level assertions to check the new `_pad` marker, and added a direct call to the guard core (`apply_job_fail_transition`/`apply_job_postdone_transition`) on a scratch `job_t` to keep pinning the actual merge semantics the test was written to protect. A 3rd test (`test_fact_state_unchanged_throughout_quorum_loss_outage`) had the identical `st_upd` bit-check for postdone; fixed the same way (already had a `(void)st_fail` precedent in the same file for exactly this "order-dependent, can't check at receipt time" reasoning — extended it to `st_upd`/`pad_upd`). Lesson: when a task's fix legitimately changes what a durable record contains, grep for every DIRECT byte/field-level test assertion on that record (not just behavioral tests) before declaring the regression sweep clean — `grep cbrp_count_jobstate_entries` found them, `--run test_apply_pump` alone would not have.
 - (2026-07-04, same task) RED-phase verification for a bugfix already merged into the same commit as its own regression test (no separate "before" commit to check out) — reverted the exact 2 production hunks in-place (record_job_fail_fact's scratch-copy computation + apply_committed_entry's WAL_JOB_FAIL case ignoring `_pad`) using Edit, confirmed the new test fails with the EXACT predicted corrupted value (`Expected 264 Was 262` = DONE|PERR vs RUN|EXIT|PERR, byte-for-byte matching the hand-derived bug trace), then restored from a pre-saved `cp` snapshot of the fixed files and `diff`-verified byte-identical restoration before rebuilding GREEN. Combined with the existing longjmp-past-teardown lesson (isolate the new test alone in RUN_TEST via `#if 0` during the revert-and-check step, restore full list after) — both techniques compose cleanly.
@@ -423,3 +427,15 @@ Caught immediately by the build (gcc: "macro requires 3 arguments, but only 2 gi
 
 ## Key Learning (2026-07-05, bug-1416, raft-apply-decoupling task 7.2) — cluster_init_phase2's persist_recover() apply-correctness verification can false-positive APPLY_DIVERGENT when a returning node's recovery vtask races a compressed catch-up replication burst — FIXED round 2
 Found live, reproduced 10/10 times, building the `--factstream` kill-mid-fact-stream HA soak scenario. `cluster_init_phase2()` (cluster.c) calls `cluster_open_listener()` (accepts network I/O, including replicated/catch-up WAL writes) BEFORE `persist_recover()` (the task-5.1 boot-time apply-correctness verification, Req 8.1/8.2) — and `persist_recover()` itself fires from a vtask, not synchronously. `persist_verify_apply_correctness()`'s LIVE reads of `p->last_applied_lsn` and `count_jobmgr_entries()` can race two live mutation paths (the apply pump, `persist_apply_pump_run`/`persist_apply_pump_kick`; and the standby live-replication apply path, `ha_apply_single_entry`/`ha_apply_term_entry_via_library` in ha.c) that write those SAME values concurrently, producing a DIVERGENT verdict on a node that has NOT actually diverged. **FIXED (round 2, review remediation)**: new `_Atomic bool persist_t.recovery_complete` gate (persist.h/persist.c). `persist_apply_pump_kick()` no-ops while closed; `ha_apply_single_entry`/`ha_apply_term_entry_via_library` skip ONLY the in-memory `apply_wal_entry()` call while closed (durability write + ACK + applied_lsn advance stay ungated — mirrors bug-1043's durability/materialization decoupling). `persist_recover()` closes it at entry, reopens it + issues one deliberate catch-up kick before returning. **Round-2-of-the-fix gap, found via live verification, not just code review**: this alone was NOT enough — a node stuck retrying its own election as a losing/timing-out candidate can receive and durably APPLY live-replicated entries via the ungated (`persist_init` default=true) path for tens of seconds BEFORE `cluster_init_phase2()` ever calls `persist_recover()` for the first time, reproducing the identical false-DIVERGENT symptom through an earlier entry point `persist_recover()`'s own bracket can't see. Closed with `persist_mark_recovery_pending(&c.persist)` in `myapp_run()` (myapp.c), called right after `persist_init()`/`persist_start()` succeed and BEFORE `ha_start_election_async()`/`cluster_run()` can process any network traffic — closing the gate from the true earliest safe moment. `persist_init()`'s default stays TRUE so none of this spec's ~20 unit-test fixtures that construct a `persist_t` directly (bypassing `myapp_run`) are affected. Verified: live 3-node `--factstream` soak (2 rounds, kill+restart both) now PASSes clean, zero `APPLY_DIVERGENT` across 5 `persist_recover()` calls; broader `controller_unit_test` sweep (23 groups) shows zero new failures; real-divergence detection re-confirmed intact via the 3 dedicated `test_apply_correctness_verification.c` divergence tests. **Do-not-repeat lesson**: when gating a live path behind a "recovery in progress" flag, the flag's OWN bracket around the recovery function itself is not sufficient if OTHER code paths (election retry, live replication) can mutate the same state BEFORE that function is ever first called — the gate must close at the EARLIEST point in the real process lifecycle traffic could possibly begin, not just around the specific function whose output it protects.
+
+## Key Learning (2026-07-07, raft-apply-decoupling task 7.4 O(n^2) apply-pump fix, CLOSED) — segment-lookup cache on `apply_pump_read_entry` fixes the regression; validated live A/B in one environment
+Root cause: `apply_pump_read_entry` (persist.c) redid a full `opendir`/`readdir`/segment-sort + a `pread` scan from byte 0 on EVERY single committed-LSN lookup; its only caller (`persist_apply_pump_run`) calls it once per LSN in strict ascending order with no gaps in the common case, making N contiguous applies O(N^2). Fix: 4 new `persist_t` fields (`apply_pump_cache_fd/seg_lsn/off/next_lsn`, guarded ENTIRELY by `apply_pump_lock`, never `p->lock`) cache the open segment fd + byte offset positioned for the next expected LSN; a fast path does a direct `pread` at the cached offset (hit → O(1), advance cache; miss → close+invalidate, fall through to the UNCHANGED slow path, which also now populates the cache on its own success branch before `fd` gets closed). Invalidated in `persist_init`/`persist_fini`/`persist_recover` (stale pre-recovery cursor) and `persist_truncate_wal_above` (segment could be ftruncate'd/unlinked away) — correctness never depends on the cache being right, only performance does (every miss path is the pre-existing, already-correct slow path). Live A/B in the SAME environment (single-node, release build, `git stash`/`pop` on persist.c/.h to swap fixed vs pre-fix): pre-fix N=2000→1.8s (1111/s), N=4000→13.3s (301/s) = **7.4x elapsed for 2x volume** (confirms superlinear); fixed N=2000→0.52s (3831/s), N=4000→0.76s (5249/s) = **1.46x elapsed for 2x volume**, throughput actually IMPROVING with N (fixed-cost amortization) — clean confirmation of the fix with zero superlinear scaling.
+
+## Do-Not-Repeat (2026-07-07) — the synchronous `jobsub` (COMMIT_MODE_WAIT) request/reply path has a real, reproducible intermittent hang; NOT this task's bug, has its own out-of-scope status
+While benchmarking task 7.4's throughput fix, a single-connection burst of sequential `jobsub` REPL calls hung after a handful to a few hundred calls (variable: 7, 150, 778, 1579 — never a fixed threshold), with the SERVER-side commit completing near-instantly (visible in the controller log) but the CLIENT's `cbuf_get` on that connection never unblocking; a BRAND NEW connection to the same server succeeds immediately, so the server itself is not deadlocked. Ruled out REQ_BLOCK admission-cap exhaustion as the cause (raising `--vcpus` 4→32, i.e. cap 3→31, did not help — still hung after 13 calls). This is `jobsub`-specific (COMMIT_MODE_WAIT, synchronous reply-wait); `jfinish`/`jstart` (COMMIT_MODE_RETAIN, fire-and-forget `xce_notify`, no reply wait) never exhibited it even at N=4000 in one burst. Confirmed pre-existing/environmental, NOT caused by the apply-pump fix (reproduces identically on stashed pre-fix binaries). **Workaround, not a fix**: submit jobs in small waves (~20) over FRESH connections with generous per-wave retry — a hung wave doesn't poison later ones, and patient retrying eventually gets 100% through. **Do-not-repeat**: don't waste time hypothesis-testing admission-pool/vcpus tuning for this class of hang without first confirming server-side liveness via an independent fresh-connection probe — that single check (does a NEW connection succeed right now?) instantly distinguishes "server deadlocked" from "this one connection's reply got lost," which have completely different fixes/workarounds.
+
+## Do-Not-Repeat (2026-07-07) — `$EPOCHREALTIME` read inside a polling loop with per-iteration subprocess calls can yield a wildly-wrong before/after diff; capture it as a single simple pair, not inline in deadline arithmetic
+A benchmark script computed elapsed time via `$EPOCHREALTIME` timestamps read inside a `while` polling loop that also computed its own timeout deadline via `awk` on every iteration — it printed a "commit-poll timeout after 180s" message in the SAME run whose reported `commit_elapsed` was 0.176s, an impossible combination. `$EPOCHREALTIME` itself is fine in isolation (verified: bash 5.3, two consecutive reads show a proper sub-ms-resolution increment) — the bug was in the surrounding script structure (mixing a `done_count`-vs-target break condition, a separate deadline-exceeded break condition, and per-iteration subprocess/awk calls all touching timing state), not the variable. **Fix that worked**: use bash's plain integer `SECONDS` builtin (`SECONDS=0` before, read `$SECONDS` after) for the loop's OWN deadline/elapsed bookkeeping, and take a SEPARATE single `t_start`/`t_end` `$EPOCHREALTIME` pair (captured once, diffed once via one final `awk` call) purely for sub-second-precision reporting. **Do-not-repeat**: never trust a timing result that contradicts an adjacent diagnostic message (e.g. a "timeout after Xs" alongside an elapsed value ≪X) — that contradiction itself is the tell that the measurement code (not the system under test) is broken; re-derive elapsed time via the simplest possible mechanism before trusting the number.
+
+## Do-Not-Repeat (2026-07-07) — a joblist/committed-count poll loop must scope its match to THIS run's own job IDs, never a cluster-wide state count
+A benchmark script counted `done_count` as "every joblist row with state DONE" — on a controller that had accumulated DONE jobs from a PRIOR run in the same process lifetime, this produced an instant false-positive "already done" (0s elapsed) the moment the pre-existing DONE count alone exceeded the new batch's N, even though none of the NEW batch's facts had been sent yet. Fixed by writing the batch's own job IDs to a file and using `awk`'s `getline` to build a lookup set, counting only `($1 in ids) && $4=="DONE"`. **Do-not-repeat**: any poll-for-completion loop against a stateful, non-reset-between-runs server must scope its match to the specific IDs/records THIS run created — a bare aggregate count silently double-counts history from earlier runs against the same live process.