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

chore(buglog): bug-1765 fixed (0f4d23e3); log bug-1894 (kill right after submit: not found)

Browse source 
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-09-30 04:14:19 +00:00
parent 0f4d23e3cd
commit 3e6c48a1fe
Signed by untrusted user: rshen
GPG key ID: 80533536B0EB651C
3 changed files with 171 additions and 20 deletions
Download patch file Download diff file Expand all files Collapse all files

99
.wolf/buglog.json
View file

@ -12400,18 +12400,18 @@
},
{
"id": "bug-1765",
"status": "open",
"status_updated": "2026-09-24",
"status_note": "frontend tests/regression/run.sh jobid regex rejects dashed jobid format",
"component": "unknown",
"severity": "unknown",
"status": "fixed",
"status_updated": "2026-09-30",
"status_note": "",
"component": "xcecli",
"severity": "wrong-result",
"timestamp": "2026-09-03T14:51:54Z",
"last_seen": "2026-09-19T09:00:00Z",
"occurrences": 1,
"error_message": "tests/regression/run.sh's 'jobs submit' test FAILs deterministically (28 passed / 1 failed / 1…\n\ntests/regression/run.sh's 'jobs submit' test FAILs deterministically (28 passed / 1 failed / 1 skipped instead of 29/0/0), with the cascading 'jobs kill' test SKIPped as a result -- reproduced identically regardless of which build system (Makefile vs Meson) produced the xcecli binary under test, confirming it predates and is unrelated to the eliminate-frontend-makefile migration.",
"file": "",
"error_message": "tests/regression/run.sh's 'jobs submit' test FAILs deterministically (28 passed / 1 failed / 1…\n\ntests/regression/run.sh's 'jobs submit' test FAILs deterministically (28 passed / 1 failed / 1 skipped instead of 29/0/0), with the cascading 'jobs kill' test SKIPped as a result -- reproduced identically regardless of which build system (Makefile vs Meson) produced the xcecli binary under test, confirming it predates and is unrelated to the eliminate-frontend-makefile migration.\n\nUPDATE (2026-09-29): also found while reproducing: run from a shell whose stdin is an open pipe (a background job, CI), the suite hangs forever at `jobs submit`, because xcecli's submit reads a job script from stdin whenever stdin is a pipe (src/frontend/xcecli/cmd/jobs/submit.go:96).",
"file": "src/frontend/tests/regression/run.sh",
"root_cause": "CONFIRMED via source + git history. src/frontend/apiserver/controllers/jobs.go:1518 formats the submit-response message with a plain-digit '%d' placeholder ('Job <%d> is submitted...'), but src/frontend/xcecli/cmd/jobs/submit.go:500 post-processes that message client-side, replacing the '<%d>' substring via format.FormatJobID() (src/frontend/xcecli/common/format/jobid.go:40-57), which renders the packed 64-bit job ID as the dashed '{cluster}-{apiserver}-{timestamp}-{sequence}' form (e.g. '1-0-1788446837-0'). tests/regression/run.sh:143's assertion regex ('Job <[0-9]+> is submitted') was never updated for this dashed format. The CLI-side reformatting was introduced by commit d6008ead ('improve frontend jobid display', 2026-05-07) -- nearly four months before this discovery -- so the test has been silently broken (as a false FAIL, not a false PASS) since then, not a new regression.",
"fix": "NOT FIXED -- out of scope for the eliminate-frontend-makefile spec's task 3.5 (pure verification task, no file changes permitted). Fix would be updating run.sh:143's regex to accept the dashed job-ID format (e.g. 'Job <[0-9-]+> is submitted' or delegating to the same format.FormatJobID() pattern). A second, independent, lower-severity issue was found in the same file during this investigation: run.sh:155's assert_not_contains 'jobs list submit_time not dash' calls grep -qF \"- \" without a '--' separator, so GNU grep treats the leading-dash argument as an invalid option and errors out -- this coincidentally still yields the intended PASS (grep's error-exit is indistinguishable here from 'no match'), so it doesn't affect reported counts, but isn't actually testing what it appears to test.",
"fix": "src/frontend/tests/regression/run.sh: the submit check matches the dashed ID (`Job <[0-9]+(-[0-9]+){3}> is submitted`) and extracts the whole ID from between the angle brackets (the old `[0-9]{10,}` would have taken only the timestamp field), which `jobs kill` parses back (format.ParseJobID). The submit command reads `</dev/null` so it never waits on an inherited pipe.\n\nVerification:\n- Test: the suite itself -- before: 28 passed / 1 failed / 1 skipped (and a hang with piped stdin); after: 30 passed / 0 failed / 0 skipped, both with stdin from /dev/null and with stdin an open pipe (`sleep 400 | ...`), against the same live cluster\n- Suites: n/a -- test-script-only change; `bash -n` clean\n- Live: manual check that the extracted ID is the job's real ID: `jobs list -u all` shows `1-0-1790741567-0 ... kcheck`, and `jobs kill 1-0-1790741567-0` answers `is being <kill>` (an immediate kill right after submit can briefly answer `not found` -- logged separately as bug-1894)",
"tags": [
"regression-suite",
"test-infra",
@ -12420,7 +12420,9 @@
"pre-existing"
],
"related_bugs": [],
"fix_commits": [],
"fix_commits": [
"0f4d23e3"
],
"record": ".wolf/bugs/bug-1765.md"
},
{
@ -16519,6 +16521,85 @@
"record": ".wolf/bugs/bug-1891.md",
"gitea_issue": 337,
"gitea_synced_status": "fixed"
},
{
"id": "bug-1892",
"status": "open",
"status_updated": "2026-09-30",
"status_note": "newly logged",
"component": "scheduler",
"severity": "wrong-result",
"timestamp": "2026-09-30T03:58:52Z",
"last_seen": "2026-09-30T03:58:52Z",
"occurrences": 1,
"error_message": "xce_scheduler admission check reads per-resource uncommitted amounts by list position, not index\n\n**Observed:** found by code reading, so there is no failing run yet. `unsatisfy_()` (`src/scheduler/src/resource.c:130-169`) compares\n```c\nif (total[i] < inuse[i] + uncomitted[i] + wanted[i])\n```\nwhere `total`, `inuse` and `wanted` are *positional* arrays (entry `i` is the\n`i`-th resource of the request, gathered by `get_resvals(..., wanted->idxs, ...)`),\nbut `uncomitted` is the context's *dense, resource-index-keyed* vector\n(`ctx->uncomitted.shared` / `ctx->uncomitted.hosts[w]`, 1024 floats,\n`schedobj.c:514/595`), filled by `xvec_idval(uncomit, &req, XVEC_ADD_FLOAT)`,\nwhich writes `d[idx] += val` (`lib/xvec.c`, `DEFINE_XVEC_IDVAL_OP`). Both\n`sched_check_shared_satisfy_()` (`resource.c:309`) and\n`sched_check_host_satisfy_()` (`resource.c:376`) pass `uncomitted->data`\nstraight through, so entry `i` reads the uncommitted amount of resource index\n`i`, not of resource `wanted->idxs[i]`.\n\n**Expected:** entry `i` uses `uncomitted[wanted->idxs[i]]` (gather it\npositionally like `total`/`inuse`, e.g. with the existing `get_resvals()`).\n\n**Impact:** wrong admission result. Uncommitted amounts are nonzero only\nwithin one allocation context that already committed something, i.e. from the\nsecond primary of a COMPOUND (or ALTER) job on, since those primaries share one\n`ctx` (`scheduler.c:348-354`); the first primary and ordinary PRIMARY jobs\nalways see all-zero uncommitted vectors, and parjob rolls back failed plans.\nFor a later primary, the check subtracts an unrelated resource's uncommitted\namount (or 0) instead of the earlier primaries' real claim on the same\nresource, so it can over-admit (earlier primary's claim ignored: the job is\ndispatched beyond host/shared capacity) or wrongly pend (another resource's\namount charged). Pend reasons printed for the same check carry the wrong\nshortfall.\n\n**Found by:** review of the `scheduler-allocator-runner` requirements\n(2026-09-29), while checking the shared-resource precheck the runner inherits.",
"file": "src/scheduler/src/resource.c, src/lib/xvec.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": [
"scheduler",
"allocation",
"compound",
"code-review"
],
"related_bugs": [
"bug-1893"
],
"fix_commits": [],
"record": ".wolf/bugs/bug-1892.md"
},
{
"id": "bug-1893",
"status": "open",
"status_updated": "2026-09-30",
"status_note": "newly logged",
"component": "scheduler",
"severity": "wrong-result",
"timestamp": "2026-09-30T03:58:52Z",
"last_seen": "2026-09-30T03:58:52Z",
"occurrences": 1,
"error_message": "xce_scheduler allocators add spurious resource-0 shared pend reasons (loop reads past unmet list)\n\n**Observed:** found by code reading, so there is no failing run yet. When the shared-resource check\nfails, both allocators add the pend reasons with\n```c\nfor (i = 0; i < ctx->alloc_req.shared.count; i++) {\n rc = vget(core->resmgr, ((int*)ctx->unmeet.idxs.data)[i], (void**)&r);\n if (rc <= 0) continue;\n add_job_preason(reason->reasons, PREASON_NO_RESOURCE, NULL, r->name);\n}\n```\n(`seqjob_allocator.c` `my_alloc`, `parjob_allocator.c` `my_alloc`). The loop\nbound is the number of *requested* shared resources, but `ctx->unmeet` holds\nonly the *unmet* ones, packed at `[0, unmeet.count)` by `unsatisfy_()`\n(`resource.c:152-165`). Its arrays were `calloc`ed with capacity\n`shared.count` (`resource.c:280`), so entries `[unmeet.count, shared.count)`\nare 0.\n\n**Expected:** iterate `i < ctx->unmeet.count` (as the host path does,\n`resource.c:566`), giving one `NO_RESOURCE` reason per unmet shared resource.\n\n**Impact:** wrong pend reason, noise level. When a job requests N shared\nresources and only M < N are unmet, the loop adds N - M extra\n`PREASON_NO_RESOURCE` reasons naming whatever resource has index 0 (if one\nexists), which that job may never have requested. Main reason and allocation\ndecision are unaffected. No out-of-bounds memory access (the tail is inside the\nallocation).\n\n**Found by:** review of the `scheduler-allocator-runner` requirements\n(2026-09-29); the loop moves into the framework runner in that spec.",
"file": "src/scheduler/src/plugins/seqjob_allocator.c, src/scheduler/src/plugins/parjob_allocator.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": [
"scheduler",
"allocation",
"preason",
"code-review"
],
"related_bugs": [
"bug-1892"
],
"fix_commits": [],
"record": ".wolf/bugs/bug-1893.md"
},
{
"id": "bug-1894",
"status": "open",
"status_updated": "2026-09-30",
"status_note": "newly logged",
"component": "apiserver",
"severity": "wrong-result",
"timestamp": "2026-09-30T04:14:02Z",
"last_seen": "2026-09-30T04:14:02Z",
"occurrences": 1,
"error_message": "xce_apiserver: jobs kill right after jobs submit can answer 'job not found' for the accepted job\n\n**Observed:** `xcecli jobs kill <id>` issued right after `jobs submit` returned that ID can answer that the job does not exist; retried moments later, the same kill succeeds:\n```\nJob <1-0-1790741567-0> is submitted to default queue <normal>.\njob <1-0-1790741567-0> not found\n... (seconds later)\njob <1-0-1790741567-0> is being <kill>\n```\n**Expected:** once submit has returned a job ID, operations on that ID see the job.\n**Impact:** minor -- a script that submits and immediately controls a job gets a spurious `not found`; the job itself is fine and appears in `jobs list` under the same ID.\n**Found by:** manual check while verifying bug-1765's regression-suite fix, 2026-09-29. Suspected (not verified): the apiserver learns of a new job through the controller's asynchronous job notification (OnJobCreated) rather than from the submit reply, so its job store lags the submit acknowledgement by up to a notification round-trip.",
"file": "src/frontend/apiserver/controllers/jobs.go (job kill lookup)",
"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": [
"apiserver",
"jobs",
"kill",
"consistency",
"latency"
],
"related_bugs": [
"bug-1765"
],
"fix_commits": [],
"record": ".wolf/bugs/bug-1894.md"
}
]
}

36
.wolf/bugs/bug-1765.md
View file

@ -1,16 +1,17 @@
---
id: "bug-1765"
status: "open"
status_updated: "2026-09-24"
status_note: "frontend tests/regression/run.sh jobid regex rejects dashed jobid format"
component: "unknown"
severity: "unknown"
status: "fixed"
status_updated: "2026-09-30"
status_note: ""
component: "xcecli"
severity: "wrong-result"
timestamp: "2026-09-03T14:51:54Z"
last_seen: "2026-09-19T09:00:00Z"
occurrences: 1
files: []
files: ["src/frontend/tests/regression/run.sh"]
tags: ["regression-suite", "test-infra", "jobid-format", "false-fail", "pre-existing"]
related: []
fix_commits: ["0f4d23e3"]
legacy: true
---
@ -19,20 +20,33 @@ legacy: true
## Description
tests/regression/run.sh's 'jobs submit' test FAILs deterministically (28 passed / 1 failed / 1 skipped instead of 29/0/0), with the cascading 'jobs kill' test SKIPped as a result -- reproduced identically regardless of which build system (Makefile vs Meson) produced the xcecli binary under test, confirming it predates and is unrelated to the eliminate-frontend-makefile migration.
UPDATE (2026-09-29): also found while reproducing: run from a shell whose stdin is an open pipe (a background job, CI), the suite hangs forever at `jobs submit`, because xcecli's submit reads a job script from stdin whenever stdin is a pipe (src/frontend/xcecli/cmd/jobs/submit.go:96).
## Environment
_Not recorded (migrated from buglog.json)._
- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64
- libc: glibc 2.42-47 for the controller (nix dev shell); xcecli/xce_apiserver are Go binaries built by meson (go_build)
- Toolchain: go (nix dev shell), gcc (GCC) 15.2.0, meson 1.9.1
- Build: asan (src/xce.build.bug1871: controller, scheduler, worker, xceadmin, apiserver, xcecli)
- Code: reproduced 2026-09-29 at f5c887dc+
- Deployment: local 3-node HA controller cluster + xcecd_virtual worker + scheduler + apiserver on :8080 (deploy-ha.sh + start-all.sh, /home/claude/tmp/xce-1765), config_file auth (admin/admin)
## Reproduction
_Not recorded (migrated from buglog.json)._
1. Deploy a cluster with an apiserver: `bash src/tools/deploy-ha.sh <builddir>/controller/xce_controller <top> localhost:9991,localhost:9992,localhost:9993 && bash <top>/scripts/start-all.sh`
2. `XCE=<builddir>/frontend/xcecli/xcecli URL=http://localhost:8080 bash src/frontend/tests/regression/run.sh </dev/null`
- Frequency: deterministic -- 1/1, 2026-09-29: `FAIL jobs submit — unexpected output: Job <1-0-1790741130-0> is submitted to default queue <normal>.`, `SKIP jobs kill`, `Results: 28 passed 1 failed 1 skipped`; without `</dev/null` from a piped shell it hung at `xcecli jobs submit` for 10+ min
- Evidence: /home/claude/tmp/xce-1765 (deploy dir, logs/apiserver.log)
## Root cause
CONFIRMED via source + git history. src/frontend/apiserver/controllers/jobs.go:1518 formats the submit-response message with a plain-digit '%d' placeholder ('Job <%d> is submitted...'), but src/frontend/xcecli/cmd/jobs/submit.go:500 post-processes that message client-side, replacing the '<%d>' substring via format.FormatJobID() (src/frontend/xcecli/common/format/jobid.go:40-57), which renders the packed 64-bit job ID as the dashed '{cluster}-{apiserver}-{timestamp}-{sequence}' form (e.g. '1-0-1788446837-0'). tests/regression/run.sh:143's assertion regex ('Job <[0-9]+> is submitted') was never updated for this dashed format. The CLI-side reformatting was introduced by commit d6008ead ('improve frontend jobid display', 2026-05-07) -- nearly four months before this discovery -- so the test has been silently broken (as a false FAIL, not a false PASS) since then, not a new regression.
## Fix
NOT FIXED -- out of scope for the eliminate-frontend-makefile spec's task 3.5 (pure verification task, no file changes permitted). Fix would be updating run.sh:143's regex to accept the dashed job-ID format (e.g. 'Job <[0-9-]+> is submitted' or delegating to the same format.FormatJobID() pattern). A second, independent, lower-severity issue was found in the same file during this investigation: run.sh:155's assert_not_contains 'jobs list submit_time not dash' calls grep -qF "- " without a '--' separator, so GNU grep treats the leading-dash argument as an invalid option and errors out -- this coincidentally still yields the intended PASS (grep's error-exit is indistinguishable here from 'no match'), so it doesn't affect reported counts, but isn't actually testing what it appears to test.
src/frontend/tests/regression/run.sh: the submit check matches the dashed ID (`Job <[0-9]+(-[0-9]+){3}> is submitted`) and extracts the whole ID from between the angle brackets (the old `[0-9]{10,}` would have taken only the timestamp field), which `jobs kill` parses back (format.ParseJobID). The submit command reads `</dev/null` so it never waits on an inherited pipe.
## Verification
_Not recorded (migrated from buglog.json)._
- Test: the suite itself -- before: 28 passed / 1 failed / 1 skipped (and a hang with piped stdin); after: 30 passed / 0 failed / 0 skipped, both with stdin from /dev/null and with stdin an open pipe (`sleep 400 | ...`), against the same live cluster
- Suites: n/a -- test-script-only change; `bash -n` clean
- Live: manual check that the extracted ID is the job's real ID: `jobs list -u all` shows `1-0-1790741567-0 ... kcheck`, and `jobs kill 1-0-1790741567-0` answers `is being <kill>` (an immediate kill right after submit can briefly answer `not found` -- logged separately as bug-1894)
## References
_Not recorded (migrated from buglog.json)._
- Fix commit: 0f4d23e3
- Related: d6008ead (dashed job-ID display), bug-1894 (submit-to-visible lag)

56
.wolf/bugs/bug-1894.md Normal file
View file

@ -0,0 +1,56 @@
---
id: "bug-1894"
status: "open"
status_updated: "2026-09-30"
status_note: "newly logged"
component: "apiserver"
severity: "wrong-result"
timestamp: "2026-09-30T04:14:02Z"
last_seen: "2026-09-30T04:14:02Z"
occurrences: 1
files: ["src/frontend/apiserver/controllers/jobs.go (job kill lookup)"]
tags: ["apiserver", "jobs", "kill", "consistency", "latency"]
related: ["bug-1765"]
---
# bug-1894: xce_apiserver: jobs kill right after jobs submit can answer 'job not found' for the accepted job
## Description
**Observed:** `xcecli jobs kill <id>` issued right after `jobs submit` returned that ID can answer that the job does not exist; retried moments later, the same kill succeeds:
```
Job <1-0-1790741567-0> is submitted to default queue <normal>.
job <1-0-1790741567-0> not found
... (seconds later)
job <1-0-1790741567-0> is being <kill>
```
**Expected:** once submit has returned a job ID, operations on that ID see the job.
**Impact:** minor -- a script that submits and immediately controls a job gets a spurious `not found`; the job itself is fine and appears in `jobs list` under the same ID.
**Found by:** manual check while verifying bug-1765's regression-suite fix, 2026-09-29. Suspected (not verified): the apiserver learns of a new job through the controller's asynchronous job notification (OnJobCreated) rather than from the submit reply, so its job store lags the submit acknowledgement by up to a notification round-trip.
## 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 @ 0f4d23e3-dirty
- Deployment: local 3-node HA controller cluster + xcecd_virtual worker + scheduler + apiserver on :8080 (deploy-ha.sh + start-all.sh), config_file auth
## Reproduction
1. Deploy a cluster with an apiserver (deploy-ha.sh + scripts/start-all.sh) and `xcecli login -u admin -p admin --url http://localhost:8080`
2. `id=$(xcecli jobs submit -q normal sleep 300 </dev/null | sed -nE 's/.*Job <([^>]+)>.*/\1/p'); xcecli jobs kill "$id"`
- Frequency: 2/4 immediate kills answered `not found`, 2026-09-29 (the lag measured 0.01-0.22 s in three timed tries)
- Evidence: /home/claude/tmp/xce-1765/logs/apiserver.log (21:12:47 query for job_id 73935322667286528)
## 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