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

mph commented

2026-08-27 10:33:37 +00:00

Owner

Found triaging IW-437 (observed closing out phase 2).

SYMPTOM. Two consecutive ./iw ./test runs over the same unchanged tree failed DIFFERENT tests, and every failing test passed when its file was run alone.

Run 1: test/open.bats:53 and test/open-prompt.bats:118
both on tmux -L "$TMUX_SOCKET" has-session -t ... returning non-zero
Run 2: test/analyze.bats:54
on the delegated iw start exiting non-zero

bats test/open.bats test/open-prompt.bats -> green
bats test/analyze.bats -> green
(all seven cases)

RULED OUT.

Not the temp-directory race. .iw/commands/test.scala:190-196 already runs each .bats file in its own bats process, sequentially.
Not a socket collision. Each file makes its own socket, TMUX_SOCKET="iw-test-$$" (e.g. test/start.bats:6).

NOT DIAGNOSED. The shape - an assertion immediately after a command that spawns a tmux session, failing only under a full-suite run - points at a race between session creation and the assertion that reads it. That is a hypothesis, not a finding. Please diagnose rather than paper over it.

WHY IT MATTERS BEYOND THE ANNOYANCE. A red ./iw ./test in this repository is not by itself evidence that the change under test broke something. That cuts both ways: someone who re-runs until green can equally well be re-running past a real regression. Until this is fixed, an E2E failure has to be confirmed by running its file alone before it is attributed to the diff - and that is exactly the kind of instruction that gets skipped.

./mill core.test (186/186) is deterministic across every run; the non-determinism is confined to the tmux-dependent BATS suites.

GOAL. A red E2E run means what it says.

Found triaging IW-437 (observed closing out phase 2). SYMPTOM. Two consecutive ./iw ./test runs over the same unchanged tree failed DIFFERENT tests, and every failing test passed when its file was run alone. Run 1: test/open.bats:53 and test/open-prompt.bats:118 both on `tmux -L "$TMUX_SOCKET" has-session -t ...` returning non-zero Run 2: test/analyze.bats:54 on the delegated `iw start` exiting non-zero bats test/open.bats test/open-prompt.bats -> green bats test/analyze.bats -> green (all seven cases) RULED OUT. - Not the temp-directory race. .iw/commands/test.scala:190-196 already runs each .bats file in its own bats process, sequentially. - Not a socket collision. Each file makes its own socket, TMUX_SOCKET="iw-test-$$" (e.g. test/start.bats:6). NOT DIAGNOSED. The shape - an assertion immediately after a command that spawns a tmux session, failing only under a full-suite run - points at a race between session creation and the assertion that reads it. That is a hypothesis, not a finding. Please diagnose rather than paper over it. WHY IT MATTERS BEYOND THE ANNOYANCE. A red ./iw ./test in this repository is not by itself evidence that the change under test broke something. That cuts both ways: someone who re-runs until green can equally well be re-running past a real regression. Until this is fixed, an E2E failure has to be confirmed by running its file alone before it is attributed to the diff - and that is exactly the kind of instruction that gets skipped. ./mill core.test (186/186) is deterministic across every run; the non-determinism is confined to the tmux-dependent BATS suites. GOAL. A red E2E run means what it says.

mph commented

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

Author

Owner

Two more instances, from IW-476. I opened #489 for these before finding this issue; #489 is closed as a duplicate and its content is folded in here.

The dashboard suite flakes too, not only the tmux BATS suites. This issue says ./mill core.test is deterministic and confines the non-determinism to tmux-dependent BATS. dashboard.test belongs on the list as well:

CaskServerTest."GET /api/status shows correct worktree count"
failed at dashboard/jvm/test/src/CaskServerTest.scala:439
green on the next run, unchanged tree

That test binds a real port and writes a state file, so it has its own shared-resource surface independent of tmux.

A correlated condition worth testing against the race hypothesis. Both IW-476 sightings happened while a second iw-cli worktree was running batch-implement on the same host. If the cause is a race between session creation and the assertion that reads it, concurrent load from another worktree is a plausible amplifier — and a cheap way to reproduce on demand rather than waiting for it.

The E2E sighting: ./iw ./test e2e exited 1 with 7 not ok lines across the issue create, open and rm suites; bats test/rm.bats alone passed both its tests; the next full run returned exit 0 with 190 ok.

A third shape, possibly separate — please treat it as its own question. Pushing the IW-476 feature branch on 2026-09-01, the pre-push hook printed:

241/241, SUCCESS] .../mill dashboard.test 10s

PUSH BLOCKED: Tests failed

The hook's step 3 is if ./iw ./test unit && ./iw ./test compile. No ./iw ./test compile output appeared at all, so ./iw ./test unit returned non-zero while printing a passing suite. Run standalone on the same tree both exit 0, and bash .git-hooks/pre-push run directly passes. The identical push retried immediately and succeeded with no change.

This one is not explained by BATS non-determinism — the hook's unit step runs Mill only. It may be a separate fault in how .iw/commands/test.scala reports its exit code. Related: #466 (./iw ./test green on code the hook rejects) and #465 (a failed push drops the hook's stderr).

Recorded as IW-476 LESSONS.md entry 10.

Two more instances, from IW-476. I opened #489 for these before finding this issue; #489 is closed as a duplicate and its content is folded in here. **The dashboard suite flakes too, not only the tmux BATS suites.** This issue says `./mill core.test` is deterministic and confines the non-determinism to tmux-dependent BATS. `dashboard.test` belongs on the list as well: CaskServerTest."GET /api/status shows correct worktree count" failed at dashboard/jvm/test/src/CaskServerTest.scala:439 green on the next run, unchanged tree That test binds a real port and writes a state file, so it has its own shared-resource surface independent of tmux. **A correlated condition worth testing against the race hypothesis.** Both IW-476 sightings happened while a *second iw-cli worktree* was running `batch-implement` on the same host. If the cause is a race between session creation and the assertion that reads it, concurrent load from another worktree is a plausible amplifier — and a cheap way to reproduce on demand rather than waiting for it. The E2E sighting: `./iw ./test e2e` exited 1 with 7 `not ok` lines across the `issue create`, `open` and `rm` suites; `bats test/rm.bats` alone passed both its tests; the next full run returned exit 0 with 190 ok. **A third shape, possibly separate — please treat it as its own question.** Pushing the IW-476 feature branch on 2026-09-01, the `pre-push` hook printed: 241/241, SUCCESS] .../mill dashboard.test 10s PUSH BLOCKED: Tests failed The hook's step 3 is `if ./iw ./test unit && ./iw ./test compile`. No `./iw ./test compile` output appeared at all, so `./iw ./test unit` returned non-zero while printing a passing suite. Run standalone on the same tree both exit 0, and `bash .git-hooks/pre-push` run directly passes. The identical push retried immediately and succeeded with no change. This one is not explained by BATS non-determinism — the hook's unit step runs Mill only. It may be a separate fault in how `.iw/commands/test.scala` reports its exit code. Related: #466 (`./iw ./test` green on code the hook rejects) and #465 (a failed push drops the hook's stderr). Recorded as IW-476 LESSONS.md entry 10.

mph referenced this issue

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

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

mph referenced this issue

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

Hooks and CI read a crashed tool as a finding, and print --no-verify as the remedy #497

mph commented

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

Author

Owner

Two more sightings from IW-436, both with a named suspect. Recording them here since #489 was merged in.

1. `project-commands-execute.bats` test 2 (2026-08-29, IW-436 Phase 1 verification)

./iw ./test exited 1 with a single failure:

not ok 2 same name in both namespaces dispatches to the right one based on ./ prefix
# (in test file test/project-commands-execute.bats, line 99)
#   `[ "$status" -eq 0 ]' failed

Line 99 is the first assertion after run ./iw-run dualname — the shared command invocation returned non-zero. bats test/project-commands-execute.bats alone passed 3/3, and a second full ./iw ./test passed with no not ok lines.

Suspect (hypothesis, not reproduced): the test writes two scala-cli command files that declare the same @main name (dualname) in two namespaces, .iw-install/commands/ and .iw/commands/, and compiles both in the same run. A race on scala-cli's shared build cache between two concurrent compilations of the same main class would explain it.

Blocker to diagnosing it: the assertion checks only $status, and the failure output does not include $output, so no scala-cli error text was captured. First move is to assert on $output as well, so the next occurrence is readable.

2. `CaskServerTest` races on its own port (2026-09-01, pushing IW-436 phase-04)

git push was blocked by the pre-push hook with one failure:

241/241, 1 FAILED] ./mill dashboard.test 13s
241] [error] dashboard.test.testForked 1 tests failed:
  iw.core.infrastructure.CaskServerTest.GET /worktrees/:issueId/card response
  contains detail page link and tracker section

Named mechanism: the test allocates a port with findAvailablePort() and then starts Undertow on it (dashboard/jvm/test/src/CaskServerTest.scala:1629-1633). The gap between choosing the port and binding it is a TOCTOU window, and the full-suite log shows dozens of io.undertow.Undertow start lines inside the same three seconds — so two forked test classes can pick the same free port.

Confirmed as infrastructure, not a regression: ./mill dashboard.test alone returned 241/241 immediately afterwards, the following git push passed every check, and the failing case never reaches the code that phase changed.

Concrete fix available now: bind the server to port 0 and read back the assigned port, or retry the bind on BindException. Worth auditing the other tests that call findAvailablePort() the same way.

Recorded during IW-436; see project-management/issues/IW-436/LESSONS.md entries 4 and 13.

Two more sightings from IW-436, both with a named suspect. Recording them here since #489 was merged in. ## 1. `project-commands-execute.bats` test 2 (2026-08-29, IW-436 Phase 1 verification) `./iw ./test` exited 1 with a single failure: ``` not ok 2 same name in both namespaces dispatches to the right one based on ./ prefix # (in test file test/project-commands-execute.bats, line 99) # `[ "$status" -eq 0 ]' failed ``` Line 99 is the first assertion after `run ./iw-run dualname` — the *shared* command invocation returned non-zero. `bats test/project-commands-execute.bats` alone passed 3/3, and a second full `./iw ./test` passed with no `not ok` lines. **Suspect (hypothesis, not reproduced):** the test writes two scala-cli command files that declare the **same `@main` name** (`dualname`) in two namespaces, `.iw-install/commands/` and `.iw/commands/`, and compiles both in the same run. A race on scala-cli's shared build cache between two concurrent compilations of the same main class would explain it. **Blocker to diagnosing it:** the assertion checks only `$status`, and the failure output does not include `$output`, so no scala-cli error text was captured. First move is to assert on `$output` as well, so the next occurrence is readable. ## 2. `CaskServerTest` races on its own port (2026-09-01, pushing IW-436 phase-04) `git push` was blocked by the pre-push hook with one failure: ``` 241/241, 1 FAILED] ./mill dashboard.test 13s 241] [error] dashboard.test.testForked 1 tests failed: iw.core.infrastructure.CaskServerTest.GET /worktrees/:issueId/card response contains detail page link and tracker section ``` **Named mechanism:** the test allocates a port with `findAvailablePort()` and *then* starts Undertow on it (`dashboard/jvm/test/src/CaskServerTest.scala:1629-1633`). The gap between choosing the port and binding it is a TOCTOU window, and the full-suite log shows dozens of `io.undertow.Undertow start` lines inside the same three seconds — so two forked test classes can pick the same free port. Confirmed as infrastructure, not a regression: `./mill dashboard.test` alone returned 241/241 immediately afterwards, the following `git push` passed every check, and the failing case never reaches the code that phase changed. **Concrete fix available now:** bind the server to port 0 and read back the assigned port, or retry the bind on `BindException`. Worth auditing the other tests that call `findAvailablePort()` the same way. --- Recorded during IW-436; see `project-management/issues/IW-436/LESSONS.md` entries 4 and 13.

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 referenced this issue from a commit

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

workflow: Triage lessons for IW-436

mph referenced this issue

2026-09-01 15:36:57 +00:00

IW-436: review-state CLI — fix five flag-parsing and update-semantics defects #499

mph commented

2026-09-01 19:46:01 +00:00

Author

Owner

The pre-push anomaly reported above is diagnosed, and the cause is Mill client concurrency rather than anything in the tests.

The failing push, with the step named. The hook's dashboard step printed:

=== Running Dashboard Unit Tests ===
/home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test
/home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test
/home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test
/home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test
Another Mill process with PID 3741791 is running 'dashboard.test', waiting for it to be done...
java.lang.IllegalStateException: Worker wire broken, worker likely crashed. Connection DaemonRpcClient

So ./iw ./test unit exits non-zero because Mill throws, not because a test fails — and the hook's box then prints PUSH BLOCKED: Tests failed. That is the misreporting filed as #497. The competing PID had already exited when checked, so the contention is transient.

The daemon's own log names the mechanism. out/mill-daemon/server.log — which is append-only across daemon restarts, unlike out/mill-daemon/stderr — shows:

2 active connections
client interrupted while server was executing command
upickle.core.TraceVisitor$TraceException
Caused by: ujson.ParseException: expected json value got \"G\" at index 0
        at mill.rpc.MillRpcWireTransport.readAndTryToParse(MillRpcWireTransport.scala:57)

A second client connects, one client leaves mid-command, the daemon reads a partial message as the next request, fails to parse it and exits. The client then prints "Worker wire broken, worker likely crashed".

The same signature covers the older sightings. The log retains 2026-08-29 00:54-00:59, when IW-476's unit suite was failing repeatedly: the same client interrupted / TraceException pair, across several daemon pids in a row. That is why ./mill shutdown appeared not to help — each fresh daemon was re-killed within seconds — and why --no-daemon worked, since it has no long-lived RPC wire.

Why this belongs on this issue. It supports the concurrent-load hypothesis for the suite flakes too: two Mill clients against one daemon is a shared-resource collision of exactly the kind this issue is looking for, and it is reproducible on demand by running two Mill tasks in the same out/ at once — cheaper than waiting for the BATS races.

Whether the tmux BATS non-determinism has the same cause is not established. dashboard.test and the hook path go through Mill; the BATS suites do not.

Recovery guidance is now in docs/testing.md under "When the Mill daemon dies".

The `pre-push` anomaly reported above is diagnosed, and the cause is Mill client concurrency rather than anything in the tests. **The failing push, with the step named.** The hook's dashboard step printed: === Running Dashboard Unit Tests === /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test /home/mph/Devel/iw/iw-cli-IW-476/mill dashboard.test Another Mill process with PID 3741791 is running 'dashboard.test', waiting for it to be done... java.lang.IllegalStateException: Worker wire broken, worker likely crashed. Connection DaemonRpcClient So `./iw ./test unit` exits non-zero because Mill throws, not because a test fails — and the hook's box then prints `PUSH BLOCKED: Tests failed`. That is the misreporting filed as #497. The competing PID had already exited when checked, so the contention is transient. **The daemon's own log names the mechanism.** `out/mill-daemon/server.log` — which is append-only across daemon restarts, unlike `out/mill-daemon/stderr` — shows: 2 active connections client interrupted while server was executing command upickle.core.TraceVisitor$TraceException Caused by: ujson.ParseException: expected json value got \"G\" at index 0 at mill.rpc.MillRpcWireTransport.readAndTryToParse(MillRpcWireTransport.scala:57) A second client connects, one client leaves mid-command, the daemon reads a partial message as the next request, fails to parse it and exits. The client then prints \"Worker wire broken, worker likely crashed\". **The same signature covers the older sightings.** The log retains 2026-08-29 00:54-00:59, when IW-476's unit suite was failing repeatedly: the same `client interrupted` / `TraceException` pair, across several daemon pids in a row. That is why `./mill shutdown` appeared not to help — each fresh daemon was re-killed within seconds — and why `--no-daemon` worked, since it has no long-lived RPC wire. **Why this belongs on this issue.** It supports the concurrent-load hypothesis for the suite flakes too: two Mill clients against one daemon is a shared-resource collision of exactly the kind this issue is looking for, and it is reproducible on demand by running two Mill tasks in the same `out/` at once — cheaper than waiting for the BATS races. Whether the tmux BATS non-determinism has the same cause is *not* established. `dashboard.test` and the hook path go through Mill; the BATS suites do not. Recovery guidance is now in `docs/testing.md` under \"When the Mill daemon dies\".

mph referenced this issue from a commit

2026-09-03 05:43:37 +00:00

fix(process): make a killed child distinguishable from a failing one

mph referenced this issue

2026-09-03 05:43:45 +00:00

Record the card's position on write, tell a killed process from a failing one, and identify a phase's pull request by its branch #506

mph commented

2026-09-03 05:55:44 +00:00

Author

Owner

Fault (c) is fixed on main as of cfe98763 (PR #506). Faults (a) and (b) are untouched and stay here.

What went in. ProcessAdapter.killedBySignal names both 143 and 137 and is public; run's timedOut uses it, so a child that ignored SIGTERM and had to be forced is no longer reported as a child that failed. runStreaming keeps returning the signal code — a consumer already matches on it — and prints one line on stderr naming the command it killed and the limit it waited. runUnitTests gives each Mill suite the ten minutes the E2E and contract suites already had, names the suite that did not pass, and says when a suite was killed rather than calling it failed. The pre-push hook runs unit and compile as separate steps so the banner names the one that blocked the push.

A new sighting of the flake class, 2026-09-03. ./iw ./test unit red on IssuePollerTest."a read that throws leaves the poller able to read again". Green alone, and green on the next full dashboard.test with no change. That test does no I/O of its own, which puts it with (a) rather than (b): the suite shares a JVM, and something in it is order- or timing-dependent.

A fixture hazard found while writing the tests for #467, worth its own issue. A PhasePrHarnessTest case that reaches CiGate.poll with a forge head sha that matches no run in the scripted snapshot does not fail — it spins in CiGate.loop, heartbeating the card, indefinitely. FakeClock does not advance on its own, so the wait budget that bounds the real gate never expires in a harness test. Twenty minutes of a test JVM at 190% CPU before it was killed by hand. The gate is right; the fixture gives a mistyped test no way to end.

Fault (c) is fixed on `main` as of `cfe98763` (PR #506). Faults (a) and (b) are untouched and stay here. **What went in.** `ProcessAdapter.killedBySignal` names both 143 and 137 and is public; `run`'s `timedOut` uses it, so a child that ignored SIGTERM and had to be forced is no longer reported as a child that failed. `runStreaming` keeps returning the signal code — a consumer already matches on it — and prints one line on stderr naming the command it killed and the limit it waited. `runUnitTests` gives each Mill suite the ten minutes the E2E and contract suites already had, names the suite that did not pass, and says when a suite was killed rather than calling it failed. The `pre-push` hook runs `unit` and `compile` as separate steps so the banner names the one that blocked the push. **A new sighting of the flake class, 2026-09-03.** `./iw ./test unit` red on `IssuePollerTest."a read that throws leaves the poller able to read again"`. Green alone, and green on the next full `dashboard.test` with no change. That test does no I/O of its own, which puts it with (a) rather than (b): the suite shares a JVM, and something in it is order- or timing-dependent. **A fixture hazard found while writing the tests for #467, worth its own issue.** A `PhasePrHarnessTest` case that reaches `CiGate.poll` with a forge head sha that matches no run in the scripted snapshot does not fail — it spins in `CiGate.loop`, heartbeating the card, indefinitely. `FakeClock` does not advance on its own, so the wait budget that bounds the real gate never expires in a harness test. Twenty minutes of a test JVM at 190% CPU before it was killed by hand. The gate is right; the fixture gives a mistyped test no way to end.

mph referenced this issue from a commit

2026-09-03 07:22:16 +00:00

fix(test): make a test server prove it owns its port before a test uses it

mph referenced this issue from a commit

2026-09-03 07:22:16 +00:00

fix(test): stop the E2E suites deleting each other's worktrees

mph referenced this issue

2026-09-03 07:22:41 +00:00

Make the forge the authority on a branch's pull request, and stop the test suites lying about themselves #511

mph referenced this issue from a commit

2026-09-03 07:46:32 +00:00

fix: act on the code review of this batch

mph referenced this issue

2026-09-03 08:12:31 +00:00

format job crashes the formatter instead of checking formatting #512

mph referenced this issue

2026-09-14 10:13:02 +00:00

start.bats "the tmux session does not carry iw's internal plumbing" fails at baseline: IW_HOME missing from the captured pane env #556

claude commented

2026-10-16 00:35:43 +00:00

Member

Intake: needs-human
Workflow: diagnostic
Reason: G7 a standing [fix] finding after the one correction: the analysis gives the tmux teardown fix to six suites, but nine have it (port-slot, service and attach-unbounded are missing)
Analysis: project-management/issues/IW-468/analysis.md on branch IW-468

Intake: needs-human Workflow: diagnostic Reason: G7 a standing [fix] finding after the one correction: the analysis gives the tmux teardown fix to six suites, but nine have it (port-slot, service and attach-unbounded are missing) Analysis: project-management/issues/IW-468/analysis.md on branch IW-468

claude added the

needs-human

label

2026-10-16 00:35:43 +00:00

Rows
Columns

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

1. project-commands-execute.bats test 2 (2026-08-29, IW-436 Phase 1 verification)

2. CaskServerTest races on its own port (2026-09-01, pushing IW-436 phase-04)

1. `project-commands-execute.bats` test 2 (2026-08-29, IW-436 Phase 1 verification)

2. `CaskServerTest` races on its own port (2026-09-01, pushing IW-436 phase-04)