lei.chen/myxce
1
0
Fork 1
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

docs(buglog): bug-1921 fixed

Browse source 
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-10-06 14:42:28 +00:00
parent 70d56a5df6
commit 77ca96ab63
Signed by untrusted user: rshen
GPG key ID: 80533536B0EB651C
2 changed files with 21 additions and 14 deletions
Download patch file Download diff file Expand all files Collapse all files

14
.wolf/buglog.json
View file

@ -17366,9 +17366,9 @@
},
{
"id": "bug-1921",
"status": "open",
"status_updated": "2026-10-05",
"status_note": "newly logged",
"status": "fixed",
"status_updated": "2026-10-06",
"status_note": "",
"component": "harness",
"severity": "wrong-result",
"timestamp": "2026-10-05T05:53:10Z",
@ -17376,8 +17376,8 @@
"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",
"root_cause": "Two defects in `xce_test`'s worker context (src/harness/test.c):\n1. Its request handlers (`handle_startjob` -> `run_job`, `handle_runtasks`, `handle_jobcontrol`) run as VTASK_IO tasks of the worker's own connection and called the synchronous notify RPCs directly (`xcecli_notify_jobstart`/`jobfail`/`taskstart`/`taskfail`/`jobchkpt`). Each waits for its reply (notifyAcked, bug-1741), and that reply is dispatched as another task of the same connection, which the vtask manager serialises behind the waiting handler. The call can only time out (-110), and the client then fails over through `xce_ctx_reconnect` (where bug-1917's quiesce hits its 2 s bound, since the caller's own task holds a reference).\n2. After any reconnect the worker session never joined again. The controller treats only the joined connection as a worker, so every later worker request (job rusage `update`, notifications) failed `get_ep_worker` (\"is not a worker\").",
"fix": "- New `src/harness/worker_notify.{c,h}`: a mutex-protected FIFO of worker notifications (`wn_defer`, `wn_drain`, `wn_pending`) and the re-join predicate `wn_need_rejoin(joined, joined_gen, cur_gen)`. A drain stops at the first failed send and keeps that notification and the rest for the next drain, so a job start is never lost.\n- `test.c`: the notify helpers (`notify_jobstart`, `notify_job_fail`, `notify_task_start`, `notify_task_fail`, and the checkpoint notify in `handle_jobcontrol`) queue the notification and schedule a one-shot flush on the worker's delay-manager thread instead of sending from the handler. `worker_house_keeping` drains the queue on every tick too (retry).\n- `cmd_join_worker` records a successful worker join (connection `reconnect_gen` via `xcecli_get_my_endpoint`, plus a copy of the join attributes). Before draining notifications and before each housekeeping round, `worker_ensure_joined` re-joins with the saved attributes when the connection generation changed.\n\nVerification:\n- Test: `test_worker_notify` (src/harness/testsuite/test_worker_notify.c, harness_unit_test): defer never sends; drain is FIFO with copied payloads; a failed send keeps it and the later ones for the next drain; fini frees what is left (LSan clean); `wn_need_rejoin` truth table. RED before the fix (module absent: link failure), GREEN after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK (harness suite includes test_worker_notify), Go tests ok (2026-10-06).\n- Live: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), one `xce_test` fake worker with a single `join`, 2026-10-06: the job started, the worker never failed over (no -110), all 3 rusage reports were accepted (0 \"is not a worker\"), and xcecli showed CPU_TIME 100 / MAX_MEM 200 / AVG_MEM 200 / CPU_EFFICIENCY 77.52% (before the fix: every report rejected, all zeros, unless the session joined a second time). Then the controller was killed and restarted: the worker printed \"host re-join ok (connection re-established)\", the restarted controller ran worker reconciliation for it (a worker join), logged no \"is not a worker\", and CPU_EFFICIENCY was recomputed to 38.61% (100 s over ~259 s), i.e. a post-restart report was accepted.",
"tags": [
"harness",
"worker",
@ -17388,7 +17388,9 @@
"bug-1917",
"bug-1736"
],
"fix_commits": [],
"fix_commits": [
"70d56a5d"
],
"record": ".wolf/bugs/bug-1921.md",
"gitea_issue": 345,
"gitea_synced_status": "open"

21
.wolf/bugs/bug-1921.md
View file

@ -1,8 +1,8 @@
---
id: "bug-1921"
status: "open"
status_updated: "2026-10-05"
status_note: "newly logged"
status: "fixed"
status_updated: "2026-10-06"
status_note: ""
component: "harness"
severity: "wrong-result"
timestamp: "2026-10-05T05:53:10Z"
@ -11,6 +11,7 @@ occurrences: 1
files: ["src/harness/test.c", "src/lib/xcectx.c"]
tags: ["harness", "worker", "reconnect", "rusage"]
related: ["bug-1917", "bug-1736"]
fix_commits: ["70d56a5d"]
gitea_issue: 345
gitea_synced_status: "open"
gitea_synced_hash: "3376844d91f7"
@ -52,15 +53,19 @@ In `xce_test`'s worker context, a job dispatched to the fake worker is started b
- Evidence: not kept (session scratchpad logs)
## Root cause
TODO: required for fixed/partial
Two defects in `xce_test`'s worker context (src/harness/test.c):
1. Its request handlers (`handle_startjob` -> `run_job`, `handle_runtasks`, `handle_jobcontrol`) run as VTASK_IO tasks of the worker's own connection and called the synchronous notify RPCs directly (`xcecli_notify_jobstart`/`jobfail`/`taskstart`/`taskfail`/`jobchkpt`). Each waits for its reply (notifyAcked, bug-1741), and that reply is dispatched as another task of the same connection, which the vtask manager serialises behind the waiting handler. The call can only time out (-110), and the client then fails over through `xce_ctx_reconnect` (where bug-1917's quiesce hits its 2 s bound, since the caller's own task holds a reference).
2. After any reconnect the worker session never joined again. The controller treats only the joined connection as a worker, so every later worker request (job rusage `update`, notifications) failed `get_ep_worker` ("is not a worker").
## Fix
TODO: required for fixed/partial
- New `src/harness/worker_notify.{c,h}`: a mutex-protected FIFO of worker notifications (`wn_defer`, `wn_drain`, `wn_pending`) and the re-join predicate `wn_need_rejoin(joined, joined_gen, cur_gen)`. A drain stops at the first failed send and keeps that notification and the rest for the next drain, so a job start is never lost.
- `test.c`: the notify helpers (`notify_jobstart`, `notify_job_fail`, `notify_task_start`, `notify_task_fail`, and the checkpoint notify in `handle_jobcontrol`) queue the notification and schedule a one-shot flush on the worker's delay-manager thread instead of sending from the handler. `worker_house_keeping` drains the queue on every tick too (retry).
- `cmd_join_worker` records a successful worker join (connection `reconnect_gen` via `xcecli_get_my_endpoint`, plus a copy of the join attributes). Before draining notifications and before each housekeeping round, `worker_ensure_joined` re-joins with the saved attributes when the connection generation changed.
## 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
- Test: `test_worker_notify` (src/harness/testsuite/test_worker_notify.c, harness_unit_test): defer never sends; drain is FIFO with copied payloads; a failed send keeps it and the later ones for the next drain; fini frees what is left (LSan clean); `wn_need_rejoin` truth table. RED before the fix (module absent: link failure), GREEN after.
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK (harness suite includes test_worker_notify), Go tests ok (2026-10-06).
- Live: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), one `xce_test` fake worker with a single `join`, 2026-10-06: the job started, the worker never failed over (no -110), all 3 rusage reports were accepted (0 "is not a worker"), and xcecli showed CPU_TIME 100 / MAX_MEM 200 / AVG_MEM 200 / CPU_EFFICIENCY 77.52% (before the fix: every report rejected, all zeros, unless the session joined a second time). Then the controller was killed and restarted: the worker printed "host re-join ok (connection re-established)", the restarted controller ran worker reconciliation for it (a worker join), logged no "is not a worker", and CPU_EFFICIENCY was recomputed to 38.61% (100 s over ~259 s), i.e. a post-restart report was accepted.
## References
- Related: none