diff --git a/.wolf/buglog.json b/.wolf/buglog.json index c8da18a7..428ed097 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -11445,7 +11445,7 @@ "error_message": "job CPU peak and efficiency usage fields are never computed\n\nPRIORITY: LOW -- display/reporting only, not consumed by any scheduling logic. Split 2026-08-30 from bug-1735 at user request: the 'statistics-only' half of that finding -- resource usage fields with no scheduling relevance, purely for operator-facing job accounting/reporting (bjobs -l/bhist-style views), as opposed to bug-1735's memory+CPU-time core, which is a prerequisite for future scheduling decisions. Worker (collect_job_rusages(), xcecd_cgroups.c) already measures and sends 'memory_swap' and 'tasks_current' per job, but the controller has NO field to receive them at all (xce_host_runusage_t only has cpu_time/mem_usage -- no swap or task-count field exists) -- these two are silently dropped entirely, not just misnamed. Separately, xce_job_runusage_t's peak/efficiency fields (peak_cpu_time, peak_cpu_duration, mem_efficiency, avg_cpu_efficiency, peak_cpu_efficiency) have no computation logic anywhere in the codebase (grepped) -- nothing populates them, ever, regardless of bug-1735's fix.", "file": "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)", "root_cause": "See bug-1735's root_cause for the full original investigation (resname-mismatch mechanism, environment-limitation note re: this session's sandbox having no real cgroup-backed worker to live-verify against) -- this entry covers only the subset of that finding split out as lower-priority. Unlike bug-1735's memory/cpu_time (which have existing-but-mismatched fields), memory_swap/tasks_current have NO receiving field in xce_host_runusage_t at all -- the worker's measurement is a complete dead end on the controller side, not a naming mismatch. The peak/efficiency fields (xce_job_runusage_t's own top-level fields) are simply never computed by anything, anywhere -- confirmed via grep, no partial implementation exists to build on.", - "fix": "(1) memory_swap/tasks_current and (2) peak_cpu_time-as-running-max -- 2026-08-30, 5c2c6664 (see git history).\n\n(3) 6df644e6, 2026-10-01: the remaining fields, with LSF bjobs -l definitions (chosen by the user). `update_job_cpu_stats()` (`src/controller/misc.c`), called by `update_job_rusages()` (`job.c`) after each report:\n- each host's `cpu_rate` = CPU-seconds gained / wall seconds since that host's previous report (`sample_time`); the job's cores = sum over its hosts. A report no later than the previous one, or with a CPU counter that went backwards, leaves the rate alone.\n- `peak_cpu` = highest job cores seen; `peak_cpu_time` = it rounded (the wire field is Int32); `peak_cpu_duration` = the interval that set it. This replaces the earlier `peak_cpu_time` = running max of cumulative CPU seconds, which only duplicated `cpu_time`.\n- `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).\nNew 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.\n\nVerification:\n- 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\n- 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)\n- Live: n/a (no consumer displays these fields; the computation is unit-tested against the same report sequence update_job_rusages() applies)", + "fix": "(1) memory_swap/tasks_current and (2) peak_cpu_time-as-running-max -- 2026-08-30, 5c2c6664 (see git history).\n\n(3) 6df644e6, 2026-10-01: the remaining fields, with LSF bjobs -l definitions (chosen by the user). `update_job_cpu_stats()` (`src/controller/misc.c`), called by `update_job_rusages()` (`job.c`) after each report:\n- each host's `cpu_rate` = CPU-seconds gained / wall seconds since that host's previous report (`sample_time`); the job's cores = sum over its hosts. A report no later than the previous one, or with a CPU counter that went backwards, leaves the rate alone.\n- `peak_cpu` = highest job cores seen; `peak_cpu_time` = it rounded (the wire field is Int32); `peak_cpu_duration` = the interval that set it. This replaces the earlier `peak_cpu_time` = running max of cumulative CPU seconds, which only duplicated `cpu_time`.\n- `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).\nNew 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.\n\nUPDATE (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.\n\nVerification:\n- 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\n- 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)\n- Live: n/a (no consumer displays these fields; the computation is unit-tested against the same report sequence update_job_rusages() applies)\n\nUPDATE (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.\n\nUPDATE (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.", "tags": [ "worker", "controller", @@ -11468,7 +11468,8 @@ ], "fix_commits": [ "5c2c6664", - "6df644e6" + "6df644e6", + "1cedd7f7" ], "record": ".wolf/bugs/bug-1736.md" }, @@ -17256,7 +17257,7 @@ "error_message": "xce_ctx_reconnect re-inits the endpoint on the caller thread while the io_worker may still use it\n\n**Observed:**\nNot yet observed as a crash -- found by code review while fixing bug-1916. `xce_ctx_reconnect` (src/lib/xcectx.c ~366) calls `endpoint_fini` / `endpoint_init` on the client's caller thread for an endpoint embedded in the context, while the io_worker may still be dispatching the same endpoint (still monitored). Exposed operations: the io_worker's post-handler store into `ep->fsm_in.pkt` and `endpoint_unref` (harmless after the bug-1916 fix), a concurrent `SSL_read` / `handle_error` on the old fd/SSL against `SSL_free` / `close`, and `fsm_out.pkt` freed while `handle_output` is writing it. `vtask_entry` also reads `ep->owner` without a lock while reconnect rewrites it.\n\n**Expected:** reconnect first unmonitors the old endpoint and waits for the io_worker to finish any in-flight dispatch on it (quiesce), then tears it down, as the controller side does with deferred per-endpoint teardown (bug-1839).\n**Impact:** potential use-after-free / crash in OpenSSL or `handle_output` stacks under `xce_ctx_reconnect` during client failover (worker, scheduler, xce_test, apiserver backend), most likely under heavy CPU load, like bug-1916.\n**Found by:** review (bug-1916 fix, 2026-10-03)\n\nUPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazard: a reply task from the OLD connection still queued when xce_ctx_reconnect re-arms ep->owner can run against the NEW session (ep->owner read unsynchronised in xcectx.c vtask_entry ~134-135).", "file": "src/lib/xcectx.c, src/lib/netio.c", "root_cause": "`xce_ctx_reconnect` (src/lib/xcectx.c) ran `endpoint_fini`/`endpoint_init` on `ctx->ep` straight away, while work dispatched for the old connection could still be running: the io_worker inside its epoll batch (it holds an endpoint reference for the whole batch: `SSL_read`/`handle_output` on the fd and SSL being freed), and VTASK_IO reply tasks still queued on the context's pool (each holds a reference and reads `ep->owner` without a lock). A queued reply task of the old connection that ran after the reconnect found `ep->owner` re-armed to the context and was delivered to the new session.", - "fix": "`xce_ctx_reconnect` first calls `xce_ctx_quiesce_ep`: unmonitor the old fd (no further io_worker events), clear `ep->owner` under `ep->lock` (stale reply tasks are dropped; `vtask_entry` frees their packet), then wait until the endpoint's reference count is back at its base value (0 for the embedded client endpoint, 1 for a heap one), polling every 1 ms. The wait is bounded at 2000 ms: if the caller is itself a task of this endpoint its own reference never drains, and the reconnect then proceeds as before with a WARN (\"reconnecting anyway\") rather than deadlocking. `vtask_entry` now reads `ep->owner` under `ep->lock`.\n\nVerification:\n- Test: `test_reconnect_drains_old_connection_tasks` (new src/lib/testsuite/test_ctx_reconnect_quiesce.c): reconnect to a local listener, queue an old-connection packet via INVOKE_MSG_HANDLER -> handle_msg with the pool stopped, reconnect again while a helper starts the pool 100 ms in. RED before the fix (the stale task reached the context's request handler: expected 0 calls, was 1), GREEN and LSan-clean after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- 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).", + "fix": "`xce_ctx_reconnect` first calls `xce_ctx_quiesce_ep`: unmonitor the old fd (no further io_worker events), clear `ep->owner` under `ep->lock` (stale reply tasks are dropped; `vtask_entry` frees their packet), then wait until the endpoint's reference count is back at its base value (0 for the embedded client endpoint, 1 for a heap one), polling every 1 ms. The wait is bounded at 2000 ms: if the caller is itself a task of this endpoint its own reference never drains, and the reconnect then proceeds as before with a WARN (\"reconnecting anyway\") rather than deadlocking. `vtask_entry` now reads `ep->owner` under `ep->lock`.\n\nVerification:\n- Test: `test_reconnect_drains_old_connection_tasks` (new src/lib/testsuite/test_ctx_reconnect_quiesce.c): reconnect to a local listener, queue an old-connection packet via INVOKE_MSG_HANDLER -> handle_msg with the pool stopped, reconnect again while a helper starts the pool 100 ms in. RED before the fix (the stale task reached the context's request handler: expected 0 calls, was 1), GREEN and LSan-clean after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- 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).\n\nUPDATE (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.", "tags": [ "race", "failover", @@ -17360,6 +17361,33 @@ "record": ".wolf/bugs/bug-1920.md", "gitea_issue": 340, "gitea_synced_status": "fixed" + }, + { + "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, + "error_message": "xce_test fake worker: startjob handler sync-RPC times out, reconnect drops its worker role\n\n**Observed:**\n```\nxce_test (worker session):\n WARN xce_ctx_quiesce_ep: xce_ctx_reconnect: old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway\n INFO xcecli_retry_next: xcecli failover: attempt 1 -> localhost:9991 (after status=-110)\ncontroller:\n server sock 4 accepted 11 <- new connection, no join on it\n myreq_handler opcode update <- the fake worker's job rusage report\n ERROR get_ep_worker: endpoint 0x7d1ff5c06ec0 is not a worker\n```\nIn `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.\n\n**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.\n**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).\n**Found by:** test (bug-1736 live E2E, 2026-10-05)", + "file": "src/harness/test.c, src/lib/xcectx.c", + "root_cause": "TODO: required for fixed/partial", + "fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "tags": [ + "harness", + "worker", + "reconnect", + "rusage" + ], + "related_bugs": [ + "bug-1917", + "bug-1736" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1921.md" } ] } diff --git a/.wolf/bugs/bug-1736.md b/.wolf/bugs/bug-1736.md index 52b92ba4..f5106823 100644 --- a/.wolf/bugs/bug-1736.md +++ b/.wolf/bugs/bug-1736.md @@ -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 diff --git a/.wolf/bugs/bug-1917.md b/.wolf/bugs/bug-1917.md index 6db20afd..1598ff10 100644 --- a/.wolf/bugs/bug-1917.md +++ b/.wolf/bugs/bug-1917.md @@ -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 diff --git a/.wolf/bugs/bug-1921.md b/.wolf/bugs/bug-1921.md new file mode 100644 index 00000000..ac63ad18 --- /dev/null +++ b/.wolf/bugs/bug-1921.md @@ -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 ` +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 -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