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 <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-08-20 04:24:44 +00:00
parent 008553e982
commit 5147396d0e
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
4 changed files with 90 additions and 1 deletions

View file

@ -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 -- <file>` 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."