From 5147396d0e90393cf32c91f5a0e6f3c0a613e023 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Thu, 20 Aug 2026 04:24:44 +0000 Subject: [PATCH] fix(controller): job start_time/finish_time/run_time never set by apply-pump apply_committed_entry()'s shared WAL_JOB_START/FINISH/STOP/RESUME/RUSAGE/ CKPT/PREASON dispatch case only ever called the generic, state-only apply_job_update_transition(j, state) -- start_time/finish_time/run_time were never touched, so `xcecli joblist` always showed StartTime=0 for RUN/DONE/EXIT jobs and FinishTime=0 for DONE jobs (EXIT jobs got a finish_time only via the separate, richer WAL_JOB_FAIL dispatch path). Fix is additive: stamp time(NULL) keyed on wal_type right after apply_job_update_transition() succeeds, still under the same lock(j, RTTI_LOCK_WRITE) -- WAL_JOB_START sets start_time, WAL_JOB_FINISH sets finish_time and derives run_time. No change to apply_job_update_transition()'s signature or the dispatch structure. Add test_ace_job_start_sets_start_time and test_ace_job_finish_sets_finish_time_and_run_time to test_apply_committed_entry.c, following the existing tace_seed_job fixture pattern. Co-Authored-By: Claude Sonnet 5 --- .wolf/cerebrum.md | 3 + .wolf/memory.md | 11 ++++ src/controller/persist.c | 19 +++++- .../testsuite/test_apply_committed_entry.c | 58 +++++++++++++++++++ 4 files changed, 90 insertions(+), 1 deletion(-) diff --git a/.wolf/cerebrum.md b/.wolf/cerebrum.md index 5c6cb370..ef2d475d 100644 --- a/.wolf/cerebrum.md +++ b/.wolf/cerebrum.md @@ -64,6 +64,9 @@ - **A pointer returned by `makeString()` (rtti-managed, `lib/xstring.c`) must always be released via `dereference()`, never `FREEUP()`/plain `free()`** — `makeInstance()`/`objAlloc()` returns an offset into a combined header+data block, not the block's own `malloc()`-returned base address, and the string is refcounted (freed only when the refcount hits zero), not directly owned. bug-1600 (2026-08-19, production, not a test fixture — see also bug-1503's earlier test-fixture instance of the identical mismatch): `lib/group.c`'s `makeGroup()` "existing group" update branch (hit every time a config-push re-applies a group name that already has members, e.g. any retried/duplicate config push — no thread concurrency required) called `FREEUP(m->u.name)` on a `makeString()`-allocated field, while the SAME FILE's `group_killer()` destructor released the identical field correctly via `dereference(m->u.name)`. This caused the real, reproducible (8 confirmed core dumps) `xce_scheduler` `free(): invalid pointer` SIGABRT crash during controller-failover config-push retries. **When adding or auditing any free/release path for a field populated by `makeString()`, grep the same file/struct for an existing destructor and match its release call — don't assume `FREEUP()` is safe just because it's used for adjacent plain-`calloc`'d fields in the same struct.** - **`lib/group.c`'s `makeGroup()` "existing group" update path takes only `RTTI_LOCK_READ` (a genuine shared `pthread_rwlock_rdlock`, confirmed via `kvmgr.c`) while mutating shared group member-list state, and the scheduler's entire config-push handler chain (`sched_init_config()` → `plugin_config_update()` → ... → `makeGroup()`) holds no serializing lock at all — while `scheduler_req_handler()` genuinely runs on whichever of the scheduler's 4 vcpu worker pthreads picked up that vtask (`vtaskmgr_init(..., 4)`).** `xce_ctx_reconnect()` reuses the same `ctx->ep` struct and `endpoint_init()` unconditionally resets `ep->busy=0`, so a reconnect racing with a still-running config-push handler can let a second, concurrently-dispatched config-push run `makeGroup()` on the same group object at the same time as the first. This is a REAL latent concurrency bug distinct from bug-1600's allocator mismatch (which alone was sufficient to explain the observed crash and was the one fixed) — flagged as a follow-up, not yet fixed; would need a write-lock scope redesign since `init_group_by_config()`'s callees (`get_group()`) take their own internal read lock, so naively holding a write lock across the whole function would self-deadlock on the non-recursive rwlock. +- **`apply_committed_entry()`'s shared WAL_JOB_START/FINISH/STOP/RESUME/RUSAGE/CKPT/PREASON dispatch case (`persist.c`) never stamped `start_time`/`finish_time`/`run_time`** — it only ever called the generic, state-only `apply_job_update_transition(j, state)` (2026-08-19, `xcecli joblist` showed `StartTime`=0 for every RUN/DONE/EXIT job, `FinishTime`=0 for DONE jobs). Fixed additively (user's explicit steering: "don't change the logic, just add extra information") by keying a `time(NULL)` stamp on `wal_type` right after `apply_job_update_transition()` succeeds, still under the same `lock(j, RTTI_LOCK_WRITE)` — `WAL_JOB_START` → `start_time`, `WAL_JOB_FINISH` → `finish_time` + `run_time = finish_time - start_time`. No change to `apply_job_update_transition()`'s signature or the dispatch structure. Mirrors what the richer (currently-unreached-on-this-path) `apply_job_start_transition()`/`apply_job_finish_transition()` cores in `job.c` already do for their own callers. +- **`test_config_repl.c`'s `test_conf_trim_keeps_only_n_versions`/`test_conf_get_saved_tag_no_config` failing with the exact same Expected/Was values plus a burst of `persist: flusher fdatasync FAILED (errno=5 Input/output error)` lines is bug-1561, a confirmed overlayfs-sandbox `fdatasync` artifact — 6 occurrences now across unrelated sessions/diffs, never once traced to a real code change.** If a `/xce-build controller` run shows exactly these 2 failures with that exact error pattern, it's environment noise, not something your change caused — don't spend time re-investigating, just note it and move on (though still bump bug-1561's `occurrences`/`last_seen` per buglog protocol). + ## Do-Not-Repeat - Don't run `clang-format -i` on whole existing files here — the repo isn't clang-format-clean at baseline, so a full reformat buries the real diff; recovering via `git checkout HEAD -- ` on a file with other uncommitted work destroys that work irrecoverably. - Before citing a bug as "still open" or a spec as "blocked," cross-check `.wolf/buglog.json`'s actual fix status and the spec's own tasks.md/commit history — blocked_on notes and prior narrative claims (including this file's own past entries) can be stale. **Self-caught recurrence (2026-08-19)**: while reconciling OTHER stale doc references, wrote a new tasks.md status line asserting "tasks 2.1-2.6 still carry no `_Verified:` annotations" by trusting a 2026-08-07 validation finding's own wording verbatim, without re-checking the file — they'd actually been backfilled the very next day (commit `d7b49690`, 2026-08-08). A dispatched verification agent caught it via `git log`/direct read. Lesson holds even for a claim you are ABOUT to write, not just one you're citing from memory: grep/read the actual current state of the specific lines before asserting their status, every time, no exceptions for "this one's probably still true." diff --git a/.wolf/memory.md b/.wolf/memory.md index fce45d4d..c7c24706 100644 --- a/.wolf/memory.md +++ b/.wolf/memory.md @@ -2509,3 +2509,14 @@ | 21:01 | Edited src/lib/group.c | FREEUP() → dereference() | ~24 | | 21:02 | Session end: 2 writes across 2 files (test_group.c, group.c) | 19 reads | ~25269 tok | | 21:06 | Fixed production heap-corruption crash: makeGroup() FREEUP() vs dereference() allocator mismatch | src/lib/group.c, src/lib/testsuite/test_group.c | RED->GREEN confirmed via ASAN, logged bug-1600 | ~15000 | +| 04:05 | Verified: nix develop ./src -- xce-build.sh lib asan (clean build, exit 0) | src/lib/group.c fix | 301 Tests 0 Failures 0 Ignored; test_reconfigure_same_group_members PASS, no ASAN aborts | ~12000 | +| 21:07 | Edited src/controller/testsuite/test_apply_committed_entry.c | 4→5 lines | ~26 | +| 21:08 | Edited src/controller/testsuite/test_apply_committed_entry.c | modified test_ace_job_start_sets_start_time() | ~540 | +| 21:08 | Edited src/controller/testsuite/test_apply_committed_entry.c | 2→4 lines | ~67 | +| 21:09 | Edited src/controller/testsuite/test_apply_committed_entry.c | 18→17 lines | ~194 | +| 21:09 | Edited src/controller/testsuite/test_apply_committed_entry.c | TEST_ASSERT_EQUAL_UINT64_MESSAGE() → TEST_ASSERT_EQUAL_INT_MESSAGE() | ~125 | +| 21:09 | Edited src/controller/persist.c | added 3 condition(s) | ~312 | +| 21:09 | Edited src/controller/persist.c | 6→8 lines | ~155 | +| 21:10 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok | +| 21:11 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok | +| 21:12 | Fixed StartTime/FinishTime never set (raft-apply-decoupling apply-pump gap) — wal_type-keyed time(NULL) stamping in apply_committed_entry, TDD RED->GREEN, bug-1561 re-observed (6th time, unrelated overlayfs artifact, not a regression) | src/controller/persist.c, src/controller/testsuite/test_apply_committed_entry.c, .wolf/buglog.json | GREEN, 1107 Tests 2 pre-existing-unrelated Failures | ~35000 | diff --git a/src/controller/persist.c b/src/controller/persist.c index 9b2c93b9..5ad40733 100644 --- a/src/controller/persist.c +++ b/src/controller/persist.c @@ -3714,7 +3714,9 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn, * apply_committed_entry for the full routing table and why this * does not dispatch to the richer type-specific apply_job_{start, * finish}_transition() cores (their parameter structs are not - * present on this wire format). */ + * present on this wire format) — start_time/finish_time/run_time + * are instead stamped directly below, keyed on wal_type, since + * apply_job_update_transition() only ever touches `state`. */ if (len < sizeof(wal_jobstate_t)) return 0; /* undersized payload — skip, mirrors apply_wal_entry */ @@ -3729,6 +3731,21 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn, lock(j, RTTI_LOCK_WRITE); job_transition_result_t result = apply_job_update_transition(j, (int)js->state); + if (result == JOB_TRANSITION_APPLIED) { + /* apply_job_update_transition() only carries {jobid, state} on + * this wire shape (see the doc comment above) and never touches + * start_time/finish_time/run_time itself — stamp them here, + * keyed on wal_type, mirroring what the richer + * apply_job_start_transition()/apply_job_finish_transition() + * cores do for their own (currently unreachable on this dispatch + * path) callers. */ + if (wal_type == WAL_JOB_START) { + j->job.start_time = time(NULL); + } else if (wal_type == WAL_JOB_FINISH) { + j->job.finish_time = time(NULL); + j->job.run_time = (int)(j->job.finish_time - j->job.start_time); + } + } unlock(j); if (result != JOB_TRANSITION_APPLIED) diff --git a/src/controller/testsuite/test_apply_committed_entry.c b/src/controller/testsuite/test_apply_committed_entry.c index 6970340c..e5a8982c 100644 --- a/src/controller/testsuite/test_apply_committed_entry.c +++ b/src/controller/testsuite/test_apply_committed_entry.c @@ -31,6 +31,7 @@ #include #include #include +#include #include @@ -402,6 +403,61 @@ test_ace_job_state_transition_rejects_backward_suppresses_notify(void) "notify: PASS\n"); } +static void test_ace_job_start_sets_start_time(void) +{ + tace_setup(); + + job_t* j = tace_seed_job(603, JOB_STAT_PEND); + TEST_ASSERT_NOT_NULL(j); + TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time, + "fixture must seed a job with start_time still unset"); + + wal_jobstate_t js = { .jobid = 603, .state = JOB_STAT_RUN }; + + time_t before = time(NULL); + int rc = apply_committed_entry(&g_tace_p, WAL_JOB_START, 22, &js, + sizeof(js)); + time_t after = time(NULL); + + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state); + TEST_ASSERT_TRUE_MESSAGE( + (j->job.start_time >= before) && (j->job.start_time <= after), + "WAL_JOB_START must stamp start_time to the apply-time clock"); + + tace_teardown(); + printf("test_ace_job_start_sets_start_time: PASS\n"); +} + +static void test_ace_job_finish_sets_finish_time_and_run_time(void) +{ + tace_setup(); + + job_t* j = tace_seed_job(604, JOB_STAT_RUN); + TEST_ASSERT_NOT_NULL(j); + j->job.start_time = 1000; + + wal_jobstate_t js = { .jobid = 604, .state = JOB_STAT_DONE }; + + time_t before = time(NULL); + int rc = apply_committed_entry(&g_tace_p, WAL_JOB_FINISH, 23, &js, + sizeof(js)); + time_t after = time(NULL); + + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT32(JOB_STAT_DONE, j->job.state); + TEST_ASSERT_TRUE_MESSAGE( + (j->job.finish_time >= before) && (j->job.finish_time <= after), + "WAL_JOB_FINISH must stamp finish_time to the apply-time clock"); + TEST_ASSERT_EQUAL_INT_MESSAGE((int)(j->job.finish_time - 1000), + j->job.run_time, + "run_time must be derived from the stamped finish_time minus the " + "job's start_time"); + + tace_teardown(); + printf("test_ace_job_finish_sets_finish_time_and_run_time: PASS\n"); +} + /* ── WAL_QUEUE_CTRL ───────────────────────────────────────────────────── */ static void test_ace_queue_ctrl_updates_and_notifies(void) @@ -1041,6 +1097,8 @@ void test_apply_committed_entry(void) RUN_TEST(test_ace_job_submit_duplicate_is_noop_no_extra_notify); RUN_TEST(test_ace_job_state_transition_applies_forward_and_notifies); RUN_TEST(test_ace_job_state_transition_rejects_backward_suppresses_notify); + RUN_TEST(test_ace_job_start_sets_start_time); + RUN_TEST(test_ace_job_finish_sets_finish_time_and_run_time); RUN_TEST(test_ace_queue_ctrl_updates_and_notifies); RUN_TEST(test_ace_worker_ctrl_join_restores_and_notifies); RUN_TEST(test_ace_worker_ctrl_update_applies_to_existing_worker);