iterative-works/iw-cli

Watch

Fork 0

E2E and dashboard suites flake when another worktree builds concurrently #489

New issue

Closed

opened 2026-09-01 12:07:50 +00:00 by mph · 3 comments

mph commented

2026-09-01 12:07:50 +00:00

Owner

The E2E and dashboard suites contend on real resources and go red without any defect in the tree when another worktree of this repo builds at the same time.

Evidence

Seen while verifying the IW-476 phase-01 review fixes, with another iw-cli worktree running batch-implement.

dashboard.test -> CaskServerTest."GET /api/status shows correct worktree count" failed at dashboard/jvm/test/src/CaskServerTest.scala:439. Green on the next run with no code change. The test binds a real port and writes a state file.
./iw ./test e2e -> exit 1 with 7 not ok lines across the issue create, open and rm suites. bats test/rm.bats alone passed both its tests, and the next full run returned exit 0 with 190 ok and no failures.

Neither touches the code changed in that phase.

A third sighting, 2026-09-01

Pushing the IW-476 feature branch, the pre-push hook printed:

241/241, SUCCESS] /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test 10s

PUSH BLOCKED: Tests failed

The hook's step 3 is if ./iw ./test unit && ./iw ./test compile. Run standalone on the same tree, both exit 0, and the hook script run directly (bash .git-hooks/pre-push) passes. The identical push retried immediately and succeeded with no change. So ./iw ./test unit returned non-zero inside the push while printing a passing suite. That half is not explained by suite flakiness and may be a separate fault.

Why it matters

A red that does not reproduce costs an investigation into code that is fine, and it trains the reader to retry rather than to read. The pre-push case is worse: the banner asserts "Tests failed" over output that says the tests passed.

Wanted

Find the resource these suites contend on and make the suites independent of it, or serialise them. Separately, find why ./iw ./test unit can return non-zero to the hook while printing success.

#443 — CI compile job must not fail on a Bloop server timeout. Adjacent but distinct: that is a build server that never starts; this is tests contending on a port and a state file.
IW-476 LESSONS.md entry 10.

The E2E and dashboard suites contend on real resources and go red without any defect in the tree when another worktree of this repo builds at the same time. ## Evidence Seen while verifying the IW-476 phase-01 review fixes, with another iw-cli worktree running `batch-implement`. - `dashboard.test` -> `CaskServerTest."GET /api/status shows correct worktree count"` failed at `dashboard/jvm/test/src/CaskServerTest.scala:439`. Green on the next run with no code change. The test binds a real port and writes a state file. - `./iw ./test e2e` -> exit 1 with 7 `not ok` lines across the `issue create`, `open` and `rm` suites. `bats test/rm.bats` alone passed both its tests, and the next full run returned exit 0 with 190 ok and no failures. Neither touches the code changed in that phase. ## A third sighting, 2026-09-01 Pushing the IW-476 feature branch, the `pre-push` hook printed: ``` 241/241, SUCCESS] /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test 10s PUSH BLOCKED: Tests failed ``` The hook's step 3 is `if ./iw ./test unit && ./iw ./test compile`. Run standalone on the same tree, both exit 0, and the hook script run directly (`bash .git-hooks/pre-push`) passes. The identical push retried immediately and succeeded with no change. So `./iw ./test unit` returned non-zero inside the push while printing a passing suite. That half is not explained by suite flakiness and may be a separate fault. ## Why it matters A red that does not reproduce costs an investigation into code that is fine, and it trains the reader to retry rather than to read. The `pre-push` case is worse: the banner asserts "Tests failed" over output that says the tests passed. ## Wanted Find the resource these suites contend on and make the suites independent of it, or serialise them. Separately, find why `./iw ./test unit` can return non-zero to the hook while printing success. ## Related - #443 — CI compile job must not fail on a Bloop server timeout. Adjacent but distinct: that is a build server that never starts; this is tests contending on a port and a state file. - IW-476 LESSONS.md entry 10.

mph referenced this issue

2026-09-01 14:02:50 +00:00

tmux-dependent BATS tests fail non-deterministically under a full ./iw ./test run #468

mph commented

2026-09-01 14:02:55 +00:00

Author

Owner

Duplicate of #468, which reports the same non-determinism with a fuller investigation (temp-directory race and socket collision already ruled out). Everything this issue added — the dashboard.test flake, the concurrent-worktree correlation, and the pre-push 'PUSH BLOCKED over SUCCESS' anomaly — is copied onto #468. Closing here; track it there.

mph closed this issue

2026-09-01 14:02:55 +00:00

mph referenced this issue

2026-09-01 15:33:03 +00:00

tmux-dependent BATS tests fail non-deterministically under a full ./iw ./test run #468

mph referenced this issue from a commit

2026-09-01 15:35:00 +00:00

workflow: Triage lessons for IW-476

mph referenced this issue

2026-09-01 15:35:39 +00:00

IW-476: The herdr sidebar names a worktree by its key, and a rename sticks #498

mph commented

2026-09-02 05:34:11 +00:00

Author

Owner

Diagnosis

Investigated on batch-implement-blockers. This is not one bug. It is three, and only two of them are about concurrency. Fix was deliberately kept out of scope for this session; this comment records the causes so the fix can be scoped properly.

(c) The gate that says "Tests failed" over passing output — highest value, and the only one that is a lie

Two things compose.

First, an ordering artefact. .iw/commands/test.scala:74-84 runs mill core.test first, then mill dashboard.test, and ANDs the two exit codes. It prints a section header before each and nothing after either. So the last thing on screen is always the second command's tail. A core.test that failed five minutes earlier leaves dashboard.test SUCCESS as the final visible line, then the hook's red banner. That alone explains the reported ordering, with no wrong exit code anywhere.

Second, and this is the real defect: runStreaming cannot tell a failing command from one we killed, and says nothing either way.

core/adapters/Process.scala:99-121 passes timeout = timeoutMs (default 5 minutes, line 24) to os-lib's call(check = false, ...). In os-lib 0.11.6 that reaches sub.join(timeout, shutdownGracePeriod), which sends SIGTERM, waits 100 ms, then SIGKILL. No exception is thrown — check = false short-circuits the throw. call returns a CommandResult whose exitCode is 143 or 137, and Process.scala:120 returns that Int verbatim. The caller sees a non-zero number with no way to know we killed it.

The repo already models the correct behaviour one function up: ProcessAdapter.run computes val timedOut = result.exitCode == SigtermExitCode (Process.scala:78, constant at line 41) and surfaces it on ProcessResult. core/test/ProcessTest.scala pins it. runStreaming drops the whole channel.

So: mill core.test crossing 300 s — which needs no bug at all, only a cold Mill daemon plus a scoverage-instrumented compile (build.mill:36) plus a second worktree saturating the machine — is SIGTERMed by our own harness. dashboard.test then runs, passes in 10 s, prints SUCCESS, and runUnitTests returns false. Exactly the reported shape.

I cannot prove from code alone which of the two produced the specific run: a silent timeout kill, or a genuine failure whose output scrolled away. That is the point — today the two are indistinguishable, at the exit code and on screen.

Hypothesis, unconfirmed: Mill 1.1.5's launcher reads the daemon's exit code out of out/mill-daemon/, so a daemon dying after finishing the graph could also produce SUCCESS-then-nonzero. The check is ./mill dashboard.test; echo $? under load. The timeout mechanism above needs no such assumption.

(a) `CaskServerTest."GET /api/status shows correct worktree count"`

The shared resource is the TCP port, not the state file. The state file is ${java.io.tmpdir}/iw-server-test-${Random.nextLong().abs}/state.json (CaskServerTest.scala:29-32) — never the shared ~/.local/share/iw/server/state.json. Collision there is not credible.

Three facts compose into a silent cross-JVM hijack:

findAvailablePort() (CaskServerTest.scala:74-78) closes the socket before returning the number. Two JVMs can be handed the same freed ephemeral port.
The loser's bind failure is swallowed. startTestServer (:43-47) runs CaskServer.start on a bare new Thread(...) with no try/catch. Undertow throws a RuntimeException wrapping BindException; on that thread it reaches only the default uncaught handler — a stack trace in the log, and the test carries on.
The readiness probe cannot tell servers apart. :50-58 polls /health and accepts any 200. /health is ujson.Obj("status" -> "ok") with no identity (CaskServer.scala:769-771). The winner answers 200, so the loser declares itself ready.

The loser then PUTs IWLE-111 and IWLE-222 into the winner's server and reads /api/status back from it. status() (CaskServer.scala:815-825) returns state.worktrees.size with no pruning, so the count is the other JVM's. worktreeCount fails — and port on the next line still passes, because both servers were told the same number. That is why the failure looks inexplicable.

On the reported line 439: at both 7a4fa367 and HEAD that line is blank; the worktreeCount assertion is at 457. The report either points at an exception out of the first PUT, or the line is slightly off. Either reading lands inside the same test and both are explained by "this test's server never owned its port."

The itest suite retries (CaskServerItest.scala:80-137) and is mostly safe — but it swallows case _: java.net.BindException => () (line 104) and also accepts any 200, so a foreign holder still reads as ready there too. The retry only rescues the case where nothing answers.

(b) The seven scattered `not ok` lines in `issue create` / `open` / `rm`

These suites isolate cwd, the tmux socket, the dashboard and plugins. They do not isolate HOME or XDG_DATA_HOME, and four resources leak:

/tmp/testproject-* is a cross-run destructor. Six teardowns glob it (rm.bats:41, open.bats:41, start.bats:41, analyze.bats:42, open-prompt.bats:54, start-prompt.bats:54). Two concurrent E2E runs delete each other's worktrees mid-test. open.bats and rm.bats are two of the suites named in the sighting.
One bloop daemon per user. Every iw <cmd> in every BATS test is exec scala-cli run -q .... Confirmed on this machine: exactly one daemon, -Xmx8g, shared by all three checked-out worktrees. Per-worktree .scala-build/ keeps the projects distinct; the daemon, its heap and its compile queue are not.
~/.cache/coursier and its lock files, shared by every mill and scala-cli invocation.
A self-inflicted amplifier. runE2ETests sets IW_CORE_JAR to installDir / "build" / "iw-core.jar" under a comment saying it avoids per-test jar rebuilds. That file is written only by scripts/package-release.sh:79 into the release staging dir — it never exists in a dev checkout. Worse, the override destroys a good value: iw-run had already exported a valid IW_CORE_JAR before exec'ing the test command. Net effect: every one of ~190 BATS tests spawns a Mill launcher against out/. Any single Mill hiccup under load becomes Error: Mill failed to resolve core.jar → iw exit 1 → a red line in whichever suite was unlucky. That is precisely "7 not ok scattered across three unrelated suites, each green when run alone."

What a fix would have to do, in order

(c) first — stop the tooling lying.

runStreaming must detect the kill and return the existing -1 sentinel rather than the signal code, and print one line naming what was killed. SigtermExitCode already exists at Process.scala:41.
runUnitTests must give the Mill invocations a build-appropriate timeout — runE2ETests and runContractTests already pass 10 minutes, so 5 minutes for a scoverage-instrumented core.test is an oversight, not a policy — and must name the culprit before returning.
.git-hooks/pre-push:56-68 runs ./iw ./test unit && ./iw ./test compile, so a unit failure never reaches compile and the banner cannot say which step failed. Run them separately and report the failing step. Do not weaken the gate.

(a) — make a test server prove it owns its port.
4. Give /health an instance identity. Without it no readiness probe can tell "my server" from "someone else's server on the same number".
5. startTestServer must capture the startup throwable instead of dropping it, accept readiness only on its own instance id, retry with a fresh port on mismatch, and fail(...) with the captured BindException when attempts run out. CaskServerItest.scala:80-137 is the retry skeleton to copy — but fix its two holes in the copy. Note the suite is var-free and the project bans var: write it recursively, not as the itest's while/var loop.

(b) — isolation.
6. Stop globbing /tmp/testproject-*. Create sibling worktrees inside a per-test parent and rm -rf only that parent. Touches the tests asserting on the sibling path (analyze.bats:49-50, start-prompt.bats:64-65).
7. Stop overriding IW_CORE_JAR with a path that does not exist. Either resolve the real jar or pass through what iw-run already exported. The comment above it then becomes true, and ~190 Mill spawns per E2E run disappear.
8. The per-user bloop daemon and coursier cache stay shared by design. If cross-worktree E2E concurrency must be safe, that is a policy decision — the honest options are a machine-wide advisory lock on iw ./test, or accepting that concurrent E2E is unsupported.

Items 6 and 7 are bugs on their own merits and are worth fixing regardless of the concurrency policy.

Diagnosis only, per the scope of this session. Claims are cited to file:line; the two places I could not prove are labelled as hypotheses.

## Diagnosis Investigated on `batch-implement-blockers`. **This is not one bug. It is three, and only two of them are about concurrency.** Fix was deliberately kept out of scope for this session; this comment records the causes so the fix can be scoped properly. --- ### (c) The gate that says "Tests failed" over passing output — highest value, and the only one that is a lie Two things compose. **First, an ordering artefact.** `.iw/commands/test.scala:74-84` runs `mill core.test` first, then `mill dashboard.test`, and ANDs the two exit codes. It prints a section header before each and nothing after either. So the last thing on screen is always the *second* command's tail. A `core.test` that failed five minutes earlier leaves `dashboard.test SUCCESS` as the final visible line, then the hook's red banner. That alone explains the reported ordering, with no wrong exit code anywhere. **Second, and this is the real defect:** `runStreaming` cannot tell a failing command from one *we killed*, and says nothing either way. `core/adapters/Process.scala:99-121` passes `timeout = timeoutMs` (default **5 minutes**, line 24) to os-lib's `call(check = false, ...)`. In os-lib 0.11.6 that reaches `sub.join(timeout, shutdownGracePeriod)`, which sends SIGTERM, waits 100 ms, then SIGKILL. No exception is thrown — `check = false` short-circuits the throw. `call` returns a `CommandResult` whose `exitCode` is 143 or 137, and `Process.scala:120` returns that Int verbatim. **The caller sees a non-zero number with no way to know we killed it.** The repo already models the correct behaviour one function up: `ProcessAdapter.run` computes `val timedOut = result.exitCode == SigtermExitCode` (`Process.scala:78`, constant at line 41) and surfaces it on `ProcessResult`. `core/test/ProcessTest.scala` pins it. `runStreaming` drops the whole channel. So: `mill core.test` crossing 300 s — which needs no bug at all, only a cold Mill daemon plus a scoverage-instrumented compile (`build.mill:36`) plus a second worktree saturating the machine — is SIGTERMed by our own harness. `dashboard.test` then runs, passes in 10 s, prints SUCCESS, and `runUnitTests` returns false. Exactly the reported shape. I cannot prove from code alone which of the two produced the specific run: a silent timeout kill, or a genuine failure whose output scrolled away. **That is the point — today the two are indistinguishable, at the exit code and on screen.** *Hypothesis, unconfirmed:* Mill 1.1.5's launcher reads the daemon's exit code out of `out/mill-daemon/`, so a daemon dying after finishing the graph could also produce SUCCESS-then-nonzero. The check is `./mill dashboard.test; echo $?` under load. The timeout mechanism above needs no such assumption. --- ### (a) `CaskServerTest."GET /api/status shows correct worktree count"` **The shared resource is the TCP port, not the state file.** The state file is `${java.io.tmpdir}/iw-server-test-${Random.nextLong().abs}/state.json` (`CaskServerTest.scala:29-32`) — never the shared `~/.local/share/iw/server/state.json`. Collision there is not credible. Three facts compose into a silent cross-JVM hijack: 1. `findAvailablePort()` (`CaskServerTest.scala:74-78`) **closes the socket before returning the number.** Two JVMs can be handed the same freed ephemeral port. 2. **The loser's bind failure is swallowed.** `startTestServer` (`:43-47`) runs `CaskServer.start` on a bare `new Thread(...)` with no try/catch. Undertow throws a RuntimeException wrapping `BindException`; on that thread it reaches only the default uncaught handler — a stack trace in the log, and the test carries on. 3. **The readiness probe cannot tell servers apart.** `:50-58` polls `/health` and accepts any 200. `/health` is `ujson.Obj("status" -> "ok")` with no identity (`CaskServer.scala:769-771`). The winner answers 200, so the loser declares itself ready. The loser then PUTs `IWLE-111` and `IWLE-222` into the **winner's** server and reads `/api/status` back from it. `status()` (`CaskServer.scala:815-825`) returns `state.worktrees.size` with no pruning, so the count is the other JVM's. `worktreeCount` fails — and `port` on the next line still **passes**, because both servers were told the same number. That is why the failure looks inexplicable. *On the reported line 439:* at both `7a4fa367` and HEAD that line is blank; the `worktreeCount` assertion is at 457. The report either points at an exception out of the first PUT, or the line is slightly off. Either reading lands inside the same test and both are explained by "this test's server never owned its port." The itest suite retries (`CaskServerItest.scala:80-137`) and is mostly safe — but it swallows `case _: java.net.BindException => ()` (line 104) and also accepts any 200, so a foreign holder still reads as ready there too. The retry only rescues the case where nothing answers. --- ### (b) The seven scattered `not ok` lines in `issue create` / `open` / `rm` These suites isolate cwd, the tmux socket, the dashboard and plugins. They do **not** isolate `HOME` or `XDG_DATA_HOME`, and four resources leak: 1. **`/tmp/testproject-*` is a cross-run destructor.** Six teardowns glob it (`rm.bats:41`, `open.bats:41`, `start.bats:41`, `analyze.bats:42`, `open-prompt.bats:54`, `start-prompt.bats:54`). Two concurrent E2E runs delete each other's worktrees mid-test. `open.bats` and `rm.bats` are two of the suites named in the sighting. 2. **One bloop daemon per user.** Every `iw <cmd>` in every BATS test is `exec scala-cli run -q ...`. Confirmed on this machine: exactly one daemon, `-Xmx8g`, shared by all three checked-out worktrees. Per-worktree `.scala-build/` keeps the *projects* distinct; the daemon, its heap and its compile queue are not. 3. **`~/.cache/coursier`** and its lock files, shared by every mill and scala-cli invocation. 4. **A self-inflicted amplifier.** `runE2ETests` sets `IW_CORE_JAR` to `installDir / "build" / "iw-core.jar"` under a comment saying it avoids per-test jar rebuilds. That file is written only by `scripts/package-release.sh:79` into the release staging dir — **it never exists in a dev checkout.** Worse, the override *destroys* a good value: `iw-run` had already exported a valid `IW_CORE_JAR` before exec'ing the test command. Net effect: every one of ~190 BATS tests spawns a Mill launcher against `out/`. Any single Mill hiccup under load becomes `Error: Mill failed to resolve core.jar` → `iw` exit 1 → a red line in whichever suite was unlucky. That is precisely "7 not ok scattered across three unrelated suites, each green when run alone." --- ### What a fix would have to do, in order **(c) first — stop the tooling lying.** 1. `runStreaming` must detect the kill and return the existing `-1` sentinel rather than the signal code, and print one line naming what was killed. `SigtermExitCode` already exists at `Process.scala:41`. 2. `runUnitTests` must give the Mill invocations a build-appropriate timeout — `runE2ETests` and `runContractTests` already pass 10 minutes, so 5 minutes for a scoverage-instrumented `core.test` is an oversight, not a policy — and must name the culprit before returning. 3. `.git-hooks/pre-push:56-68` runs `./iw ./test unit && ./iw ./test compile`, so a unit failure never reaches compile and the banner cannot say which step failed. Run them separately and report the failing step. Do not weaken the gate. **(a) — make a test server prove it owns its port.** 4. Give `/health` an instance identity. Without it no readiness probe can tell "my server" from "someone else's server on the same number". 5. `startTestServer` must capture the startup throwable instead of dropping it, accept readiness only on its *own* instance id, retry with a fresh port on mismatch, and `fail(...)` with the captured `BindException` when attempts run out. `CaskServerItest.scala:80-137` is the retry skeleton to copy — but fix its two holes in the copy. Note the suite is `var`-free and the project bans `var`: write it recursively, not as the itest's `while`/`var` loop. **(b) — isolation.** 6. Stop globbing `/tmp/testproject-*`. Create sibling worktrees inside a per-test parent and `rm -rf` only that parent. Touches the tests asserting on the sibling path (`analyze.bats:49-50`, `start-prompt.bats:64-65`). 7. Stop overriding `IW_CORE_JAR` with a path that does not exist. Either resolve the real jar or pass through what `iw-run` already exported. The comment above it then becomes true, and ~190 Mill spawns per E2E run disappear. 8. The per-user bloop daemon and coursier cache stay shared by design. If cross-worktree E2E concurrency must be safe, that is a policy decision — the honest options are a machine-wide advisory lock on `iw ./test`, or accepting that concurrent E2E is unsupported. Items 6 and 7 are bugs on their own merits and are worth fixing regardless of the concurrency policy. --- *Diagnosis only, per the scope of this session. Claims are cited to `file:line`; the two places I could not prove are labelled as hypotheses.*

mph referenced this issue

2026-09-02 06:22:57 +00:00

Squash the batch-implement blockers: nine fixes for the phase gate, the CI gate and the review-state card #501

mph commented

2026-09-02 22:18:44 +00:00

Author

Owner

Follow-up from a real consumer hitting this, which sharpens fault (c) and adds a second defect beside it.

The kanon plugin added a PhaseOutcome.AwaitCI handler that shells out to ./iw ci-gate through ProcessAdapter.runStreaming(cmd, guardMs) and treated any exit that was not 0 or 3 as CI's verdict. With runStreaming returning a killed child's signal code verbatim, a CI wait outliving that guard was reported to the user as "ci-gate exited with code 143; CI did not go green" — the batch dying and blaming a healthy build. They have fixed it on their side by treating 143 and 137 as "the guard fired, call the gate again".

Two things that fix exposed:

1. SigtermExitCode is private, so a consumer cannot detect the case at all.
core/adapters/Process.scala:42 is private val SigtermExitCode = 143. A caller of runStreaming that wants to distinguish "we killed it" from "it failed" has no constant to compare against and must hardcode the magic numbers, which is exactly what the plugin now does. Whatever shape the fix takes, the timeout signal has to be reachable by callers — either surfaced on the return value, or the constant made public.

2. run's own timedOut misses SIGKILL.
Process.scala:76 is val timedOut = result.exitCode == SigtermExitCode, and SigtermExitCode is 143 only. os-lib sends SIGTERM, waits the grace period, then sends SIGKILL — a child that ignores SIGTERM, or is stopped, exits 137. So ProcessAdapter.run — the function that gets this right relative to runStreaming — still answers timedOut = false for a process it killed the hard way. The correct check covers both 143 and 137.

This is not a new fault so much as evidence that (c) is worse than "the harness is quiet about it": the missing channel propagates into consumers as confidently wrong error messages, and the two functions that should agree do not agree with each other either.

Follow-up from a real consumer hitting this, which sharpens fault (c) and adds a second defect beside it. The kanon plugin added a `PhaseOutcome.AwaitCI` handler that shells out to `./iw ci-gate` through `ProcessAdapter.runStreaming(cmd, guardMs)` and treated any exit that was not 0 or 3 as CI's verdict. With `runStreaming` returning a killed child's signal code verbatim, a CI wait outliving that guard was reported to the user as "ci-gate exited with code 143; CI did not go green" — the batch dying and blaming a healthy build. They have fixed it on their side by treating 143 and 137 as "the guard fired, call the gate again". Two things that fix exposed: **1. `SigtermExitCode` is private, so a consumer cannot detect the case at all.** `core/adapters/Process.scala:42` is `private val SigtermExitCode = 143`. A caller of `runStreaming` that wants to distinguish "we killed it" from "it failed" has no constant to compare against and must hardcode the magic numbers, which is exactly what the plugin now does. Whatever shape the fix takes, the timeout signal has to be reachable by callers — either surfaced on the return value, or the constant made public. **2. `run`'s own `timedOut` misses SIGKILL.** `Process.scala:76` is `val timedOut = result.exitCode == SigtermExitCode`, and `SigtermExitCode` is 143 only. os-lib sends SIGTERM, waits the grace period, then sends SIGKILL — a child that ignores SIGTERM, or is stopped, exits 137. So `ProcessAdapter.run` — the function that gets this right relative to `runStreaming` — still answers `timedOut = false` for a process it killed the hard way. The correct check covers both 143 and 137. This is not a new fault so much as evidence that (c) is worse than "the harness is quiet about it": the missing channel propagates into consumers as confidently wrong error messages, and the two functions that should agree do not agree with each other either.