Skip to content

fix(index): make a crashed worker's log survive and name the run - #1644

Merged
DeusData merged 1 commit into
mainfrom
fix/worker-log-flush
Aug 15, 2026
Merged

fix(index): make a crashed worker's log survive and name the run#1644
DeusData merged 1 commit into
mainfrom
fix/worker-log-flush

Conversation

@DeusData

Copy link
Copy Markdown
Owner

The problem

Six open reports end at the same dead end. The supervisor contains a worker
failure, prints the log path, and the file is empty:

the worker log file mentioned (.worker-*.log) is completely empty (0 KB),
so I cannot identify which file caused the crash — #1145

Six reports, zero diagnoses. Not one is reproducible or attributable, and the
hint we print — "Indexing worker crashed on a file" — never names the file.

Root cause: buffering, not the crash

The supervisor redirects the worker's stdout+stderr into the log file
(options.log_file, subprocess.c), and every diagnostic reaches it through
fprintf(stderr, …) in log.c with no flush anywhere.

The C standard only promises stderr is "not fully buffered". The Windows CRT
gives a redirected stderr full buffering — which is why five of the six
reports are Windows. A worker that aborts, is SIGKILLed by the OOM killer, or is
terminated after a hang dies with its whole diagnostic still in a userspace
buffer. The file on disk is 0 bytes because nothing was ever written to it.

What this changes

cbm_log_set_crash_durable()setvbuf(_IONBF) plus a per-line flush in
emit_line. Both, deliberately: setvbuf covers every writer to the stream,
including the plain fprintf(stderr, "CBM index worker could not start: …")
paths that explain a worker which never got as far as logging; the per-line flush
covers the case where setvbuf is refused because the stream was already written
to (it only binds before a stream's first operation). Enabled for the worker role
only, claimed in main() before the process writes anything.

cbm_index_worker_log_begin() — a startup header written and flushed as the
worker's first act: version, build fingerprint, pid, repo path, and the worker's
own arguments. It is a control record, not an info line, so a user running with
CBM_LOG_LEVEL=warn cannot end up back at a 0-byte log.

Per-file breadcrumb — under a crash-durable log the parallel extract pass logs
every file it starts, not just the first two rounds of workers, so the log ends
with the files that were in flight when the worker died. One line per file, never
per node. Behaviour is unchanged for every non-worker caller.

What a reporter now attaches instead of an empty file (real capture, worker
SIGKILLed mid-run):

{"level":"control","event":"index.worker.start","version":"dev","build":"0123…cdef","pid":"97197","repo_path":"/tmp/…/some repo","args":"{\"__cbm_test_worker\":\"buffered-kill\",\"repo_path\":\"/tmp/…/some repo\"}"}
level=info msg=mem.allocator.bound_populations_only owned_classes=0/6 populations=sqlite,tree_sitter …
level=info msg=mem.init budget_mb=24576 total_ram_mb=49152 source=ram_fraction
level=info msg=index.worker.buffered_kill_probe phase=before_kill

This fixes no crash. It converts six unreproducible reports into reports we
can act on, and every future one arrives with the run identified. That is the
whole claim — none of these six issues is closed by this PR.

Test

index_supervisor_killed_worker_log_is_never_empty_and_names_the_run
(tests/test_index_supervisor.c, suite index_supervisor).

A real worker child starts with a fully buffered stderr — the state the
Windows CRT hands a redirected stderr, forced on POSIX by the harness so the
contract binds on all three legs instead of being a Windows-only claim nobody can
run locally. It writes diagnostics and is then SIGKILLed. The supervisor keeps the
log of a failed worker, so what is on disk afterwards is exactly what a user would
attach to an issue. Asserted: non-empty, carries the header with version / pid /
repo path (containing a space, as Windows reporters have) / args, and still holds
the line written after the header.

The probe kills rather than aborts, and that mattered: Darwin's abort() runs
the stdio cleanup handler and flushes the very buffer the repro depends on
stranding. The first version of this test used abort(), and the reverted build
still produced a populated log — the repro was quietly toothless. SIGKILL cannot
be caught, blocked or handled, so no cleanup of any kind runs; it is also literally
#1070's death (signal=9) and how #1130's hung worker is terminated.

Revert-check — production change reverted (setvbuf + per-line flush + header
emission neutralised, test untouched), the log comes back at 0 bytes and the test
fails on the first content assertion. The harness dumps the log at the failure
site and it prints nothing at all:

  index_supervisor_killed_worker_log_is_never_empty_and_names_the_run
level=info msg=index.supervisor.reap outcome=killed exit_code=-1 signal=9
level=warn msg=index.supervisor.worker_failed outcome=killed exit_code=-1 log=/tmp/cbm-index-logheader-8VnBT2/logs/.worker-log-F42mK2
  [worker-dump] buffered-kill worker log: /tmp/cbm-index-logheader-8VnBT2/logs/.worker-log-F42mK2

  FAIL tests/test_index_supervisor.c:841: ASSERT(log_size > 0)

  6 passed, 1 failed

With the change in place, ./build/c/test-runner index_supervisor is 7/7 green
on macOS arm64 (ASan/UBSan build).

Six reports describe the same dead end: the indexing worker dies, the
supervisor points at `logs/.worker-<pid>.log`, and the file is 0 bytes.
Nothing was ever flushed, so not one of #1070, #1130, #1132, #1133,
#1145 or #1450 is reproducible or attributable -- the hint says "crashed
on a file" and the file is never named.

Root cause is buffering, not the crash. The worker's stderr is redirected
to that log file by the supervisor, and every diagnostic goes through
`fprintf(stderr, ...)` with no flush. The C standard only promises stderr
is "not fully buffered"; the Windows CRT gives a redirected stderr FULL
buffering, which is why five of the six reports are Windows. A worker
that aborts, is SIGKILLed by the OOM killer, or is terminated after a
hang takes its whole buffer with it.

  - cbm_log_set_crash_durable(): setvbuf(_IONBF) plus a per-line flush in
    emit_line. Both, deliberately -- setvbuf covers every writer to the
    stream including the plain fprintf startup errors that explain a
    worker which never got as far as logging, and the flush covers the
    case where setvbuf is refused because the stream was already written
    to. Enabled for the worker role only, claimed in main() before the
    process writes anything.
  - cbm_index_worker_log_begin(): a startup header written and flushed as
    the worker's first act -- version, build fingerprint, pid, repo path,
    and the worker's own arguments. A control record rather than an info
    line, so CBM_LOG_LEVEL cannot restore the 0-byte log.
  - Under a crash-durable log the parallel extract pass logs every file
    it starts, not just the first two rounds of workers, so the log ends
    with the files that were in flight when the worker died. One line per
    file, never per node; unchanged for every non-worker caller.

This fixes no crash. It converts six unreproducible reports into reports
we can act on, and every future one arrives with the run identified.

Test: a worker started with a fully buffered stderr -- the state the
Windows CRT hands it, forced on POSIX so the contract binds on all three
legs -- writes diagnostics and is then SIGKILLed. The retained log must
be non-empty, carry the header with the version, pid, repo path and args,
and still hold the line written after it. Reverting the production change
leaves that log at 0 bytes.

The probe kills rather than aborts because Darwin's abort() runs the
stdio cleanup handler and flushes the very buffer the repro depends on
stranding: under abort the reverted build still produced a populated log
and the test was quietly toothless. SIGKILL runs no cleanup, and is
literally #1070's death (signal=9).

Refs #1070
Refs #1130
Refs #1132
Refs #1133
Refs #1145
Refs #1450

Signed-off-by: Martin Vogel <martin.vogel.tech@gmail.com>
@DeusData
DeusData merged commit 092c77e into main Aug 15, 2026
36 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant