From 72b6fdea4a139933c0a374d32f45bcfcb1dc5931 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 18 Aug 2026 10:21:50 +0000 Subject: [PATCH] feat(resource-value-verification): scheduler-side verification check (task 6.3) poll_scheduler_log()/query_scheduler_resvals() tail the live scheduler daemon's log (task 4.1's trace line) for each accepted injected resource, with a bounded ~15s wait batched across all pending resources per poll iteration (not N times the timeout). Reports MATCH / MISMATCH (both values) / UNREACHABLE (timeout, distinct from mismatch), tracked in SCHEDULER_OBSERVED/SCHEDULER_CHECK_RESULTS + scheduler-check-results.tsv. Live-proven immune to bug-1579 (unlike the controller check): injecting a host-attrs resource (cpuf) simultaneously produces a controller MISMATCH and a scheduler MATCH, since this check reads task 4.1's trace log (written once, at apply-time) rather than re-querying live state after the worker disconnects. Co-Authored-By: Claude Sonnet 5 --- .../xce-test-resources/run-resource-verify.sh | 246 +++++++++++++++--- .../resource-value-verification/tasks.md | 4 +- 2 files changed, 218 insertions(+), 32 deletions(-) diff --git a/.claude/skills/xce-test-resources/run-resource-verify.sh b/.claude/skills/xce-test-resources/run-resource-verify.sh index 9589dac0..ef55d930 100755 --- a/.claude/skills/xce-test-resources/run-resource-verify.sh +++ b/.claude/skills/xce-test-resources/run-resource-verify.sh @@ -5,23 +5,27 @@ # resource value via xce_test's resupdate, confirm it is visible at the # controller, live scheduler, and Go apiserver). # -# resource-value-verification spec, task 5.1+6.1+6.2 SCOPE: this file +# resource-value-verification spec, task 5.1+6.1+6.2+6.3 SCOPE: this file # currently implements deployment (task 5.1), worker join + resource -# injection (task 6.1), AND the controller-side per-layer verification check -# (task 6.2) -- stand up a fresh controller + scheduler (-vvv) + apiserver -# (debug logging) deployment via xce-deploy-ha's deploy-ha.sh + generated +# injection (task 6.1), the controller-side per-layer verification check +# (task 6.2), AND the scheduler-side per-layer verification check (task 6.3) +# -- stand up a fresh controller + scheduler (-vvv) + apiserver (debug +# logging) deployment via xce-deploy-ha's deploy-ha.sh + generated # start-all.sh, confirm all three components are actually up, join a # SYNTHETIC worker (no real worker daemon process) through xce_test's worker -# context, run resupdate for one or more resource=value pairs, then query the -# controller (xce_test client-context `resval`) for every ACCEPTED pair and -# report MATCH/MISMATCH against the injected value, and clean up (trap-based, -# covering a mid-deployment abort, not just a completed run). Scheduler/ -# apiserver per-layer verification (tasks 6.3-6.4) and verdict aggregation / +# context, run resupdate for one or more resource=value pairs, then (a) query +# the controller (xce_test client-context `resval`) for every ACCEPTED pair +# and report MATCH/MISMATCH against the injected value, and (b) poll the live +# scheduler daemon's own log file (task 4.1's trace line) for the same +# ACCEPTED pairs, within a bounded wait, and report MATCH/MISMATCH/ +# UNREACHABLE distinctly from the controller-side result, then clean up +# (trap-based, covering a mid-deployment abort, not just a completed run). +# Apiserver per-layer verification (task 6.4) and verdict aggregation / # cleanup-on-every-path (task 7.1) are added by LATER tasks -- see the # "Extension points" markers in main() below for exactly where they hook in. # See .kiro/specs/resource-value-verification/{requirements,design}.md, -# Requirements 2.1, 2.2, 3.1, 3.2, 5.3, 6.1, 6.4, 6.5 for these tasks; the -# full skill covers 3.1-6.5. +# Requirements 2.1, 2.2, 3.1, 3.2, 4.1, 4.2, 4.3, 5.3, 6.1, 6.4, 6.5 for these +# tasks; the full skill covers 3.1-6.5. # # Task 6.1 deliberate deviation from design.md: the default (no-args) # resource set is Requirement 1's gap-resource set (r15m, pg, ls, it, swp, @@ -83,18 +87,21 @@ # components confirmed up, worker joined, resupdate ran for every requested # resource -- accepted AND rejected outcomes are both a successful run of # THIS script's scope, see inject_resources() -- and the controller-side -# check (task 6.2) ran for every accepted resource -- a MATCH or a MISMATCH -# are BOTH a successful run of this script's own scope, see -# query_controller_resvals(); only a structural failure to query the -# controller at all is fatal here -- cleaned up per --keep-running). +# check (task 6.2) and scheduler-side check (task 6.3) each ran for every +# accepted resource -- a MATCH, a MISMATCH, or (scheduler-side only) an +# UNREACHABLE/timeout are ALL a successful run of this script's own scope, +# see query_controller_resvals()/query_scheduler_resvals(); only a structural +# failure to query the controller, or to read the injection manifest for the +# scheduler check, is fatal here -- cleaned up per --keep-running). # Non-zero == deployment failed at some step, the worker failed to join, # resupdate produced no observable accept/reject outcome for some name (a # structural injection failure, distinct from a legitimate rejection), or the # controller-side check itself could not run (e.g. the client context failed -# to connect). Once tasks 6.3-7.1 land, the exit code instead reflects the -# full injection/verification PASS/FAIL verdict -- task 6.2 deliberately does -# NOT fail the run on a controller-layer MISMATCH yet (see -# ANY_CONTROLLER_MISMATCH, groundwork for task 7.1's aggregation). +# to connect). Once task 6.4/7.1 land, the exit code instead reflects the +# full injection/verification PASS/FAIL verdict -- tasks 6.2/6.3 deliberately +# do NOT fail the run on a controller- or scheduler-layer MISMATCH/ +# UNREACHABLE yet (see ANY_CONTROLLER_MISMATCH/ANY_SCHEDULER_MISMATCH/ +# ANY_SCHEDULER_UNREACHABLE, groundwork for task 7.1's aggregation). # set -u @@ -623,6 +630,176 @@ $out" done } +# ── Step 6: scheduler-side verification check (task 6.3) ─────────────────── +# Requirement 4.1/4.2/4.3: for every SUCCESSFULLY-injected (accepted) +# resource/worker pair, poll (short interval, bounded generous total wait -- +# design.md's "poll with a short interval up to a generous timeout, not +# tight polling that could flake") the live scheduler daemon's own log file +# for task 4.1's trace line -- "resval applied host= resource= +# value=" at DEBUG3 (`-vvv`, already how start-all.sh starts the +# scheduler, per task 3.1) -- and compare the parsed value against the +# injected one, reusing controller_values_match() (numeric-with-tolerance vs. +# exact-string, same rule for either layer). A resource whose trace line +# never appears within the bounded wait is reported as "unreachable" / +# timeout, explicitly distinct from a value MISMATCH (design.md Error +# Handling -- "Layer unreachable" is its own category, not folded into +# mismatch). No record/replay/REPL round-trip -- a plain tail/grep of a live +# log file, per the System Flows sequence diagram. A REJECTED resource was +# never actually applied anywhere (task 2.2's own follow-up query inside +# resupdate already confirmed that at injection time) -- nothing to verify +# for it here either, same skip rule query_controller_resvals() (task 6.2) +# already established. + +# Poll interval / bounded total wait, shared across the WHOLE batch of +# still-pending resources per iteration (see poll_scheduler_log below), not +# a separate full bounded wait PER resource -- so N accepted resources costs +# at most one ~15s bounded wait in the worst case (all N stuck), not N of +# them stacked sequentially; in the common case (scheduler already applied +# everything by the time this runs, since it fires after inject_resources() +# AND query_controller_resvals()'s own extra RPC round trip) it costs one +# fast pass with no sleep at all. +SCHED_POLL_INTERVAL="0.5" +SCHED_POLL_MAX_ITERS=30 # 30 x 0.5s = 15s total bounded wait + +# poll_scheduler_log SCHED_LOG_FILE HOST NAME... +# Core bounded-wait poller, deliberately factored out of +# query_scheduler_resvals() so it can be exercised directly (e.g. against a +# name/host combination that was never actually injected, to prove the +# "unreachable" path is genuinely reachable) independent of the +# accepted-injection bookkeeping -- same "pure/self-contained, independently +# testable" spirit as controller_values_match(). Each iteration takes ONE +# full pass over SCHED_LOG_FILE (a single awk invocation building a +# name->value map for every "resval applied host= resource=..." line +# seen for HOST, last occurrence per name wins) and checks every STILL- +# PENDING name against that map, rather than a separate grep-with-its-own- +# timeout per name run in sequence -- by the time a later name in the batch +# is checked, an earlier name's line has almost certainly already appeared +# in the same log-file read. Prints "namevalue" to stdout for every +# name that WAS observed within the bounded wait; a name with no +# corresponding output line was NOT observed -- the caller's job to report +# that distinctly as "unreachable", not silently as a mismatch with an empty +# value. +poll_scheduler_log() { + local sched_log="$1" host="$2" + shift 2 + local pending=("$@") + local -A found=() + local iter=0 + + while [ "$iter" -lt "$SCHED_POLL_MAX_ITERS" ] && [ "${#pending[@]}" -gt 0 ]; do + iter=$((iter + 1)) + + local name val + while IFS=$'\t' read -r name val; do + [ -n "$name" ] || continue + found["$name"]="$val" + done < <(awk -v needle="resval applied host=${host} resource=" ' + index($0, needle) > 0 { + line = $0 + sub(/^.*resource=/, "", line) + sep = index(line, " value=") + if (sep > 0) { + seen[substr(line, 1, sep - 1)] = substr(line, sep + 7) + } + } + END { for (n in seen) print n "\t" seen[n] } + ' "$sched_log" 2>/dev/null) + + local still_pending=() + for name in "${pending[@]}"; do + if [ -z "${found[$name]+x}" ]; then + still_pending+=("$name") + fi + done + pending=("${still_pending[@]}") + + if [ "${#pending[@]}" -gt 0 ] && [ "$iter" -lt "$SCHED_POLL_MAX_ITERS" ]; then + sleep "$SCHED_POLL_INTERVAL" + fi + done + + local n + for n in "${!found[@]}"; do + printf '%s\t%s\n' "$n" "${found[$n]}" + done +} + +declare -A SCHEDULER_OBSERVED=() # resource name -> raw applied value string from the scheduler's trace log (only set for accepted names actually observed) +declare -A SCHEDULER_CHECK_RESULTS=() # resource name -> "MATCH" | "MISMATCH: injected= observed=" | "UNREACHABLE: ..." +ANY_SCHEDULER_MISMATCH=0 # groundwork for task 7.1's verdict aggregation, mirrors ANY_CONTROLLER_MISMATCH; this task's own exit code does NOT depend on it +ANY_SCHEDULER_UNREACHABLE=0 # groundwork for task 7.1; kept distinct from ANY_SCHEDULER_MISMATCH per Requirement 4.2/4.3 and design.md's "Layer unreachable" being its own error category + +# query_scheduler_resvals -- reads $TOP/logs/injection-results.tsv (same +# durable, order-preserving source query_controller_resvals() (task 6.2) +# reads) and, for every name marked "accepted", polls $TOP/logs/ +# scheduler.log via poll_scheduler_log() above. Populates +# SCHEDULER_OBSERVED/SCHEDULER_CHECK_RESULTS and $TOP/logs/ +# scheduler-check-results.tsv (name\tinjected\tobserved\tresult), following +# the exact same pattern query_controller_resvals() established for its own +# layer. +query_scheduler_resvals() { + local tsv="$TOP/logs/injection-results.tsv" + [ -f "$tsv" ] || fail "scheduler check: $tsv not found -- inject_resources() must run first" + + local name value result accepted_names=() skipped_names=() + while IFS=$'\t' read -r name value result; do + if [ "$result" = "accepted" ]; then + accepted_names+=("$name") + else + skipped_names+=("$name") + fi + done < "$tsv" + + if [ "${#skipped_names[@]}" -gt 0 ]; then + log "scheduler check: skipping ${#skipped_names[@]} non-accepted resource(s) -- never actually applied at the scheduler, nothing to verify there: ${skipped_names[*]}" + fi + + if [ "${#accepted_names[@]}" -eq 0 ]; then + log "scheduler check: no accepted resources to verify" + return 0 + fi + + local sched_log="$TOP/logs/scheduler.log" + local total_wait + total_wait="$(awk -v i="$SCHED_POLL_INTERVAL" -v n="$SCHED_POLL_MAX_ITERS" 'BEGIN{printf "%.1f", i*n}')" + log "scheduler check: polling $sched_log for ${#accepted_names[@]} accepted resource(s), bounded wait up to ${total_wait}s total: ${accepted_names[*]}" + + local -A observed_map=() + local n v + while IFS=$'\t' read -r n v; do + [ -n "$n" ] || continue + observed_map["$n"]="$v" + done < <(poll_scheduler_log "$sched_log" "$WORKER_HOST" "${accepted_names[@]}") + + mkdir -p "$TOP/logs" + local results_tsv="$TOP/logs/scheduler-check-results.tsv" + : > "$results_tsv" + + local injected observed result_str + for name in "${accepted_names[@]}"; do + injected="${INJECTED_VALUES[$name]}" + + if [ -z "${observed_map[$name]+x}" ]; then + observed="" + result_str="UNREACHABLE: no scheduler trace-log line observed within bounded wait (injected=$injected observed=)" + ANY_SCHEDULER_UNREACHABLE=1 + else + observed="${observed_map[$name]}" + if controller_values_match "$injected" "$observed"; then + result_str="MATCH" + else + result_str="MISMATCH: injected=$injected observed=$observed" + ANY_SCHEDULER_MISMATCH=1 + fi + fi + + SCHEDULER_OBSERVED["$name"]="$observed" + SCHEDULER_CHECK_RESULTS["$name"]="$result_str" + log "scheduler check: $name -> $result_str" + printf '%s\t%s\t%s\t%s\n' "$name" "$injected" "$observed" "$result_str" >> "$results_tsv" + done +} + main() { parse_args "$@" resolve_top @@ -644,21 +821,28 @@ main() { query_controller_resvals - # --- Extension point (tasks 6.3-6.4): scheduler/apiserver per-layer - # verification checks here, consuming ${INJECTED_VALUES[@]}/ - # ${INJECTED_RESULTS[@]} and $WORKER_HOST populated by - # inject_resources() above (also mirrored to - # $TOP/logs/injection-results.tsv), following the same pattern - # query_controller_resvals() (task 6.2) just established for its own - # layer -- CONTROLLER_OBSERVED/CONTROLLER_CHECK_RESULTS + - # $TOP/logs/controller-check-results.tsv. --- + query_scheduler_resvals + + # --- Extension point (task 6.4): apiserver per-layer verification check + # here, consuming ${INJECTED_VALUES[@]}/${INJECTED_RESULTS[@]} and + # $WORKER_HOST populated by inject_resources() above (also mirrored + # to $TOP/logs/injection-results.tsv), following the same pattern + # query_controller_resvals() (task 6.2) and query_scheduler_resvals() + # (task 6.3) just established for their own layers -- + # CONTROLLER_OBSERVED/CONTROLLER_CHECK_RESULTS + + # $TOP/logs/controller-check-results.tsv; + # SCHEDULER_OBSERVED/SCHEDULER_CHECK_RESULTS + + # $TOP/logs/scheduler-check-results.tsv. --- # --- Extension point (task 7.1): aggregate results into a VERDICT line # plus the terminal PASS/FAIL oracle line, replacing this task's - # placeholder success message and exit code below. ANY_CONTROLLER_MISMATCH - # (set by query_controller_resvals() above) is groundwork for this - # aggregation -- task 6.2 itself deliberately does not act on it. --- + # placeholder success message and exit code below. + # ANY_CONTROLLER_MISMATCH/ANY_SCHEDULER_MISMATCH/ + # ANY_SCHEDULER_UNREACHABLE (set by query_controller_resvals()/ + # query_scheduler_resvals() above) are groundwork for this + # aggregation -- tasks 6.2/6.3 themselves deliberately do not act on + # them. --- - log "PASS (task 5.1+6.1+6.2 scope): controller, scheduler, and apiserver confirmed up; worker '$WORKER_HOST' joined and resupdate ran for ${#INJECTED_RESULTS[@]} resource(s) under $TOP (see $TOP/logs/injection-results.tsv for the accept/reject detail per name -- a rejection there is a captured outcome, not a script failure at this stage); controller-side check ran for every accepted resource (see $TOP/logs/controller-check-results.tsv -- a MISMATCH there is also a captured outcome, not a script failure at this stage, see ANY_CONTROLLER_MISMATCH); scheduler/apiserver per-layer verification and the overall PASS/FAIL verdict land in tasks 6.3-7.1; cleaning up" + log "PASS (task 5.1+6.1+6.2+6.3 scope): controller, scheduler, and apiserver confirmed up; worker '$WORKER_HOST' joined and resupdate ran for ${#INJECTED_RESULTS[@]} resource(s) under $TOP (see $TOP/logs/injection-results.tsv for the accept/reject detail per name -- a rejection there is a captured outcome, not a script failure at this stage); controller-side check ran for every accepted resource (see $TOP/logs/controller-check-results.tsv -- a MISMATCH there is also a captured outcome, not a script failure at this stage, see ANY_CONTROLLER_MISMATCH); scheduler-side check ran for every accepted resource (see $TOP/logs/scheduler-check-results.tsv -- a MISMATCH or UNREACHABLE there is also a captured outcome, not a script failure at this stage, see ANY_SCHEDULER_MISMATCH/ANY_SCHEDULER_UNREACHABLE); apiserver per-layer verification and the overall PASS/FAIL verdict land in tasks 6.4-7.1; cleaning up" exit 0 } diff --git a/.kiro/specs/resource-value-verification/tasks.md b/.kiro/specs/resource-value-verification/tasks.md index 14d50604..6622bfc2 100644 --- a/.kiro/specs/resource-value-verification/tasks.md +++ b/.kiro/specs/resource-value-verification/tasks.md @@ -76,7 +76,7 @@ - _Depends: 6.1_ - _Boundary: xce-test-resources skill (controller check) — same file as 6.3/6.4 (`run-resource-verify.sh`), sequential, not parallel-safe_ -- [ ] 6.3 Implement the scheduler-side verification check via trace-log tail +- [x] 6.3 Implement the scheduler-side verification check via trace-log tail - Tail/grep the live scheduler daemon's log file (task 4.1's trace line) for each injected resource/worker pair, polling with a short interval up to a generous, explicit bounded wait — no record, no replay, no REPL - Compare the scheduler's observed value against the injected value, reported distinctly from the controller-side result; a timeout with no matching line is reported as "unreachable," distinct from a value mismatch - Observable completion: the check reports, per resource, whether the scheduler's observed value matches the injected value within the bounded wait, attributable specifically to the scheduler layer @@ -116,6 +116,8 @@ - _Depends: 7.1_ ## Implementation Notes +- Task 6.3 confirmed (live, via a `cpuf` probe: controller MISMATCH + scheduler MATCH simultaneously) that the scheduler check is genuinely immune to bug-1579 — it reads task 4.1's trace log (written once, at apply-time, in the `RESVALS_DELTA` case only), never touched by a later worker-disconnect's `WORKERS_PUSH`-driven reset. **Real fix for bug-1579 identified, not yet applied** (see below) — the `!` escape in `xce_test` (`preprocess_and_run()`, `test.c` ~line 965) works in ANY context including `worker` mode, since it's handled in the single top-level REPL loop before context dispatch, not per-context. This means `inject_resources()` can stay in worker context (connection held open) after injecting, shell out via `!` to a separate `xce_test` client-mode process for the controller query, and only `quit` at the very end — fully closing bug-1579 (not just working around it in the default set) rather than needing a C-level `xce_test` change. Plan: retrofit this into `inject_resources()`/`query_controller_resvals()` as a follow-up before/alongside task 7.1, then restore a host-attrs resource (e.g. `cpuf`) to `DEFAULT_RESOURCE_ARGS` to prove it. +- Minor non-blocking follow-up from task 6.3's review: `poll_scheduler_log()`'s output isn't filtered to the caller's `pending` list (harmless today since the only caller already filters, but worth tightening). - Task 6.2 (round 1 REJECTED, round 2 fixed) discovered **bug-1579**: any host-attrs-derived resource (`type`/`model`/`cpuf`/`maxcpus`/`maxmem`/`maxswap`/`maxtmp`/`ndisks` — `worker.c`'s `N_HOST_ATTRS`) gets reset to baseline by the controller the instant the synthetic worker disconnects, and `inject_resources()` (6.1) always disconnects (`quit`) before each layer's separate check session runs — so a controller-layer check on any host-attrs name will ALWAYS false-MISMATCH under the current two-session structure. Fixed for the default set by swapping `DEFAULT_RESOURCE_ARGS`'s `cpuf` for `r1m` (periodic/dynamic, confirmed safe). **This risk is NOT fully closed** — a user-supplied custom `resource=value` argument using any host-attrs name will still hit this. A real fix requires either a C-level `xce_test` change (its REPL has no path from the `worker` context to the `client` context without a disconnect-equivalent `leave_ctx()`) or a bash coprocess restructuring to keep the worker connected across all layer checks — out of scope for tasks 6.1-6.4, worth a dedicated follow-up task if host-attrs resources ever need default-set coverage. - Task 6.1 uncovered and got fixed a critical, unrelated, pre-existing controller bug (**bug-1578**, commit `b406dd7`, standalone — a dangling-pointer use-after-free in `sched_worker_change()`/`sched.c` that crashed the controller on worker disconnect once a scheduler had ever joined, 5 months old, unrelated to this feature). It's fixed now with regression coverage (`test_sched_worker_change.c`). If any later task sees a live controller die unexpectedly during a worker-disconnect sequence, confirm you're building from a commit that includes `b406dd7` before assuming it's a new bug. `inject_resources()` also fixed **bug-1577** (in-boundary): `XCE_WORKER_BIN=/bin/true` is exported before invoking `start-all.sh` to suppress the REAL `xcecd_virtual` worker daemon that `deploy-ha.sh`'s pre-existing worker branch would otherwise silently start (Requirement 2.1 violation) whenever the build dir happens to contain one. - Task 6.1: injection results are stored in `INJECTED_VALUES`/`INJECTED_RESULTS` associative arrays plus `$TOP/logs/injection-results.tsv` (`name\tvalue\tresult`) for tasks 6.2-6.4's extension points, which are appended directly after `inject_resources()` in `main()` (explicit "Extension point" comments mark exactly where). `SKILL.md` is now stale (still says injection "not yet implemented", still illustrates `type` in the default set) — deliberately left unedited since task 6.1's CLI parsing shape didn't change; fix this in task 7.1 when SKILL.md is next touched.