h-dv/code-index

Watch

Fork 0

daemon_log_e2e: the daemon does not publish its lockfile within 60s on BOTH CI platforms (105ms locally) #94

New issue

Closed

opened 2026-09-03 21:13:26 +02:00 by buildagent · 1 comment

buildagent commented

2026-09-03 21:13:26 +02:00

Member

What happened

a_detached_daemon_writes_a_log_beside_its_lockfile timed out at the 60s deadline on both CI legs of the same commit (334f2c9):

Linux, run 4913: test result: FAILED. 3 passed; 1 failed; finished in 62.42s
Windows, run 4912: test result: FAILED. 3 passed; 1 failed; finished in 60.18s

It waits for the daemon to write daemon listener bound; lockfile published into its log.

What is established

Locally the same step takes 105 ms, with near-zero variance (6/6 runs, 0.105–0.106s). The CI outcome is a ~570x outlier, not a slow machine.

Neither load axis reproduces it on this hardware:

12-way CPU saturation on 12 cores: 8/8 pass
8-way fsync-heavy I/O load: 6/6, still ~0.107s

Where the fault has to be

The suite's other three tests wait only for some log line (a DEBUG line, or rotation). This is the only test that requires the daemon to get past write_payload. So the stall or death sits in a ~10-line window in crates/daemon/src/main.rs:

info!(... "RPC server bound")      <- inside bind(), the last thing PROVEN to run
Lockfile { pid, port, version, token, ... }
guard.write_payload(&lock)?        <- fsync + rename; on Windows also restrict_to_owner
info!(... "daemon listener bound; lockfile published")   <- what the test waits for

It is also the only test that runs with auth ON (env_remove("CODE_INDEX_DAEMON_NO_AUTH")), so token: Some(..) and generate_token() (getrandom) are on its path and no other's.

Leading unproven candidates, in order: the daemon was OOM-killed / evicted under the full-workspace suite (would explain both platforms and the load dependence, and is invisible on an idle box); sync_data() stalling on slow CI storage; getrandom blocking.

Root cause is NOT established and is deliberately not claimed here.

What has been done

The test could not previously tell a slow daemon from a dead one — it waited the full budget and printed the same sentence either way, which is why a 60s timeout arrived with nothing to go on. It now:

polls the child beside the condition, so a daemon that exited fails immediately naming its exit status (measured: 0.24s instead of 60s), and
prints the log's actual content on timeout, which bisects the window above — file absent = died before setup_logging; RPC server bound present but not the published line = the write_payload gap; published line present = we were racing the poll.

Deadline raised 60s -> 180s, so a genuinely slow-but-alive daemon is distinguished from a wedged one rather than being cut off at the same mark.

Both branches were mutation-proved (dead-daemon branch and alive-but-wedged branch each run RED with the diagnostic content).

Next step

The next CI occurrence names its own cause. Leave this open until a run prints the log content and the sub-case is identified.

## What happened `a_detached_daemon_writes_a_log_beside_its_lockfile` timed out at the 60s deadline on **both** CI legs of the same commit (`334f2c9`): - Linux, run 4913: `test result: FAILED. 3 passed; 1 failed; finished in 62.42s` - Windows, run 4912: `test result: FAILED. 3 passed; 1 failed; finished in 60.18s` It waits for the daemon to write `daemon listener bound; lockfile published` into its log. ## What is established **Locally the same step takes 105 ms**, with near-zero variance (6/6 runs, 0.105–0.106s). The CI outcome is a ~570x outlier, not a slow machine. Neither load axis reproduces it on this hardware: - 12-way CPU saturation on 12 cores: **8/8 pass** - 8-way fsync-heavy I/O load: **6/6, still ~0.107s** ## Where the fault has to be The suite's other three tests wait only for *some* log line (a `DEBUG` line, or rotation). This is the **only** test that requires the daemon to get past `write_payload`. So the stall or death sits in a ~10-line window in `crates/daemon/src/main.rs`: ``` info!(... "RPC server bound") <- inside bind(), the last thing PROVEN to run Lockfile { pid, port, version, token, ... } guard.write_payload(&lock)? <- fsync + rename; on Windows also restrict_to_owner info!(... "daemon listener bound; lockfile published") <- what the test waits for ``` It is also the only test that runs with **auth ON** (`env_remove("CODE_INDEX_DAEMON_NO_AUTH")`), so `token: Some(..)` and `generate_token()` (getrandom) are on its path and no other's. Leading unproven candidates, in order: the daemon was **OOM-killed / evicted** under the full-workspace suite (would explain both platforms and the load dependence, and is invisible on an idle box); `sync_data()` stalling on slow CI storage; `getrandom` blocking. **Root cause is NOT established and is deliberately not claimed here.** ## What has been done The test could not previously tell a *slow* daemon from a *dead* one — it waited the full budget and printed the same sentence either way, which is why a 60s timeout arrived with nothing to go on. It now: 1. polls the child beside the condition, so a daemon that **exited** fails immediately naming its exit status (measured: 0.24s instead of 60s), and 2. prints the log's **actual content** on timeout, which bisects the window above — file absent = died before `setup_logging`; `RPC server bound` present but not the published line = the `write_payload` gap; published line present = we were racing the poll. Deadline raised 60s -> 180s, so a genuinely slow-but-alive daemon is distinguished from a wedged one rather than being cut off at the same mark. Both branches were mutation-proved (dead-daemon branch and alive-but-wedged branch each run RED with the diagnostic content). ## Next step The next CI occurrence names its own cause. Leave this open until a run prints the log content and the sub-case is identified.

dhoyer referenced this issue from a commit

2026-09-03 22:40:21 +02:00

fix: keys that moved with the disk, probes that could not look, waits that could not tell dead from slow

buildagent commented

2026-09-04 00:01:15 +02:00

Author

Member

SOLVED — and it was a defect in the TEST, not in the daemon

The instrument added when this was filed did exactly what it was built to do. On commit 4d8911b the same test failed on both legs, but this time it printed its own cause:

the daemon's startup record reaches the log did not happen within 180s, and the daemon
was still RUNNING throughout — so this is slowness or a wedge, not a crash.
the log EXISTS but is EMPTY

That one line eliminated every hypothesis in the issue body. Still RUNNING rules out the OOM kill and the crash. Log present but EMPTY rules out the write_payload window entirely — the daemon had not even written the "daemon log" line that main() emits immediately after setup_logging, long before the bind. A live process with an empty log is not a wedge; it is a level filter.

The cause

setup_logging falls back to CODE_INDEX_LOG when --log is absent (main.rs), and this test deliberately omits --log — its own doc says why: the asserted line is an info, "the DEFAULT level a production daemon runs at".

Both workflows set the variable job-wide:

.forgejo/workflows/ci.yml:481          CODE_INDEX_LOG: warn
.forgejo/workflows/ci-windows.yml:55   CODE_INDEX_LOG: warn

So in CI the child inherited warn, every info was filtered, the file was created and stayed empty, and the test waited the full budget for a line that was never going to be written. It could not reproduce on a developer's machine because nothing sets that variable there.

That also explains what looked inexplicable: both platforms, identically (it is the environment, not the OS), and no reproduction under 12-way CPU saturation or 8-way fsync load (it was never about load).

Proved, not argued

$ CODE_INDEX_LOG=warn cargo test -p code-index-daemon --test daemon_log_e2e a_detached_daemon
the daemon was still RUNNING throughout ... the log EXISTS but is EMPTY
test result: FAILED. 0 passed; 1 failed ... finished in 183.12s

Byte-identical to the CI failure, on this Linux box. With .env_remove("CODE_INDEX_LOG") added to the spawn, the same command is:

test result: ok. 4 passed; 0 failed ... finished in 0.48s

The lesson worth keeping

The test already carried .env_remove("CODE_INDEX_DAEMON_NO_AUTH") with a comment saying it was there "so an ambient value in the developer's shell cannot silently empty the assertion below". The identical hazard one line later, for the variable that decides whether the asserted line exists at all, was not handled. A test that asserts on log CONTENT must control the LEVEL, for the same reason it controls auth.

Closing. The diagnostic stays: it is what turned a third occurrence into a five-minute answer instead of a fourth investigation.

## SOLVED — and it was a defect in the TEST, not in the daemon The instrument added when this was filed did exactly what it was built to do. On commit `4d8911b` the same test failed on both legs, but this time it printed its own cause: ``` the daemon's startup record reaches the log did not happen within 180s, and the daemon was still RUNNING throughout — so this is slowness or a wedge, not a crash. the log EXISTS but is EMPTY ``` That one line eliminated every hypothesis in the issue body. **Still RUNNING** rules out the OOM kill and the crash. **Log present but EMPTY** rules out the `write_payload` window entirely — the daemon had not even written the `"daemon log"` line that `main()` emits immediately after `setup_logging`, long before the bind. A live process with an empty log is not a wedge; it is a **level filter**. ## The cause `setup_logging` falls back to `CODE_INDEX_LOG` when `--log` is absent (`main.rs`), and this test deliberately omits `--log` — its own doc says why: the asserted line is an `info`, "the DEFAULT level a production daemon runs at". Both workflows set the variable job-wide: ``` .forgejo/workflows/ci.yml:481 CODE_INDEX_LOG: warn .forgejo/workflows/ci-windows.yml:55 CODE_INDEX_LOG: warn ``` So in CI the child inherited `warn`, every `info` was filtered, the file was created and stayed empty, and the test waited the full budget for a line that was never going to be written. It could not reproduce on a developer's machine because nothing sets that variable there. That also explains what looked inexplicable: **both platforms, identically** (it is the environment, not the OS), and no reproduction under 12-way CPU saturation or 8-way fsync load (it was never about load). ## Proved, not argued ``` $ CODE_INDEX_LOG=warn cargo test -p code-index-daemon --test daemon_log_e2e a_detached_daemon the daemon was still RUNNING throughout ... the log EXISTS but is EMPTY test result: FAILED. 0 passed; 1 failed ... finished in 183.12s ``` Byte-identical to the CI failure, on this Linux box. With `.env_remove("CODE_INDEX_LOG")` added to the spawn, the same command is: ``` test result: ok. 4 passed; 0 failed ... finished in 0.48s ``` ## The lesson worth keeping The test already carried `.env_remove("CODE_INDEX_DAEMON_NO_AUTH")` with a comment saying it was there "so an ambient value in the developer's shell cannot silently empty the assertion below". The identical hazard one line later, for the variable that decides whether the asserted line exists at all, was not handled. **A test that asserts on log CONTENT must control the LEVEL, for the same reason it controls auth.** Closing. The diagnostic stays: it is what turned a third occurrence into a five-minute answer instead of a fourth investigation.

buildagent closed this issue

2026-09-04 00:01:18 +02:00

dhoyer referenced this issue from a commit

2026-09-04 00:47:50 +02:00

fix: a test that asserted an info line while CI filtered it, and an invariant that was true only on Linux

buildagent referenced this issue

2026-09-04 09:43:26 +02:00

bug: the auto-spawned daemon has NO log — its stderr is /dev/null, so no field failure can ever be diagnosed #92