docs(buglog): bug-1736 exposed to apiserver/xcecli; log bug-1921
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
1cedd7f791
commit
07d81fc5bc
GPG key ID:
80533536B0EB651C
4 changed files with 103 additions and 4 deletions
File diff suppressed because one or more lines are too long
|
|
@ -11,7 +11,7 @@ occurrences: 1
|
|||
files: ["src/worker/src/xcecd_cgroups.c (collect_job_rusages -- already sends memory_swap/tasks_current", "no controller-side field to receive them)", "src/include/xce/types.h (xce_host_runusage_t -- would need new fields for swap/task-count; xce_job_runusage_t -- the peak/efficiency fields with no producer)", "src/controller/misc.c (update_host_runusage -- would need new parse branches)", "src/controller/job.c (update_job_rusages -- same open FIXME as bug-1735", "this is the other half of what it would need to cover)"]
|
||||
tags: ["worker", "controller", "resource-usage", "rusage", "display-only", "reporting-only", "priority-low", "split-2026-08-30", "no-scheduling-impact", "static-analysis-only", "unreproduced-in-sandbox", "needs-design-not-just-fix", "peak-cpu-time-fixed", "swap-taskcount-fixed", "efficiency-fields-remain-scope-decision"]
|
||||
related: ["bug-1735"]
|
||||
fix_commits: ["5c2c6664", "6df644e6"]
|
||||
fix_commits: ["5c2c6664", "6df644e6", "1cedd7f7"]
|
||||
legacy: true
|
||||
---
|
||||
|
||||
|
|
@ -38,10 +38,16 @@ See bug-1735's root_cause for the full original investigation (resname-mismatch
|
|||
- `avg_cpu_efficiency` = cpu_time / elapsed since start / allocated slots; `peak_cpu_efficiency` = peak_cpu / slots; `mem_efficiency` = highest used_mem / the job-wide `rusage[mem]` request (`calc_wanted_job_total_resval`, per task by default, as the scheduler reserves it); all in percent, as the apiserver/xcecli models document; 0 when there is no slot count or no memory request (or the request is not a single primary one).
|
||||
New persisted fields `HostRunusage.sampleTime`/`cpuRate` and `JobRunusage.peakCpu` are appended to `controller.capnp` (old WAL entries still decode) and copied by `merge_job_runusage()`. The values are controller-side only: the apiserver does not map run usage into its job model and xcecli/harness do not display these fields.
|
||||
|
||||
UPDATE (2026-10-05): Exposed to the apiserver and xcecli (2026-10-05): the capnp Job struct gains runUsage @13 (JobRunusage, mapped to xce_job_t.run_usage), so the job pushed to the apiserver on every update (update_job_rusages fires HOOK_DETAIL_JOB_UPDATE after recomputing the stats) carries the values. The same struct is the snapshot/WAL job format, so checkpoints now keep run_usage too (before, a job restored from a snapshot lost it: the WAL_JOB_RUSAGE facts behind the checkpoint are trimmed). Old entries decode with no run usage. apiserver: convert.go/convert_pure.go map run_usage into JobInfo, which gains max_mem/avg_mem/used_mem/peak_cpu/peak_cpu_time/peak_cpu_duration/mem_efficiency/avg_cpu_efficiency/peak_cpu_efficiency columns (moved out of the validation-only JobAdditionalFields; cpu_time was there but never set). xcecli: new -o fields MAX_MEM, AVG_MEM, MEM_EFFICIENCY, CPU_PEAK, CPU_PEAK_DURATION, CPU_EFFICIENCY, CPU_PEAK_EFFICIENCY (CPU_TIME now renders too; all printed '-' before), and jobs list -l prints an LSF bjobs -l style MEMORY USAGE / CPU USAGE block for started jobs.
|
||||
|
||||
## Verification
|
||||
- Test: `test_cpu_stats_*` (rate/peak/duration/efficiency, multi-host sum, mem efficiency as a peak, guards) and `test_aggregate_job_runusage_leaves_peak_cpu_alone` in `src/controller/testsuite/test_host_runusage.c` (11/11; written before `update_job_cpu_stats()` existed); WAL round trip of the new fields added to `test_wal_job_rusage_fact.c`, and the existing-host merge test `test_wru_apply_committed_entry_merges_without_freeing_live_host`: RED with the new `merge_job_runusage()` lines removed (`Expected 3.25 Was 0`), GREEN with them
|
||||
- Suites: controller_unit_test 1275/1275; `xce-build.sh all asan build.jai` 126/127 -- the one failure was the known intermittent harness pty timeout bug-1902 (recurrence recorded; 3/3 reruns pass)
|
||||
- Live: n/a (no consumer displays these fields; the computation is unit-tested against the same report sequence update_job_rusages() applies)
|
||||
|
||||
UPDATE (2026-10-05): Exposure (2026-10-05): test_snapent_checkpoint_run_usage_roundtrip (test_persist_snapshot_entities.c, every job- and host-level field through checkpoint frames and persist_load_snapshot; RED before: run_usage NULL), TestRawJobToModel_RunUsage / _NoRunUsage / TestJobInfoExposesRunUsageColumns (apiserver backend), TestJobResourceUsageLines_* / TestJobRunUsageColumn / TestJobFieldsMapIncludesRunUsage (xcecli output), all RED before. Field-completeness check (audit dimension 7, run_usage only): encoded by capnp_encode_job (snapshot) and WAL_JOB_RUSAGE; adopted by restore_job/job_init (MOVE_PTR) and both apply seams via merge_job_runusage. xce-build all asan: 127/127 + Go ok. Live: single controller + scheduler + apiserver (run-resource-verify.sh --keep-running), an xce_test fake worker reporting cpu_time_sec=100 / memory_rss=200 every 60 s: xcecli jobs list -o showed CPU_TIME 100, MAX_MEM 200, AVG_MEM 200, CPU_EFFICIENCY 50.00% (100 s over ~200 s elapsed, 1 slot), CPU_PEAK 0.00 (the fake counter is constant, so the rate is 0), MEM_EFFICIENCY 0.00% (no rusage[mem] request); jobs list -l printed the same in the MEMORY USAGE / CPU USAGE block.
|
||||
|
||||
UPDATE (2026-10-05): Format change under HA (2026-10-05): /xce-test-ha sequential 20 rounds PASS (zero job loss, all 3 nodes led, no ASAN, WAL segment layout clean); its virtual worker sends no usage reports, so those jobs carry a null runUsage -- the populated round trip is covered by test_snapent_checkpoint_run_usage_roundtrip.
|
||||
|
||||
## References
|
||||
- Related: bug-1735
|
||||
|
|
|
|||
|
|
@ -53,5 +53,7 @@ UPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazar
|
|||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).
|
||||
- Live: loaded `/xce-test-ha` sequential 30 rounds (40 busy loops on 32 cores), 2026-10-04: PASS, zero job loss, all 3 nodes led, no ASAN report in any controller/worker/scheduler log; client failover reconnects in worker/scheduler/xce_test throughout, and the quiesce never needed its timeout (no "reconnecting anyway" WARN).
|
||||
|
||||
UPDATE (2026-10-05): Live observation (2026-10-05, bug-1736 E2E): the xce_test fake worker hit the bounded-wait path -- a vtask handler of its own connection timed out waiting for a reply queued behind it (-110), failed over through xce_ctx_reconnect, and the quiesce logged 'old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway' and proceeded, as designed; no crash or ASAN report.
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
63
.wolf/bugs/bug-1921.md
Normal file
63
.wolf/bugs/bug-1921.md
Normal file
|
|
@ -0,0 +1,63 @@
|
|||
---
|
||||
id: "bug-1921"
|
||||
status: "open"
|
||||
status_updated: "2026-10-05"
|
||||
status_note: "newly logged"
|
||||
component: "harness"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-05T05:53:10Z"
|
||||
last_seen: "2026-10-05T05:53:10Z"
|
||||
occurrences: 1
|
||||
files: ["src/harness/test.c", "src/lib/xcectx.c"]
|
||||
tags: ["harness", "worker", "reconnect", "rusage"]
|
||||
related: ["bug-1917", "bug-1736"]
|
||||
---
|
||||
|
||||
# bug-1921: xce_test fake worker: startjob handler sync-RPC times out, reconnect drops its worker role
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
```
|
||||
xce_test (worker session):
|
||||
WARN xce_ctx_quiesce_ep: xce_ctx_reconnect: old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway
|
||||
INFO xcecli_retry_next: xcecli failover: attempt 1 -> localhost:9991 (after status=-110)
|
||||
controller:
|
||||
server sock 4 accepted 11 <- new connection, no join on it
|
||||
myreq_handler opcode update <- the fake worker's job rusage report
|
||||
ERROR get_ep_worker: endpoint 0x7d1ff5c06ec0 is not a worker
|
||||
```
|
||||
In `xce_test`'s worker context, a job dispatched to the fake worker is started by `handle_startjob`, which runs as a VTASK_IO task of the worker's own connection and makes a synchronous RPC (the start notify, answered with notifyAcked) on that same connection. The reply is queued as another task of that connection, behind the handler that waits for it, so the call times out (-110) and the client fails over through `xce_ctx_reconnect`. The fake worker never re-joins on the new connection, so the controller rejects all its later reports (`update`: job rusage) as coming from a non-worker endpoint.
|
||||
|
||||
**Expected:** the fake worker's start notify completes on its connection (the handler must not wait synchronously on a reply that can only be dispatched after it returns), and after any reconnect a worker-context session re-joins before sending worker requests.
|
||||
**Impact:** harness only: an `xce_test` fake worker loses its worker role ~10-12 s after its first job starts, so every job-usage report it sends afterwards is dropped (CPU time / memory / efficiency stay 0) and the job's later worker notifications are refused. Live run-usage checks need a manual second `join`. Real xcecd workers are not affected by this path (they do not start jobs from a connection vtask handler).
|
||||
**Found by:** test (bug-1736 live E2E, 2026-10-05)
|
||||
|
||||
## Environment
|
||||
- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64
|
||||
- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2)
|
||||
- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1
|
||||
- Build: asan (xce.build)
|
||||
- Code: scheduler-framework @ e2472aa7-dirty
|
||||
- Deployment: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), one `xce_test` fake worker
|
||||
|
||||
## Reproduction
|
||||
1. `bash .claude/skills/xce-test-resources/run-resource-verify.sh --keep-running --dir <D>`
|
||||
2. `printf 'set masters localhost:9991\nset myname fakew\nworker\njoin\n!sleep 200\nquit\n' | xce_test --norc &`
|
||||
3. Submit a long job from another session (`client`, `jobsub -u user1 -q normal -c "sleep 600"`); close other hosts with `hostctrl -h <host> -c -y` so it lands on fakew.
|
||||
4. /tmp/xce_test.log shows the -110 failover ~12 s after the start; the controller log shows `get_ep_worker ... is not a worker` for each later rusage report. Workaround: a second `join` in the worker session after the reconnect.
|
||||
- Frequency: deterministic, 3/3 runs, 2026-10-05
|
||||
- Evidence: not kept (session scratchpad logs)
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## Fix
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## Verification
|
||||
- Test: TODO: name + file; RED before the fix, GREEN after
|
||||
- Suites: TODO: suite results and build profile
|
||||
- Live: TODO: soak/deploy run, or n/a and why
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
Loading…
Add table
Add a link
Reference in a new issue