Rongsong Shen
d26ff8870d
The buglog was one 27K-line JSON file whose fields covered only symptom,
root cause and fix, as free text: 2% of entries named the code version a
bug was found on, 12% the build profile, 36% a way to reproduce, and 58% of
the file was OpenWolf hook auto-detections ("Missing guard clause",
"Function not marked async" on .md files).
- .claude/skills/buglog/bug-record.md: the record standard. Eight
sections (Summary as the title, Description, Environment, Reproduction;
Root cause, Fix, Verification, References once fixed), each with the
content it must contain -- e.g. Environment needs the OS, the libc the
failing binary loads (from its ELF interpreter: glibc 2.42 in the nix
shell vs 2.40 on the host), toolchain, build profile and commit.
- .wolf/bugs/<id>.md: 500 records migrated from buglog.json; every field
verified to round-trip. They carry legacy: true and an explicit "not
recorded" where the old log had no such field; component derived from
file paths, severity from keywords (else unknown), fix_commits from
hashes in status_note/fix that git resolves (91 of 463 fixed).
- .wolf/buglog-archive.json: the 710 hook auto-detections, verbatim.
- .wolf/buglog.json is now an index generated from the records, keeping
the fields OpenWolf's hooks and `openwolf bug search` read.
- scripts/buglog.py rewritten: new (template + Environment collected from
the machine and --binary), check, status (refuses a status the record
doesn't support; fixed needs Root cause, Fix, Verification and
--commit hashes git resolves), note, recur, set, show, list, triage,
env, index. 29 unittest cases in scripts/tests/test_buglog.py.
- scripts/git-hooks/pre-commit runs `check --staged`: incomplete staged
records, a legacy record hand-changed to fixed without the fix-time
sections, a new record claiming legacy: true, or a stale index refuse
the commit.
- scripts/gitea-sync.py reads the records: issue body = the record's
sections plus linked fix commits (origin remote, GITEA_COMMIT_REPO to
override), and a body hash so an issue's text is refreshed when the
record changes.
- bug-1866 rewritten to the full standard as the worked example.
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
10 KiB
| id | status | status_updated | status_note | component | severity | timestamp | last_seen | occurrences | files | tags | related | legacy | ||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| bug-1715 | fixed | 2026-09-24 | xceadmin | crash | 2026-08-26T18:45:00Z | 2026-09-19T09:00:00Z | 1 |
|
|
|
true |
bug-1715: User-reported, live 3-node cluster: xceadmin scheduler record status --controller localhost:9901…
Description
User-reported, live 3-node cluster: xceadmin scheduler record status --controller localhost:9901 failed once with Error: scheduler disconnected, then succeeded on the very next identical invocation moments later. Root-caused to a full cluster redeploy (user confirmed: 'This is a full rebuilt and re-deployed cluster') restarting all 5 processes (3 controllers + worker + scheduler) together -- PIDs across ctrl-1/ctrl-2/ctrl-3/scheduler/worker logs are all tightly clustered (4137667/4137684/4137696/4137745/4138046), confirming a coordinated restart, not an isolated scheduler crash. The request happened to land in the brief, normal window between the old scheduler disconnecting and the new one reconnecting.
Environment
Not recorded (migrated from buglog.json).
Reproduction
Not recorded (migrated from buglog.json).
Root cause
FULLY ROOT-CAUSED, same family as bug-1713 but NOT covered by that fix. 'scheduler disconnected' is delivered via a DIFFERENT signaling path than bug-1713's two numeric status codes: cluster.c's bug-1693 disconnect-detection mechanism (cluster.c:1052-1067) sends reply.status = 0 (success at the RPC level) with schedadminreplymsg{ok=false, error="scheduler disconnected"} -- a normal-status reply carrying a domain-level failure, not a nonzero reply.status the way E_XCE_NOT_READY/E_XCE_NOMASTER are. _send_admin_request() (scheduler.py:145-154) treats admin_reply.ok == False as an unconditional hard SchedAdminError for EVERY reason string, with no distinction between genuinely transient conditions ('scheduler disconnected', 'scheduler not connected', 'request timeout' -- all connection/timing related, expected to self-resolve within seconds, especially during a redeploy/restart cycle) and genuinely permanent domain errors ('not recording', 'already recording', 'invalid record file name' -- real error states that must NOT be retried, e.g. calling record-stop on an already-stopped recorder is a correct, meaningful rejection, not a transient hiccup).
Fix
FIXED and LIVE-VERIFIED (2026-08-26). Extended bug-1713's retry loop in _send_admin_request() (src/xceadmin/src/xceadmin/scheduler.py:158-249) to a SECOND, differently-signaled transient family: after decoding admin_reply = reply.data.schedadminreplymsg and finding admin_reply.ok == False, the code now checks admin_reply.error in _TRANSIENT_ADMIN_REASONS (new module-level frozenset, scheduler.py:114-160) and, if so and attempt < _MAX_TRANSIENT_ATTEMPTS, sleeps _TRANSIENT_RETRY_DELAY_S and continues the SAME for attempt in range(1, _MAX_TRANSIENT_ATTEMPTS+1) loop bug-1713 already added -- no second retry loop, same budget (4 attempts, 1.5s fixed delay), same re-run-follow_redirects()-from-scratch shape (a fresh attempt can discover a newly-reconnected scheduler, exactly like a fresh attempt can discover a newly-settled primary in bug-1713's case). On exhaustion, raises the same SchedAdminError shape with the reason string annotated '(still transient after N attempts over ~Xs -- giving up)', mirroring bug-1713's own distinguishable-message convention exactly. AUTHORITATIVE error-string list (grepped every literal sched_admin_reply_t/SchedAdminReply .error = "..." assignment across src/controller/ and src/scheduler/, then read each site's surrounding code, not just the string text): transient (all 4 now in _TRANSIENT_ADMIN_REASONS) -- "scheduler disconnected" (cluster.c:1062, bug-1693's disconnect-detection path), "scheduler not connected" (cluster.c:958, c->sched.ep==NULL), "request timeout" (cluster.c:1078, SCHEDADMIN_TIMEOUT_MS wait expired), and "server busy, try again" (cluster.c:937, vtaskmgr_blocking_acquire() admission-reservation exhaustion -- a 4th transient reason NOT in this bug's original three-string hypothesis, added after reading the admission-gate's own 'try again' design comment: resource contention that self-resolves as soon as another admitted vtask op completes, not a domain rejection). Permanent (left untouched, still raise on the very first attempt): "already recording"/"not recording" (driver.c:390/426, rc==-EALREADY) and validation_error_text()'s six filename/path-rejection strings (driver.c:298-316: "invalid record file name", "record directory not found", "record directory path is not a directory", "permission denied accessing record file", "a non-file entry with this name already exists", "record file path too long"), plus a dynamic (not a fixed literal, so it could never join an exact-match retry set anyway) "cannot write to %s: %s" I/O-failure message (driver.c:398-404). RED/GREEN proof (src/xceadmin/tests/test_scheduler.py): confirmed RED by temporarily reverting only the two bug-1715 edits back to bug-1713's exact shipped state (not via git stash, since bug-1713's own fix was itself still an uncommitted working-tree change sharing the same file -- a bare git stash would have reverted bug-1713 too) -- the new parametrized test_record_status_retries_on_transient_admin_reason_then_succeeds/..._retry_exhaustion_on_transient_admin_reason_... tests failed at COLLECTION time (AttributeError: module 'xceadmin.scheduler' has no attribute '_TRANSIENT_ADMIN_REASONS'), and a standalone ad hoc script against that same pre-fix code confirmed BEHAVIORAL red too: a real TLS mock returning ok=false, error='scheduler disconnected' once raised SchedAdminError immediately after exactly 1 connection, no retry. Reapplied the fix -> GREEN: all 41 tests in test_scheduler.py pass, including 4 new _TRANSIENT_ADMIN_REASONS-parametrized retry-then-succeed tests, 4 new retry-exhaustion tests (one per confirmed-transient reason, each asserting exact connection_count == _MAX_TRANSIENT_ATTEMPTS and a distinguishable exhaustion message), and a new test_record_stop_not_recording_never_retried non-regression test (asserts connection_count==1, zero sleep calls, for the permanent 'not recording' reason). The pre-existing test_record_start_error_codes_raise_sched_admin_error parametrize list was edited (not left untouched): "scheduler not connected"/"request timeout" were removed (they are now confirmed-transient and retried, not raised immediately -- their coverage moved to the new retry tests) and replaced with two more confirmed-permanent validation_error_text() strings ("record directory not found", "permission denied accessing record file") alongside the original "invalid record file name", for stronger permanent-error coverage. bug-1713's own 5 tests (transient-status retry/exhaustion, both E_XCE_STANDBY regression locks) were run UNMODIFIED and all still pass -- no shared-loop refactor was needed since bug-1713's for attempt in range(...) loop and its reply.status != 0 branch were reused as-is; only a second if/retry check was added inside the existing if not admin_reply.ok: branch. Full xceadmin suite: 283 passed, 1 failed -- the failure (test_live_config_push_against_standby_returns_standby_rejection_not_redirect) is the SAME pre-existing, already-flagged-stale failure named in bug-1713's own report (test_e2e_live_ha_push.py, stale since bug-1700/1701's redirect-gap fix generalized to OPCode_upgradeConfig) -- zero new failures caused by this fix (284 total tests vs bug-1713's reported 275, consistent with the 9 new tests added here). LIVE VERIFICATION (real 3-node cluster, deploy-ha.sh + start-all.sh, build.dbg's real xce_controller/xce_scheduler/xcecd_virtual binaries -- no C rebuild needed since this fix is Python-only and none of the C-side cluster.c/driver.c code changed): hammered xceadmin.scheduler.record_status('localhost:9991') (the elected primary) in a tight zero-delay loop against the fixed client for 20s while concurrently kill -9-ing the live xce_scheduler process mid-run and restarting it via start-scheduler.sh (a genuine scheduler-process-death-and-restart, not a mock, not a controller failover). Result: 153 of 154 requests during the window succeeded, most transparently absorbing the scheduler-down period with zero visible failure to the caller; ONE request genuinely hit the real 'scheduler not connected' condition, went through the full retry budget (logged exactly as designed: 'scheduler not connected (still transient after 4 attempts over ~4.5s -- giving up)'), and still surfaced a SchedAdminError because this particular sandbox's scheduler restart (relaunched via a fresh nix develop subshell each time, which carries its own multi-second evaluation overhead on top of the scheduler's own re-join handshake) took longer to fully rejoin than the shared 4-attempt/1.5s (~4.5s total) budget -- the very next request after that succeeded again. This is honestly reported as PARTIAL absorption, not a zero-failure live result like bug-1713's controller-failover scenario got: the retry mechanism is proven to engage correctly on a genuine, non-mocked signal end-to-end (real controller, real scheduler restart, real wire reply, real client-side retry/give-up message), and it converted what would have been 100% visible failure for the whole outage window (pre-fix) into 1 failure out of 154 requests (post-fix) -- but this sandbox's nix-develop-relaunch overhead for the scheduler restart is likely slower than a real production supervisor restart would be, so the single exhaustion here should not be read as proof the shared 4.5s budget is too short in general. Kept the identical bug-1713 budget as instructed (no concrete evidence specific to THIS class of condition that it's wrong -- the one exhaustion observed is plausibly a sandbox-restart-mechanism artifact, not a signal about the real-world scheduler-restart timescale) rather than inventing a different cadence from one ambiguous data point. push.py's push_config()/probe_config() gap flagged by bug-1713 as a sibling finding remains unfixed and out of this bug's scope (unchanged from bug-1713's report).
Verification
Not recorded (migrated from buglog.json).
References
- Related: bug-1713, bug-1693