myxce/.wolf/bugs/bug-1729.md
Rongsong Shen d26ff8870d
feat(buglog): one Markdown record per bug, checked against a record standard
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>
2026-09-28 03:40:11 +00:00

3.7 KiB

id status status_updated status_note component severity timestamp last_seen occurrences files tags related legacy
bug-1729 fixed 2026-09-24 worker unknown 2026-08-28T10:25:14Z 2026-09-19T09:00:00Z 1
src/worker/src/uv_ipc.c (ipc_worker_send_status
JOB_EXITED branch)
worker
logging-severity
false-error
job-kill
tdd
found-live
session-sibling-of-bug-1727
session-sibling-of-bug-1728
bug-1727
bug-1728
true

bug-1729: xcecd_worker.log logs [ERROR] Job <jobid> exited with code 137: Killed for an ordinary…

Description

xcecd_worker.log logs [ERROR] Job <jobid> exited with code 137: Killed for an ordinary, deliberate job kill/cancel (exit code 137 = 128+SIGKILL) -- user-reported as misleading, since 'kill job' is a normal admin operation, not a failure.

Environment

Not recorded (migrated from buglog.json).

Reproduction

Not recorded (migrated from buglog.json).

Root cause

CONFIRMED: process_exit_callback() (xcecd_worker.c:467-502) already treats a signal-terminated job exit as informational -- XCECD_WORKER_LOG(XCE_LOG_INFO, "Child %d killed by signal %d\n", pid, term_signal) at line 497 -- immediately before calling ipc_worker_send_status(&job_runtime_info, "Killed"). But ipc_worker_send_status() (uv_ipc.c, JOB_EXITED branch) re-derived its own severity purely from job_status, hardcoded to XCE_LOG_ERROR for every JOB_EXITED regardless of cause -- so the SAME kill event logged INFO two lines earlier and ERROR two lines later, in the same call chain. There is no JOB_KILLED status distinct from JOB_EXITED, so a deliberate xcecli kill (worker_signal_callback(), xcecd_worker.c:1118, itself logs INFO: 'Terminating job %s with signal %d') produced an ERROR-level status log downstream regardless of intent. worker_signal_callback() only ever sends SIGTERM or SIGKILL for a normal cancel/force-kill (xcecd_worker.c:1116-1125) -- exit_code is always exactly 128+term_signal (xcecd_worker.c:493), so exit_code==143 (SIGTERM) or 137 (SIGKILL) reliably identifies a deliberate worker-initiated termination, distinct from a genuine crash signal (SIGSEGV=139, SIGBUS=135, SIGABRT=134, etc.).

Fix

FIXED and unit-tested (TDD red->green, negative-control verified: temporarily forced job_exit_log_level() to always return XCE_LOG_ERROR, confirmed 2/4 new tests failed as expected, then restored the real fix and confirmed all 4 pass). Extracted the severity decision into a small pure function, static LogLevel job_exit_log_level(int exit_code) (uv_ipc.c, just above ipc_worker_send_status()): returns XCE_LOG_INFO for exit_code == 128+SIGTERM or 128+SIGKILL (matches process_exit_callback()'s own INFO judgment for the identical event), XCE_LOG_ERROR otherwise (preserves ERROR for genuine crash signals and any other/unrecognized exit code). Wired into the JOB_EXITED branch: XCECD_WORKER_LOG(job_exit_log_level(job_info->exit_code), "Job %s exited with code %d: %s", ...). Added #include <signal.h> for SIGTERM/SIGKILL/SIGSEGV/etc. New test worker/testsuite/test_uv_ipc_job_exit_severity.c (4 cases: deliberate SIGTERM, deliberate SIGKILL, genuine crash signals SIGSEGV/SIGABRT/SIGBUS, unrecognized/plain exit codes) white-box #includes uv_ipc.c directly (existing suite convention) and exercises only the pure helper -- no libuv/IPC machinery needed. Two link-only stub functions added (find_worker_by_pid, xcecd_job_remote_start) to satisfy the linker for code paths this test never calls, same stubbing idiom test_resource_sync.c already establishes. Full worker test suite (5 binaries, 25 tests total) green after the fix; real xcecd_worker binary rebuilds cleanly.

Verification

Not recorded (migrated from buglog.json).

References

  • Related: bug-1727, bug-1728