diff --git a/.wolf/anatomy-index.json b/.wolf/anatomy-index.json index f95ae568..32a8da36 100644 --- a/.wolf/anatomy-index.json +++ b/.wolf/anatomy-index.json @@ -1,13 +1,13 @@ { "version": 1, "meta": { - "lastScanned": "2026-08-30T15:25:28.278Z", - "fileCount": 558, + "lastScanned": "2026-08-30T15:51:46.646Z", + "fileCount": 570, "hits": 0, "misses": 0, - "renderedHash": "6515a885c8768e4276e975dcc3d90f08f7d92107ca44a3203ea7e560af9be4dc", - "storeUpdatedAt": "2026-08-30T15:25:28.287Z", - "rootHash": "24fb14ecfae59ce8" + "renderedHash": "02917fcf201105c5a47a46990a85e3a5eadaf3094f63f46a074a1cfc48fa942d", + "storeUpdatedAt": "2026-08-30T15:51:46.654Z", + "rootHash": "1dc62110ed2beaa4" }, "files": { ".agent-shell/transcripts/2026-08-11-11-39-59.md": { @@ -6254,20 +6254,20 @@ }, "src/scheduler/testsuite/test_core_events.c": { "description": "Declares and", - "tokens": 11084, - "hash": "2014e0b2df793f10", - "size": 41565, - "mtimeMs": 1788058449744.0327, - "updatedAt": "2026-08-30T02:54:09.785Z", + "tokens": 12017, + "hash": "79747faef09c99f5", + "size": 45063, + "mtimeMs": 1788104586039.423, + "updatedAt": "2026-08-30T15:43:06.089Z", "source": "hook" }, "src/scheduler/src/core_events.c": { "description": "include ", - "tokens": 12200, - "hash": "c0e97827aec51533", - "size": 45750, - "mtimeMs": 1788089633567.1846, - "updatedAt": "2026-08-30T11:33:53.614Z", + "tokens": 13231, + "hash": "b61d009c6f3960bb", + "size": 49616, + "mtimeMs": 1788105106599.9404, + "updatedAt": "2026-08-30T15:51:46.646Z", "source": "hook" }, "src/controller/job.c": { @@ -6664,6 +6664,114 @@ "mtimeMs": 1788103256851.4102, "updatedAt": "2026-08-30T15:20:56.894Z", "source": "hook" + }, + "src/controller/testsuite/test_commit_barrier_rollout.c": { + "description": "Declares explicitly", + "tokens": 28190, + "hash": "4c35348de2da47d7", + "size": 108496, + "mtimeMs": 1788104339444.8875, + "updatedAt": "2026-08-30T15:38:59.480Z", + "source": "hook" + }, + "src/controller/testsuite/test_demotion_convergence.c": { + "description": "define _GNU_SOURCE", + "tokens": 15498, + "hash": "f446627b32235d27", + "size": 59238, + "mtimeMs": 1788104353831.8499, + "updatedAt": "2026-08-30T15:39:13.879Z", + "source": "hook" + }, + "src/controller/testsuite/test_convergence_verification.c": { + "description": "define _GNU_SOURCE", + "tokens": 19002, + "hash": "7c18822592bd1d36", + "size": 72585, + "mtimeMs": 1788104362906.453, + "updatedAt": "2026-08-30T15:39:22.954Z", + "source": "hook" + }, + "src/controller/testsuite/test_egress_filter.c": { + "description": "Declares of", + "tokens": 5156, + "hash": "437c7c366a160c49", + "size": 19663, + "mtimeMs": 1788104373948.1824, + "updatedAt": "2026-08-30T15:39:33.984Z", + "source": "hook" + }, + "src/controller/testsuite/test_apply_pump.c": { + "description": "Declares of", + "tokens": 21139, + "hash": "cd030bacfa21b02f", + "size": 79572, + "mtimeMs": 1788104397937.752, + "updatedAt": "2026-08-30T15:39:57.984Z", + "source": "hook" + }, + "src/controller/testsuite/test_apply_pump_integration.c": { + "description": "Declares hook", + "tokens": 17030, + "hash": "dd1d38943161f43c", + "size": 65226, + "mtimeMs": 1788104408615.4438, + "updatedAt": "2026-08-30T15:40:08.662Z", + "source": "hook" + }, + "src/controller/testsuite/test_job_array_fence.c": { + "description": "Declares of", + "tokens": 6195, + "hash": "3e179e1188896942", + "size": 23707, + "mtimeMs": 1788104421469.2717, + "updatedAt": "2026-08-30T15:40:21.516Z", + "source": "hook" + }, + "src/controller/testsuite/test_ha_role_lifecycle.c": { + "description": "define _GNU_SOURCE", + "tokens": 15235, + "hash": "41ebe421929747cd", + "size": 57694, + "mtimeMs": 1788104432742.9932, + "updatedAt": "2026-08-30T15:40:32.792Z", + "source": "hook" + }, + "src/controller/testsuite/test_job_array_replay_fence.c": { + "description": "Declares uint64_t", + "tokens": 13778, + "hash": "55f2fa1da5272bbd", + "size": 53201, + "mtimeMs": 1788104442560.618, + "updatedAt": "2026-08-30T15:40:42.600Z", + "source": "hook" + }, + "src/controller/testsuite/test_commit_durability.c": { + "description": "define _GNU_SOURCE", + "tokens": 34003, + "hash": "a033657993fe00f5", + "size": 127876, + "mtimeMs": 1788104600778.2966, + "updatedAt": "2026-08-30T15:43:20.812Z", + "source": "hook" + }, + "src/controller/testsuite/test_commit_engine.c": { + "description": "", + "tokens": 18081, + "hash": "76cee726d40039b7", + "size": 70312, + "mtimeMs": 1788104676422.7012, + "updatedAt": "2026-08-30T15:44:36.458Z", + "source": "hook" + }, + "src/controller/testsuite/test_p2_integration.c": { + "description": "include ", + "tokens": 5212, + "hash": "0983423366e037eb", + "size": 19613, + "mtimeMs": 1788104772616.135, + "updatedAt": "2026-08-30T15:46:12.655Z", + "source": "hook" } } } \ No newline at end of file diff --git a/.wolf/anatomy.md b/.wolf/anatomy.md index 1940a352..c9643b7e 100644 --- a/.wolf/anatomy.md +++ b/.wolf/anatomy.md @@ -1,7 +1,7 @@ # anatomy.md -> Auto-maintained by OpenWolf. Last scanned: 2026-08-30T15:25:28.278Z -> Files: 558 tracked | Anatomy hits: 0 | Misses: 0 +> Auto-maintained by OpenWolf. Last scanned: 2026-08-30T15:51:46.646Z +> Files: 570 tracked | Anatomy hits: 0 | Misses: 0 ## ./ @@ -823,10 +823,22 @@ ## src/controller/testsuite/ - `test_apply_committed_entry.c` — Declares directly (~13500 tok) +- `test_apply_pump_integration.c` — Declares hook (~17030 tok) +- `test_apply_pump.c` — Declares of (~21139 tok) - `test_apply_reapply_idempotency.c` — Declares xce_job_t (~4115 tok) - `test_commit_barrier_reply.c` — Declares uint8_t (~45642 tok) +- `test_commit_barrier_rollout.c` — Declares explicitly (~28190 tok) +- `test_commit_durability.c` — define _GNU_SOURCE (~34003 tok) +- `test_commit_engine.c` (~18081 tok) - `test_config_repl.c` — define _GNU_SOURCE (~87218 tok) +- `test_convergence_verification.c` — define _GNU_SOURCE (~19002 tok) +- `test_demotion_convergence.c` — define _GNU_SOURCE (~15498 tok) +- `test_egress_filter.c` — Declares of (~5156 tok) +- `test_ha_role_lifecycle.c` — define _GNU_SOURCE (~15235 tok) - `test_host_runusage.c` — Declares char (~3442 tok) +- `test_job_array_fence.c` — Declares of (~6195 tok) +- `test_job_array_replay_fence.c` — Declares uint64_t (~13778 tok) +- `test_p2_integration.c` — include (~5212 tok) - `test_wal_job_finish_fact.c` — Declares as (~8980 tok) - `test_wal_job_start_fact.c` — Declares as (~12368 tok) - `test.c` — include (~40634 tok) @@ -858,7 +870,7 @@ ## src/scheduler/src/ -- `core_events.c` — include (~12200 tok) +- `core_events.c` — include (~13231 tok) - `driver.c` — include (~9779 tok) - `handler.c` — include (~7162 tok) - `main.c` — include (~5330 tok) @@ -868,7 +880,7 @@ ## src/scheduler/testsuite/ - `test_admin_request.c` — Declares level (~13020 tok) -- `test_core_events.c` — Declares and (~11084 tok) +- `test_core_events.c` — Declares and (~12017 tok) - `test_sim_contention_parity.c` — Declares calls (~18713 tok) - `test_sim_e2e_original_motivation.c` (~17120 tok) - `test_sim_session_ordering.c` (~8092 tok) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 11d70007..9e6be6e2 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -12871,28 +12871,39 @@ "id": "bug-1429", "timestamp": "2026-07-10", "error_message": "controller_unit_test suite TIMEOUT (300s, killed by SIGTERM) during /xce-build controller run immediately after uncommitted edits to persist.c, ha_convergence.c, config_repl.c (delaymgr-inline blocking I/O moved to VTASK_LIVE_BLOCK vtasks with inline-fallback-on-failure). Compile succeeded with zero errors (only pre-existing warnings). meson test summary: Ok:0 Fail:0 Timeout:1. Last test output before the hang was test_demotion_replay_yields_committed_only (test_commit_barrier_reply.c) printing overlayfs-SKIP, followed by a burst of HA FSM / persist_apply_pump_run log lines ending in \"HA quorum lost: connected=0 required=1\", then total silence for the remaining ~294s until SIGTERM. No ASAN/crash report -- looks like a genuine hang/deadlock, not a crash.", - "file": "src/controller/persist.c, src/controller/ha_convergence.c, src/controller/config_repl.c", - "root_cause": "NOT YET ROOT-CAUSED. Suspect the new delaymgr-trampoline -> vtask_enq_classified(pool, task, VTASK_LIVE_BLOCK) path blocks waiting for vtask completion that never arrives inside the controller_unit_test harness (e.g. vtask thread pool not pumped/started for this test fixture, or a lock-ordering deadlock between the delaymgr thread and the vtask worker). Ruled out: disk space is not exhausted (162G free, 81% used) so this is NOT the bug-924 ENOSPC/overlayfs-fdatasync pattern despite ~8182 leftover /tmp/xce_* dirs being present.", - "fix": "NOT FIXED -- reported to user for diagnosis; no code changes made in this session. Reproduced again 2026-08-20 on scheduler-framework worktree /xce-build controller run (unrelated diff: only src/controller/main.c and testsuite/test.c argp_program_version/version-log changes) -- controller_unit_test TIMEOUT 300.14s SIGTERM, Ok:4 Fail:0 Timeout:1, hang appears to be inside/after test_commit_barrier_rollout.c's test_configack_* group. Still not root-caused; confirms this is pre-existing/environmental, not caused by the version-string diff.\n\nReproduced a 3rd time 2026-08-23 on scheduler-framework worktree, verifying scheduler-dispatch-commit task 3.1 GREEN phase (`xce-build.sh controller asan xce.build.green31`, dedicated build dir). Diff this session: src/controller/job.c (dispatch_a_job_() restructure -- gate alloc-commit+JOB_STAT_RUN transition on xce_startjob_req() success, reset dispatch_fail_count, append WAL_JOB_DISPATCH), src/controller/meson.build, src/controller/testsuite/controller_test.c, new src/controller/testsuite/test_dispatch_commit.c -- none of the three prior hang locations' files. Compile succeeded with zero errors (367/367 ninja targets). meson test: Ok:4 Fail:0 Timeout:1, \"5/5 xce:controller / controller test TIMEOUT 300.13s killed by signal 15 SIGTERM\". This time the hang location is test_commit_barrier_reply.c's test_jobsubmit_repeated_truncation_forced_failures_no_phantom_jobs (a PRE-EXISTING, unmodified-this-session test) -- a 3rd distinct hang location across 3 occurrences (test_demotion_replay_yields_committed_only, then test_configack_* group, now test_jobsubmit_repeated_truncation_forced_failures_no_phantom_jobs), each time in an unrelated diff. Independently reproduced twice more in the same session: (a) a standalone direct run of the built binary bypassing the meson harness/300s cap (timeout 1200s) hung at the identical test with zero further output for 180s+; /proc showed both threads (main tid + 1 worker tid) parked in futex_do_wait (deadlock-consistent, not CPU-bound) -- gdb attach was blocked by sandbox ptrace restrictions so no user-space backtrace was obtainable; (b) a fully independent rebuild+test run (another agent in the same Claude session, `xce-build.sh controller asan xce.build.green31 --incremental`) hit the exact same TIMEOUT signature (300.12s) at the exact same test. Strongly corroborates this is a pre-existing, systemic, timing/order-dependent hang in the controller_unit_test harness (not caused by any of the 3 diffs seen so far) -- still NOT root-caused. Inspected the new job.c code path for an obvious lock-order regression (new `lock(j, RTTI_LOCK_WRITE)` around persist_submit_job_fact(WAL_JOB_DISPATCH)): this mirrors the pre-existing record_job_start_fact() pattern exactly (its own comment: \"every caller holds job under RTTI_LOCK_WRITE\"), and the hanging test (test_jobsubmit_repeated_truncation_forced_failures_no_phantom_jobs) never calls dispatch_a_job_() at all -- no causal link found to this session's diff specifically.", + "file": "src/controller/testsuite/test_commit_barrier_rollout.c, test_demotion_convergence.c, test_convergence_verification.c, test_egress_filter.c, test_apply_pump.c, test_apply_pump_integration.c, test_job_array_fence.c, test_ha_role_lifecycle.c, test_job_array_replay_fence.c, test_commit_durability.c, test_commit_engine.c, test_p2_integration.c (test-fixture teardown ordering, 21 sites across 12 files); src/controller/commit.c (commit_engine_fini, unchanged -- confirms the documented contract); src/controller/persist.c (fsync_worker, unchanged -- confirms the race window)", + "root_cause": "ROOT-CAUSED 2026-08-30, LIVE-REPRODUCED with a full gdb thread backtrace (the first time in this bug's history any session captured a live hang instead of just reporting the SIGTERM/timeout). The original delaymgr/VTASK_LIVE_BLOCK hypothesis carried by this bug since 2026-07-10 was WRONG -- a static read of every vtask_enq_classified(..., VTASK_LIVE_BLOCK) call site in ha.c/persist.c/config_repl.c/commit.c found every one of them NULL-checks its pool pointer (or the trampoline is gated behind `c->delaymgr.running`, which test fixtures never set) and falls back inline on failure -- there is no path where a controller_unit_test fixture leaves a non-NULL-but-never-started vtaskmgr_t that a VTASK_LIVE_BLOCK task could be silently swallowed into. That entire subsystem is a red herring for this bug.\n\nThe REAL root cause is the same TOCTOU test-teardown race already root-caused once before, for a DIFFERENT symptom, in bug-1452 (2026-07-19: an ASAN SEGV in test_persist_truncate.c) and partially re-applied once more in bug-1687 (2026-08-25: cbrp_teardown in test_commit_barrier_reply.c). Every affected test fixture calls `commit_engine_fini(&ce)` BEFORE `persist_stop(&persist)` in its teardown helper -- the exact opposite of the contract documented in commit_engine_fini's own comment (commit.c: 'Callers are expected to have stopped the flusher (persist_stop) first'). Because persist_stop had not yet run, the persist_t's live fsync_worker background thread (persist.c:800, started by persist_start) can still be mid-flight calling `p->on_durable_advance(p->durable_cb_ctx)` -- i.e. commit_on_durable_advance(ce) -- with NO lock held (persist.c:866-868), concurrently with commit_engine_fini destroying ce->lock/ce->cond (commit.c:476-477) and freeing ce->continuations. commit_engine_fini's own persist_set_durable_cb(ce->p, NULL, NULL) unhook is 'defensive and cheap' per its own comment but is NOT sufficient on its own: the flusher thread can have already read the OLD non-NULL callback pointer a few instructions before the unhook takes effect. Depending on exact thread interleaving this TOCTOU race manifests as either bug-1452's SEGV (a NULL/freed dereference inside commit_advance_locked) OR -- newly confirmed this session -- a hang: pthread_cond_destroy(&ce->cond) blocking forever because the racing fsync_worker thread is concurrently inside pthread_cond_broadcast(&ce->cond) / holding ce->lock from commit_on_durable_advance, which glibc's cond-destroy implementation cannot safely proceed past. This explains every symptom previously logged against this bug: the varying hang location across sessions (different tests hit their OWN teardown's copy of this same race, at whatever moment the fsync_worker thread happened to be flushing), the total silence after the hang (both racing threads are genuinely blocked in futex/pthread_cond primitives, not spinning), zero CPU time accruing, and \"both threads parked in futex_do_wait\" from the 2026-08-23 sighting.\n\nLIVE REPRO (this session): `meson test -C src/xce.build.bug1429 --suite controller --verbose` hung 40s into the run with 3 threads (main + 2x fsync_worker) all in futex_do_wait, 0 CPU time advancing over a 3s recheck. gdb -p -batch -ex 'thread apply all bt full' (attached BEFORE the 300s SIGTERM, while the process was still alive) showed: Thread 1 (main) stuck in pthread_cond_destroy() called from commit_engine_fini (commit.c:476) <- jap_teardown() (test_commit_barrier_rollout.c:1877) <- test_job_array_submit_payload_size_bounded_at_max_array_idx (test_commit_barrier_rollout.c:2294) <- UnityDefaultTestRun <- test_commit_barrier_rollout() <- main(). Threads 2 and 3 both stuck in pthread_cond_timedwait at fsync_worker (persist.c:827), BOTH with `p = &g_jap` (the same global persist_t) -- confirming jap_teardown's exact commit_engine_fini-before-persist_stop ordering bug (test_commit_barrier_rollout.c:1877-1879, at the time of capture) as the live mechanism. This is the 4th distinct hang location logged against this bug (previously: test_demotion_replay_yields_committed_only, the test_configack_* group, test_jobsubmit_repeated_truncation_forced_failures_no_phantom_jobs) -- all four are different call sites of the identical teardown-ordering bug, which is why the location never repeated and why every prior static-inference pass aimed at the vtaskmgr/delaymgr subsystem instead never found it.", + "fix": "FIXED 2026-08-30. Test-fixture-only fix -- no production code changed (commit.c and persist.c are exactly as documented; the bug is every affected fixture violating commit_engine_fini's own documented calling contract). Inserted an explicit `persist_stop(&persist);` call immediately before every confirmed-vulnerable `commit_engine_fini(&ce);` call (mirroring bug-1452/bug-1687's established fix pattern exactly), leaving each function's pre-existing later persist_stop()/teardown-helper call in place as a safe, idempotent no-op (persist_stop's own fsync_thread_running and wal_fd>=0 guards make the second call a clean skip). Where a fixture also tears down a real multi-vcpu vtaskmgr_t pool (test_apply_pump.c's tpr_teardown, test_apply_pump_integration.c's tpi_teardown), vtaskmgr_fini() was left in its original position AFTER commit_engine_fini() (a separate, unrelated invariant: no new vtask may be dispatched onto the pool mid-teardown) -- only persist_stop()'s position moved earlier.\n\n21 sites fixed across 12 files, all confirmed vulnerable by verifying (a) the fixture's persist_t is genuinely persist_start()'d (has a live fsync_worker thread) and (b) the teardown called commit_engine_fini() before persist_stop(): test_commit_barrier_rollout.c (3 sites -- g_fce/g_fp inline teardown, cb5_teardown, jap_teardown -- the last being the exact live-reproduced hang site), test_demotion_convergence.c (dc_teardown -- this EXACT site was flagged but explicitly left unfixed by bug-1452's own remediation note as a known follow-up, never actioned until now), test_convergence_verification.c (cv_teardown), test_egress_filter.c (ef_teardown), test_apply_pump.c (2 sites -- tap_teardown, tpr_teardown), test_apply_pump_integration.c (tpi_teardown), test_job_array_fence.c (tf_teardown), test_ha_role_lifecycle.c (lifecycle_cluster_teardown), test_job_array_replay_fence.c (1 site of its 4 persist_start'd fixtures -- the other 3 never wire a commit engine), test_commit_durability.c (3 sites, including one with a comment that incorrectly claimed persist_set_durable_cb's unhook alone was sufficient), test_commit_engine.c (3 sites, all sharing sync_persist_teardown), test_p2_integration.c (3 sites, 2 sharing var `p` + 1 using `g_p9`). Confirmed SAFE and left unchanged: barrier_teardown (test_commit_barrier_rollout.c), engine_teardown (test_commit_engine.c), and the fixtures in test_repl_majority.c/test_commit_admission_pool.c/test_coldstart_lsn0.c/test_commit_resolve.c -- all use a 'stub' persist_t that is never actually persist_start()'d (no live fsync_worker thread), confirmed by grep for persist_start against each fixture's global before touching it.\n\nKNOWN REMAINING EXPOSURE (not fixed this session, explicit follow-up for a future pass, same as bug-1452 left one for this session): test_config_repl.c has ~23 call sites following the identical inline `commit_engine_fini(&c->commit); t42_teardown(c);` pattern (t42_teardown, line 629, confirmed calls persist_stop THEN persist_fini -- so every one of these is the same bug) -- not fixed here because the file is large (~7000 lines) with some sites (e.g. the c_control/c_raced pair around line 2911-2912) not yet individually verified for uniformity, and a bulk edit without that verification was judged too risky for this session's budget. test_term_safety_adapter.c has persist_start'd fixtures (lines 59, 245, 2382) and 5 commit_engine_fini call sites (676, 930, 1776, 1950, 2338) not individually checked. Neither file's exposure has been observed to hang or crash yet (this bug's own history shows the race is intermittent and timing-dependent -- absence of a prior sighting there is not evidence of safety). Recommended next step: a dedicated /xce-audit-invariants or grep-driven sweep of these two files using the exact same verification method used here (confirm persist_start presence, confirm fini-before-stop order, insert persist_stop() immediately before commit_engine_fini()).\n\nVERIFICATION: full `meson test -C xce.build.bug1429 --suite controller` run 3 times back-to-back after the settled fix (no edits during any of these three runs) -- 39.01s / 38.86s / 38.91s, Ok:6 Fail:0 every time, zero hangs, zero timeouts (previously: TIMEOUT 300.08s-300.30s on effectively every attempt this session before the fix, reproduced live on the very first try). No regression test added (per the task's own documented exception for a suite-level timing-dependent teardown race): the race requires a live fsync_worker thread mid-flush at the exact moment of teardown, which is not reliably triggerable in a bounded, fast unit test without reintroducing the same flakiness this fix removes; the 3x full-suite re-run is the verification method this project's own bug-1452 precedent already established for this exact bug class.", "tags": [ - "vtask", + "FIXED", "VTASK_LIVE_BLOCK", - "delaymgr", - "timeout", - "hang", - "deadlock-suspected", - "controller-tests", - "persist.c", - "ha_convergence.c", + "commit_engine_fini", "config_repl.c", + "controller-tests", + "delaymgr", + "fsync_worker", + "gdb-confirmed", + "ha_convergence.c", + "hang", + "live-repro", + "multi-location", + "persist.c", + "persist_stop", + "root-caused", + "teardown-ordering", + "test-fixture-bug", "test_commit_barrier_reply", - "multi-location" + "timeout", + "toctou-race", + "vtask" ], "related_bugs": [ + "bug-1452", + "bug-1687", "bug-924" ], - "occurrences": 3, - "last_seen": "2026-08-23T10:00:00.000Z" + "occurrences": 4, + "last_seen": "2026-08-30T15:26:00.000Z" }, { "id": "bug-1430", @@ -19988,8 +19999,8 @@ "timestamp": "2026-08-30T10:15:00Z", "error_message": "User-reported live deployment: scheduler's view of a job array's state (`[sim] jobs` / xce_scheduler -i -s) diverges sharply from the controller's own joblist for the SAME array, well after every element genuinely finished. Array 0-4-1788084587-0 (50 elements, command `hostname`): controller's `joblist` shows ALL 50 elements as DONE with real, monotonically-increasing StartTime/FinishTime timestamps (1788084587..1788084602) -- the array is genuinely, fully complete. The scheduler's own concurrent view of the identical array shows a scrambled mix: [0-4]=RUN, [5-16]=DONE, [17]=EXIT, [18-19]=DONE, [20]=EXIT, [21]=DONE, [22-24]=EXIT, [25]=DONE, [26-29]=EXIT, [30-46]=RUN, [47-49]=PEND. Two things about this pattern are themselves suspicious, not just 'the scheduler is behind': (a) elements [30-46] show RUN and [47-49] show PEND, i.e. the scheduler believes 20 elements haven't even STARTED yet, even though the controller's timestamps show the whole array finished by 1788084602 -- this is not a small lag, the scheduler's view is drastically behind reality for over a third of the array; (b) EXIT appears interspersed with DONE for a uniform array of a single reliably-successful command (`hostname`, not `/bin/false` or anything failure-prone) -- elements 17/20/22-24/26-29 show EXIT while their immediate neighbors show DONE, which is not what a simple 'scheduler hasn't caught up yet' lag would produce (a lagging-but-otherwise-correct view should show a clean PEND/RUN prefix behind a DONE suffix, not DONE and EXIT interleaved for what should be uniform outcomes). CORRELATED evidence from the SAME run: xce_scheduler's own log shows 10 consecutive WARN lines at the very same timeframe -- `xce_core_push_events JOBS_PUSH: sched_add_job failed for jobid (rc=-17), discarding duplicate/orphaned job` for jobid 4631575359520768000 through 4631575359520768009 -- which decode (JobID bit layout: tag/cluster/apiserver/timestamp/array_idx) to EXACTLY array elements 0-4-1788084587-0[0] through [9] of this SAME array. This WARN is emitted by the bug-1714-adjacent fix landed earlier this session (commit 38437e57, 'fix(scheduler): don't hand an orphaned duplicate job to the picker') -- confirms live, in this exact reproduction, that this array's first 10 elements were pushed to the scheduler TWICE (the TOCTOU dedup race in sched_on_job_array()/handler.c that commit documented as theoretically possible is firing for real here), and the second copy is now being correctly discarded rather than corrupting state or crashing (that part of the fix is working as designed). User also separately requested (logged here as part of the same report, lower priority, not a correctness bug): xce_core_push_events's WARN line above prints the raw numeric jobid (`4631575359520768000`) instead of this project's human-readable fmt_jobid() form (`0-4-1788084587-0[0]`) that every other job-related log line in this codebase uses -- a logging-usability gap in that specific WARN, worth a one-line fix.", "file": "src/scheduler/src/handler.c (sched_on_job_array's dedup-race, already documented as a known TOCTOU race by commit 38437e57), src/scheduler/src/core_events.c (xce_core_push_events, WARN log site + the JOBS_PUSH duplicate-discard path from commit 38437e57), src/scheduler/src/driver.c / src/controller/sched.c / src/controller/persist.c (the job-update notify pipeline this session's bug-1731/bug-1714 investigations already covers)", - "root_cause": "NOT YET ROOT-CAUSED -- logged for follow-up investigation per user request, not investigated live this session (a separate, still-running background investigation was mid-flight on bug-1714's own stale-reader when this was reported). Working hypothesis, NOT confirmed: this looks like more than one mechanism compounding. (1) The already-known, already-partially-mitigated sched_on_job_array() dedup race (see bug-1714's own root_cause history and commit 38437e57's message) is CONFIRMED firing live here (the WARN evidence decodes to exactly this array's first 10 elements) -- but discarding a genuine duplicate PUSH should be harmless on its own (both copies start from identical fresh JOB_STAT_PEND state; sched_add_job()'s key_add() correctly keeps the first copy), so this alone should not explain elements staying stuck at RUN/PEND when the controller confirms DONE. (2) The DONE/EXIT interleaving for a uniform, reliably-successful command (hostname) suggests either an ordering bug in how terminal-state notifications get applied (an older notification overwriting a newer one, or vice versa, for different elements) -- which would tie into bug-1731's own notify-drop/redelivery investigation and its live-captured evidence of scheduler-endpoint-NULL notify drops -- or a distinct bug in how JOB_STATE_CHANGE vs JOB_UPDATE detail routing interacts for array elements specifically (both hook-detail paths were touched this session by bug-1731's fixes; worth checking whether an array element's terminal notification can race between the two). (3) The ~20 elements the scheduler shows as never having started (RUN/PEND for [30-49]) despite controller-confirmed completion by 1788084602 is the most severe and least explained part of this report -- if genuinely not just a stale UI snapshot, this suggests SOME elements' notifications are being lost entirely, not just delayed, distinct from anything bug-1731's fix addressed (bug-1731 fixed the CONTROLLER never firing the right hook; this could be a SEPARATE loss further downstream, e.g. in delivery to the scheduler, or in how the scheduler's REPL/inspect view is rendered from its own internal state). NOT RULED OUT: this could also be nothing more than a snapshot-timing artifact if `[sim] jobs`/`joblist` were captured at genuinely different moments and the scheduler was still catching up -- but the user's own framing ('still have some issues') and the DONE/EXIT interleaving for a uniform command argue against pure timing lag being the whole explanation. Needs live reproduction with synchronized capture (query both views at the same instant, ideally with sequence numbers/timestamps on the query itself) to distinguish 'genuinely stuck' from 'was mid-catch-up when sampled'.\n\nADDITIONAL CONFIRMATION (same report, user follow-up): xce_test itself (the submitting client) also reports every job in this array finished successfully -- i.e. all three independent vantage points agree the work genuinely completed (worker execution, controller's own joblist/WAL state, and the submitting client's own completion tracking). This rules out worker-side execution failure and controller-side completion-tracking failure as explanations, narrowing this specifically to the scheduler-side notification delivery/application path (or, less likely, the scheduler's own REPL/inspect rendering of otherwise-correct internal state) -- consistent with, but not identical to, bug-1731's already-fixed dead-hook gap and its still-open notify-drop-on-disconnect finding.", - "fix": "NOT FIXED -- not yet investigated beyond this initial evidence capture, logged per explicit user request to defer to a later session. RECOMMENDED NEXT STEPS, in order of expected signal: (1) Reproduce with synchronized before/after captures of both `[sim] jobs` (scheduler) and `joblist` (controller) for the same array, timestamped precisely, to rule in/out pure snapshot-timing lag as the explanation for the [30-49] never-started-per-scheduler symptom. (2) If genuinely stuck (not just lagging), check whether the DEBUG3-gated diagnostic TRACE lines already added this session (job.c's update_job_rusages, sched.c's sched_job_update_fun, both from bug-1731's investigation) fire for the specific stuck elements' jobids -- if the TRACE never fires for them at all, the loss is upstream of the scheduler-notify layer (controller-side); if it fires but the scheduler's view still doesn't update, the loss is scheduler-side (delivery or apply). (3) Investigate whether the dedup-race discard path (commit 38437e57) has any interaction with the SPECIFIC elements that show the DONE/EXIT interleaving -- decode the jobids in scheduler.log's other DIAG/WARN lines around this same timeframe to see if the interleaved-EXIT elements correlate with duplicate-discard events too, the way [0-9] did here. (4) Small, separately-scoped fix for the human-readable-jobid logging request: xce_core_push_events's WARN in core_events.c (added by commit 38437e57) should use fmt_jobid() (already used throughout sched.c/handler.c/scheduler.c for jobid formatting in logs) instead of a raw %llu -- trivial, no TDD complexity, safe to land independently of the rest of this investigation.\n\nUPDATE (2026-08-30, later same day): NOT ATTEMPTED this session (documenting the gap rather than leaving it silent). Live repro of THIS entry specifically needs a worker to actually run array elements to DONE/EXIT so the scheduler-vs-controller views can diverge and be compared -- no `xcecd_virtual` binary exists in any build directory currently on this box (checked src/xce.build, src/xce.build.validate, src/build-asan, src/build-asan-1696repro -- only worker *unit test* binaries are present, never the daemon itself), and this session's time budget was consumed by an unrelated disk-space/nix-environment incident (see bug-1714's same-day update) plus a bug-1714-focused live-ASAN repro attempt, leaving no bounded time remaining to build `worker` fresh and pursue this entry's own recommended synchronized-capture plan. NEXT SESSION: build `worker` (`/xce-build worker`) alongside controller/scheduler before attempting this entry's Step 1 (synchronized `[sim] jobs` vs `joblist` capture) -- everything else in this entry's own recommended-next-steps list still stands unchanged.", + "root_cause": "NOT YET ROOT-CAUSED -- logged for follow-up investigation per user request, not investigated live this session (a separate, still-running background investigation was mid-flight on bug-1714's own stale-reader when this was reported). Working hypothesis, NOT confirmed: this looks like more than one mechanism compounding. (1) The already-known, already-partially-mitigated sched_on_job_array() dedup race (see bug-1714's own root_cause history and commit 38437e57's message) is CONFIRMED firing live here (the WARN evidence decodes to exactly this array's first 10 elements) -- but discarding a genuine duplicate PUSH should be harmless on its own (both copies start from identical fresh JOB_STAT_PEND state; sched_add_job()'s key_add() correctly keeps the first copy), so this alone should not explain elements staying stuck at RUN/PEND when the controller confirms DONE. (2) The DONE/EXIT interleaving for a uniform, reliably-successful command (hostname) suggests either an ordering bug in how terminal-state notifications get applied (an older notification overwriting a newer one, or vice versa, for different elements) -- which would tie into bug-1731's own notify-drop/redelivery investigation and its live-captured evidence of scheduler-endpoint-NULL notify drops -- or a distinct bug in how JOB_STATE_CHANGE vs JOB_UPDATE detail routing interacts for array elements specifically (both hook-detail paths were touched this session by bug-1731's fixes; worth checking whether an array element's terminal notification can race between the two). (3) The ~20 elements the scheduler shows as never having started (RUN/PEND for [30-49]) despite controller-confirmed completion by 1788084602 is the most severe and least explained part of this report -- if genuinely not just a stale UI snapshot, this suggests SOME elements' notifications are being lost entirely, not just delayed, distinct from anything bug-1731's fix addressed (bug-1731 fixed the CONTROLLER never firing the right hook; this could be a SEPARATE loss further downstream, e.g. in delivery to the scheduler, or in how the scheduler's REPL/inspect view is rendered from its own internal state). NOT RULED OUT: this could also be nothing more than a snapshot-timing artifact if `[sim] jobs`/`joblist` were captured at genuinely different moments and the scheduler was still catching up -- but the user's own framing ('still have some issues') and the DONE/EXIT interleaving for a uniform command argue against pure timing lag being the whole explanation. Needs live reproduction with synchronized capture (query both views at the same instant, ideally with sequence numbers/timestamps on the query itself) to distinguish 'genuinely stuck' from 'was mid-catch-up when sampled'.\n\nADDITIONAL CONFIRMATION (same report, user follow-up): xce_test itself (the submitting client) also reports every job in this array finished successfully -- i.e. all three independent vantage points agree the work genuinely completed (worker execution, controller's own joblist/WAL state, and the submitting client's own completion tracking). This rules out worker-side execution failure and controller-side completion-tracking failure as explanations, narrowing this specifically to the scheduler-side notification delivery/application path (or, less likely, the scheduler's own REPL/inspect rendering of otherwise-correct internal state) -- consistent with, but not identical to, bug-1731's already-fixed dead-hook gap and its still-open notify-drop-on-disconnect finding.\n\nUPDATE (2026-08-30, later same session, FULLY ROOT-CAUSED via live reproduction): Built controller+scheduler+worker+xceadmin fresh into src/xce.build.bug1734 (asan), deployed a real 3-node HA cluster (localhost:19991-19993) + xcecd_virtual worker + xce_scheduler (-vvv), submitted a 50-element `hostname` array job via xce_test, and captured synchronized evidence: controller `joblist` (ground truth, all 50 DONE with monotonic timestamps) vs the SAME scheduler process's own live session recording (`xceadmin scheduler record start/stop`) replayed via `xce_scheduler -i -s ` + `continue` (runs the ENTIRE recorded session set to completion, ruling out lag) + `info jobs`. REPRODUCED EXACTLY: final replayed state showed 23 of 50 elements wrong (3 EXIT, 13 RUN, 7 PEND) despite `continue` reaching 'replay complete' -- confirms GENUINE PERMANENT DESYNC, not lag. \n\nFull causal chain (all three links independently confirmed in the SAME live run's logs): (1) The scheduler's own OUTBOUND xcecli connection to the primary controller repeatedly failed over and reconnected under the array's load -- scheduler.log shows `xcecli failover: attempt N -> localhost:1999X` bouncing across all 3 candidates, 8 extra times in an ~8s window (exact trigger for THIS layer not further isolated -- plausibly -vvv DEBUG3 log volume + concurrent WAL/replication load causing a client-side request timeout to fire spuriously; flagged as a follow-up, see below). (2) Every one of those 8 reconnects made ctrl-1.log log `handle_scheduler_join` again, which runs on_scheduler_join() (controller/sched.c) -- a FULL resync (xcesched_push_configs + xcesched_push_workers + xcesched_push_jobs) on every join, no incrementality. xcesched_push_jobs()'s XceData_data_schedjobs wire path re-sends EVERY currently-committed job (not just the array), hitting the scheduler's ordinary (non-array) JOBS_PUSH handling with zero pre-existence filtering. Confirmed live: 700 `sched_add_job failed ... discarding duplicate` WARNs across the session (100 distinct jobids x up to 8 resyncs each), vs only ONE `job array push received and expanded` INFO line -- proving these duplicates come from the ordinary resync path, NOT bug-1714's documented sched_on_job_array() TOCTOU race (that race is real but was a red herring for THIS bug's data-loss mechanism -- it only ever double-submits freshly-PEND array elements, which key_add() correctly and harmlessly rejects, exactly as bug-1714/commit 38437e57 already established). (3) During the gap between disconnect and each reconnect, c->sched.ep is NULL, and any real job-finish notify due in that window is SILENTLY SKIPPED -- ctrl-1.log's pre-existing bug-1731-era DEBUG3 diagnostic `DIAG sched_job_update_fun: jobid=... state=... -- c->sched.ep is NULL, notify SKIPPED` fired 36 times in this run, for jobids matching the array. The very next full resync (link 2) is that job's ONLY remaining chance to reach the scheduler -- but XCE_CORE_EVENT_JOBS_PUSH's handling of an already-tracked jobid (core_events.c) discarded the incoming (correct, newer) job object UNCONDITIONALLY on sched_add_job()->key_add() EEXIST, NEVER updating the existing tracked xce_sched_job_t's state -- so a job whose terminal state only ever reached the scheduler via this resync path was permanently frozen at whatever PEND/RUN state it had before, exactly matching the reported DONE/EXIT-interleaved-with-stuck-RUN/PEND symptom. CONFIDENCE: HIGH -- root cause reproduced live, instrumented with the project's own existing diagnostics (no new printf needed), and closed with a RED->GREEN regression test that fails against the pre-fix code and passes after. \n\nNOT FIXED / follow-up (deliberately out of scope for this session, logged for a future bug): WHY the scheduler's own outbound xcecli connection to the primary keeps failing over under load (causal link 1 above) is not isolated to a specific timeout value or code site -- worth its own investigation (possibly a too-aggressive client-side request timeout in the shared xcecli/xce_request layer under DEBUG3 logging + concurrent WAL replication load). Reducing that flapping would reduce how often on_scheduler_join()'s full resync fires at all, but this session's fix (below) makes the resync SAFE regardless of how often it fires, which is the more load-bearing property (a resync will always be needed on genuine scheduler restart/rejoin, not just spurious flapping).", + "fix": "FIXED (2026-08-30). Root cause: src/scheduler/src/core_events.c's XCE_CORE_EVENT_JOBS_PUSH case treated sched_add_job()'s -EEXIST (job already tracked) as always a harmless no-op duplicate (per bug-1714/commit 38437e57's Bug A fix) and unconditionally freed the incoming xce_job_t without ever touching the existing tracked job. That assumption held for the array-push redelivery bug-1714 covers (both copies start fresh JOB_STAT_PEND) but not for on_scheduler_join()'s full-resync redelivery (controller/sched.c's xcesched_push_jobs(), fired on every scheduler (re)join), which can legitimately carry a job's CURRENT state -- including a terminal state the scheduler never saw because the matching real-time notify was dropped while c->sched.ep was NULL during the disconnect gap (bug-1731's still-open 'notify SKIPPED' diagnostic). Discarding that redelivery unconditionally silently and PERMANENTLY froze the scheduler's own view of the job at its pre-disconnect state, exactly reproducing this entry's reported controller-vs-scheduler divergence live. \n\nFIX (src/scheduler/src/core_events.c, XCE_CORE_EVENT_JOBS_PUSH case): on sched_add_job() EEXIST, look up the existing tracked xce_sched_job_t via sched_get_job() and, if its state differs from the redelivered copy's state, apply the SAME terminal-transition accounts/allocs cleanup XCE_CORE_EVENT_JOB_STATE_CHANGE/JOB_UPDATE already perform, update existing->state in place, and fire picker->picker_iface->on_job_state_change() so the picker's own bookkeeping stays consistent -- instead of silently dropping the newer information. The redelivered xce_job_t clone itself is still freed afterward (it was never registered in core->jobs and never will be) -- only its STATE is salvaged into the object future sched_get_job() lookups actually resolve to. Deliberately scoped to state only (not queue/resreq/other fields) -- documented as an explicit scope decision in the fix's own comment, same convention persistence.md's field-completeness guidance uses elsewhere. \n\nTDD: new regression test test_jobs_push_duplicate_jobid_with_newer_state_updates_existing_job (src/scheduler/testsuite/test_core_events.c) -- pushes jobid 56 as JOB_STAT_PEND, then redelivers the SAME jobid via a second JOBS_PUSH batch carrying JOB_STAT_DONE (simulating on_scheduler_join()'s resync racing a dropped terminal notify), asserts sched_get_job() still resolves to the SAME xce_sched_job_t (no orphaned duplicate, no key_add() churn) AND that its state is now JOB_STAT_DONE, not frozen at JOB_STAT_PEND. RED confirmed first (`Expected 8 Was 1` -- JOB_STAT_DONE vs JOB_STAT_PEND); GREEN after the fix. Full scheduler suite: 55/55 passing after the fix, zero regressions (bug-1714's own test_jobs_push_duplicate_jobid_does_not_call_on_job_push_or_leak still passes unchanged -- the two duplicate-handling paths, state-differs vs state-identical, are both exercised and both correct). \n\nLIVE RE-VERIFICATION: rebuilt xce_scheduler with the fix, restarted it against the SAME live 3-node cluster (still under the same reconnect-storm conditions -- 700 duplicate-discard WARNs still fired, confirming the fix does not suppress or depend on suppressing the underlying reconnect flapping), submitted a second 50-element array job, captured a fresh session recording, and replayed it via `xce_scheduler -i -s ` + `continue` + `info jobs`: all 100 jobs across both arrays (the pre-fix array replayed through the fixed binary this time, plus the new array) now show DONE, matching the controller's joblist exactly -- zero divergence, confirming the fix closes the reported gap under the exact live conditions that originally exposed it.", "tags": [ "scheduler", "controller", @@ -19997,25 +20008,24 @@ "state-desync", "found-live", "array-job", - "notify-loss-suspected", - "ordering-suspected", - "unfixed", - "unreproduced-with-sync-capture", - "needs-owner", + "fixed", + "root-caused", + "reconnect-storm", + "notify-drop-on-disconnect", + "resync-data-loss", "session-sibling-of-bug-1714", "session-sibling-of-bug-1731", - "correlated-with-dedup-race-warn", - "human-readable-jobid-logging-gap", - "low-priority-logging-followup", - "not-attempted-no-worker-binary-2026-08-30" + "session-sibling-of-bug-1733", + "human-readable-jobid-logging-gap-still-open", + "xcecli-failover-under-load-needs-followup" ], "related_bugs": [ "bug-1714", "bug-1731", "bug-1733" ], - "occurrences": 2, - "last_seen": "2026-08-30T14:00:00Z" + "occurrences": 3, + "last_seen": "2026-08-30T15:46:00Z" }, { "id": "bug-1735", diff --git a/.wolf/memory.md b/.wolf/memory.md index 6ac0fd8c..d9795860 100644 --- a/.wolf/memory.md +++ b/.wolf/memory.md @@ -3189,3 +3189,27 @@ | 08:24 | Edited src/controller/testsuite/test_host_runusage.c | modified test_update_host_runusage_parses_swap_and_task_count() | ~356 | | 08:25 | Edited src/controller/testsuite/test_host_runusage.c | modified test_aggregate_job_runusage_peak_cpu_time_is_running_max() | ~351 | | 08:25 | Edited src/controller/testsuite/test_host_runusage.c | 5→7 lines | ~126 | +| 08:38 | Edited src/controller/testsuite/test_commit_barrier_rollout.c | expanded (+7 lines) | ~173 | +| 08:38 | Edited src/controller/testsuite/test_commit_barrier_rollout.c | 4→8 lines | ~119 | +| 08:38 | Edited src/controller/testsuite/test_commit_barrier_rollout.c | modified jap_teardown() | ~370 | +| 08:39 | Edited src/controller/testsuite/test_demotion_convergence.c | expanded (+9 lines) | ~206 | +| 08:39 | Edited src/controller/testsuite/test_convergence_verification.c | expanded (+6 lines) | ~158 | +| 08:39 | Edited src/controller/testsuite/test_egress_filter.c | 3→8 lines | ~102 | +| 08:39 | Edited src/controller/testsuite/test_apply_pump.c | modified tap_teardown() | ~114 | +| 08:39 | Edited src/controller/testsuite/test_apply_pump.c | modified tpr_teardown() | ~175 | +| 08:40 | Edited src/controller/testsuite/test_apply_pump_integration.c | modified if() | ~254 | +| 08:40 | Edited src/controller/testsuite/test_job_array_fence.c | 3→8 lines | ~105 | +| 08:40 | Edited src/scheduler/testsuite/test_core_events.c | modified reproduction() | ~930 | +| 08:40 | Edited src/controller/testsuite/test_ha_role_lifecycle.c | 3→8 lines | ~104 | +| 08:40 | Edited src/controller/testsuite/test_job_array_replay_fence.c | 2→7 lines | ~97 | +| 08:40 | Edited src/scheduler/testsuite/test_core_events.c | 4→4 lines | ~69 | +| 08:42 | Edited src/controller/testsuite/test_commit_durability.c | expanded (+8 lines) | ~199 | +| 08:42 | Edited src/controller/testsuite/test_commit_durability.c | 6→10 lines | ~124 | +| 08:43 | Edited src/scheduler/testsuite/test_core_events.c | 2→3 lines | ~64 | +| 08:43 | Edited src/controller/testsuite/test_commit_durability.c | 7→11 lines | ~142 | +| 08:44 | Edited src/scheduler/src/core_events.c | added 5 condition(s) | ~1385 | +| 08:44 | Edited src/controller/testsuite/test_commit_engine.c | expanded (+6 lines) | ~115 | +| 08:45 | Edited src/controller/testsuite/test_p2_integration.c | expanded (+6 lines) | ~140 | +| 08:46 | Edited src/controller/testsuite/test_p2_integration.c | 5→9 lines | ~108 | +| 08:46 | Edited src/controller/testsuite/test_p2_integration.c | 4→8 lines | ~88 | +| 08:51 | Edited src/scheduler/src/core_events.c | modified 1734() | ~242 |