feat(resource-value-verification): add scheduler resval trace log (task 4.1)

One TRACE (tlog_debug3) line in xce_core_push_events()'s RESVALS_DELTA case,
logging host/resource/value in a fixed format ("resval applied host=...
resource=... value=..."), immediately after the value is written to the
worker's live state. Debug-level only, no control-flow change.

Explicit svalue/fvalue branching (round-2 fix after review) - never reads a
Value_u_t union member without confirming .which matches first, since
Value_u_bvalue (boolean resources) is reachable at this path in production
and would otherwise be misread as a garbage float.

Live-confirmed against a real deployment at -vvv. Also surfaced (but did not
fix, out of boundary) a pre-existing double-free crash on a resource's
second periodic report - logged as bug-1572.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-08-18 01:49:25 +00:00
parent bc1380017e
commit e68444f1e9
Signed by: rshen
SSH key fingerprint: SHA256:8Vf2pZ3h6rJa7EhGK+WaAQ9Mta/apZvteW6g9U/WKKk
2 changed files with 38 additions and 1 deletions

View file

@ -42,7 +42,7 @@
- _Boundary: xce-deploy-ha (deploy-ha.sh, SKILL.md)_
- [ ] 4. Core: scheduler and apiserver trace-log instrumentation
- [ ] 4.1 (P) Add a trace log line to the scheduler's live resource-update handling
- [x] 4.1 (P) Add a trace log line to the scheduler's live resource-update handling
- In `xce_core_push_events()`'s `XCE_CORE_EVENT_RESVALS_DELTA` case (`src/scheduler/src/core_events.c`), add one `TRACE`-level log line (this component's existing `tinylog` convention) immediately after the resolved worker's value is written, logging the resolved host, resource name, and applied value in a fixed, greppable format
- Confirm the existing scheduler testsuite (`test_core_events.c` and friends) still passes unchanged — this is a pure log addition with no control-flow change, so no new unit test is required (consistent with this codebase's existing precedent: other `TRACE`/`WARN` calls in this area, e.g. `apiserver_worker_change`, have no dedicated unit test coverage either); the log line's actual content/format is confirmed live in task 8.1
- Observable completion: a live scheduler daemon's log file contains one line per applied resource update, in the format task 6.3 will grep for; existing scheduler tests are unaffected
@ -116,6 +116,8 @@
- _Depends: 7.1_
## Implementation Notes
- Task 4.1: the scheduler's trace log line format (task 6.3 must grep for exactly this) is `resval applied host=<H> resource=<R> value=<V>` at `DEBUG3` level (requires `-vvv`, per task 3.1's `start-all.sh`). Numeric resources use `%f` (fixed 6-decimal, e.g. `12345.500000` — parse-and-compare as float, not exact string match); string-typed resources (`type`/`model`) use `%s`. Any other `Value_u_which` tag (e.g. `Value_u_bvalue`, boolean resources) is silently NOT logged by this line (matches this file's own sibling-function convention) — not relevant to this feature's resource set, which is entirely fvalue/svalue.
- Task 4.1 (round 2) discovered and logged, but deliberately did NOT fix (out of boundary, confirmed pre-existing since 2026-08-03/04, unrelated to this feature): **bug-1572** — the live scheduler daemon double-frees and silently crashes on a worker's SECOND periodic resource report for the same resource (`core_events.c`'s RESVALS_DELTA case stores `rv->val` into `w->resvals` without `MOVE_PTR`, while `driver.c`'s `release_translated_payload()` unconditionally frees the same list). This feature's own resupdate-based injection flow (tasks 5.1+) should avoid resupdate-ing the exact same resource name twice against the same live scheduler within one run until bug-1572 is fixed separately, or the live e2e task (8.1) could intermittently crash the scheduler mid-run.
- Task 1.1: `resval_typeresolve.c`'s new function is `int resval_resolve_type(const char* name, int type_override)`, returning a `Value_u_which` tag or `RESVAL_TYPE_UNKNOWN` (-1, doesn't collide with the real 0-6 enum range). Task 2.1 should build on this exact signature rather than inventing a new one. `test.c`'s `set_resval()`/`cmd_resupdate()` were deliberately left untouched by task 1.1 — task 2.1 is the one that makes `set_resval()` a thin wrapper.
- `controller_unit_test` (the big legacy Unity binary) has a pre-existing, unrelated flaky failure in `test_config_repl.c` (bug-1561, overlayfs `fdatasync errno=5` sandbox artifact) that shows up on every `/xce-build controller` run in this environment. It is NOT caused by this feature's changes — do not chase it in later tasks; cross-check `.wolf/buglog.json`'s bug-1561 entry before treating a `controller_unit_test` failure as real, and confirm via `git status` that `test_config_repl.c`/`config_repl.c` are untouched by the current task's diff.
- Task 3.1: `src/frontend/Makefile`'s `build-server` target does not work standalone in this environment — it never sets `CGO_CFLAGS`/`CGO_LDFLAGS` the way `test-backend` does, failing with `fatal error: client.h: No such file or directory`. Pre-existing, out-of-boundary for this feature (confirmed unrelated to any of this feature's changes). To build a real apiserver binary for a live smoke test, export the same CGO flags `make test-backend` derives before running `go build`. Worth a separate bug-log entry / follow-up fix to the Makefile itself, not fixed here. Also found and worked around (config-only, no source change): `main.go`'s `RegisterToBackend` gate checks `BackendYamlConfig.Address` before consulting `Peers`, so a generated config needs `address`/`port` populated from the first `--peers` candidate, not just `peers` itself (bug-1571).

View file

@ -784,6 +784,41 @@ int xce_core_push_events(xce_sched_core_t* core, xce_core_event_t* events,
}
zarray_put(&(w->resvals), res->idx, rv->val);
/* resource-value-verification spec (task 4.1): the only
* place the live scheduler daemon observes and applies a
* resupdate-injected (or real) resource value -- fixed,
* greppable format, host/resource/value fields explicitly
* labeled, so task 6.3's log-tail check can match on
* "resval applied host=<H> resource=<R> value=<V>"
* without depending on any other text in this line.
* Debug/trace level only (tlog_debug3 via TRACE) -- no
* control-flow change, fires on every applied delta.
*
* bug-1573 fix (round-2 remediation): Value_u_which has 7
* tags (ivalue32/uvalue32/ivalue64/uvalue64/svalue/fvalue/
* bvalue -- controller.capnp.h) and Value_u_bvalue is a real,
* reachable tag at this exact path (worker.c's
* mark_host_res() sets it for any XCE_VAL_BOOLEAN resource,
* routed through the same update_val_res()/resupdate RPC).
* Round-1 wrongly treated "not svalue" as "must be fvalue"
* and read the wrong union member for bvalue. Only check
* .u.fvalue once .which is confirmed Value_u_fvalue, mirroring
* core_apply_worker_resvals()'s (this file, ~360 lines above)
* established convention for this same ambiguity: this
* feature's resource set is entirely fvalue/svalue today
* (resval_typeresolve.c), so other tags are silently skipped
* here rather than guessed at. */
if ((rv->val != NULL) && (rv->val->which == Value_u_svalue)) {
TRACE("resval applied host=%s resource=%s value=%s",
w->name ? w->name : "(null)", res->name,
rv->val->u.svalue ? rv->val->u.svalue : "(null)");
} else if ((rv->val != NULL)
&& (rv->val->which == Value_u_fvalue)) {
TRACE("resval applied host=%s resource=%s value=%f",
w->name ? w->name : "(null)", res->name,
rv->val->u.fvalue);
}
}
break;
}