flake: TestRoutingPodEndToEnd port-wait deadline exceeded under load #15

New Issue

mathias · 2026-05-18T15:23:58Z

mathias commented

2026-05-18 15:23:58 +00:00

Symptom

TestRoutingPodEndToEnd in cmd/routing/main_test.go intermittently fails at line 58 with:

Error: Received unexpected error: context deadline exceeded
Test: TestRoutingPodEndToEnd

The 5s deadline is waitForPort(t, "127.0.0.1:33310", 5*time.Second) (main_test.go:58, 85–104) waiting for the freshly-built routing binary to bind its HTTP listener.

Observed during #14 e2e work (2026-05-18)

Failed twice in a row:

task check (full project test suite with -race -count=1)
go test -race -count=1 ./cmd/routing/... immediately after

Both at ~5.23s. Then it stopped reproducing — 5/5 passes in isolation with -race -count=1, including with cold test cache (go clean -testcache).

Pattern: triggered under load, not by code.

Likely causes (untriaged)

go build cost inside the test. buildRouting(t) compiles ./cmd/routing into a temp dir. Cold build + -race instrumentation can take >5s on a loaded machine. Running the produced binary directly outside the test starts in <2s, so the bottleneck is build, not bind.
Port 33310 contention. Hardcoded port; a previous test or stray process could hold it briefly. ss -tlnp | grep 33310 was empty when checked, but a previous TIME_WAIT or another test could collide.
osPath() returns empty PATH. Lines 116–122 iterate exec.Command("env").Env which is the child Cmd's env (nil unless set), not the parent's. The test passes PATH= (empty) to the routing subprocess. The binary doesn't need PATH at runtime (statically linked Go), so this is probably benign — but it is incorrect and worth fixing while we're here.

Proposed fix

Cheap, low risk:

Increase waitForPort deadline to 30s (cost only paid on failure paths).
Replace hardcoded port 33310 with a net.Listen("tcp", ":0") random port allocation passed via ROUTING_PORT env.
Fix osPath() to read parent process env via os.Getenv("PATH") (or just drop the explicit PATH= and rely on cmd.Env inheriting).

Acceptance criteria

go test -race -count=10 ./cmd/routing/... is green
task check is green across 3 consecutive runs
Port no longer hardcoded
osPath() either correct or removed

References

cmd/routing/main_test.go:30–80 — test body
cmd/routing/main_test.go:85–104 — waitForPort
cmd/routing/main_test.go:116–122 — osPath
Surfaced during #14 verification (commit 937355c).

## Symptom `TestRoutingPodEndToEnd` in `cmd/routing/main_test.go` intermittently fails at line 58 with: ``` Error: Received unexpected error: context deadline exceeded Test: TestRoutingPodEndToEnd ``` The 5s deadline is `waitForPort(t, "127.0.0.1:33310", 5*time.Second)` (main_test.go:58, 85–104) waiting for the freshly-built routing binary to bind its HTTP listener. ## Observed during #14 e2e work (2026-05-18) Failed twice in a row: 1. `task check` (full project test suite with `-race -count=1`) 2. `go test -race -count=1 ./cmd/routing/...` immediately after Both at ~5.23s. Then it stopped reproducing — 5/5 passes in isolation with `-race -count=1`, including with cold test cache (`go clean -testcache`). Pattern: triggered under load, not by code. ## Likely causes (untriaged) 1. **`go build` cost inside the test.** `buildRouting(t)` compiles `./cmd/routing` into a temp dir. Cold build + `-race` instrumentation can take >5s on a loaded machine. Running the produced binary directly outside the test starts in <2s, so the bottleneck is build, not bind. 2. **Port 33310 contention.** Hardcoded port; a previous test or stray process could hold it briefly. `ss -tlnp | grep 33310` was empty when checked, but a previous TIME_WAIT or another test could collide. 3. **`osPath()` returns empty PATH.** Lines 116–122 iterate `exec.Command("env").Env` which is the *child* Cmd's env (nil unless set), not the parent's. The test passes `PATH=` (empty) to the routing subprocess. The binary doesn't need PATH at runtime (statically linked Go), so this is probably benign — but it is incorrect and worth fixing while we're here. ## Proposed fix Cheap, low risk: - Increase `waitForPort` deadline to 30s (cost only paid on failure paths). - Replace hardcoded port `33310` with a `net.Listen("tcp", ":0")` random port allocation passed via `ROUTING_PORT` env. - Fix `osPath()` to read parent process env via `os.Getenv("PATH")` (or just drop the explicit `PATH=` and rely on `cmd.Env` inheriting). ## Acceptance criteria - [ ] `go test -race -count=10 ./cmd/routing/...` is green - [ ] `task check` is green across 3 consecutive runs - [ ] Port no longer hardcoded - [ ] `osPath()` either correct or removed ## References - `cmd/routing/main_test.go:30–80` — test body - `cmd/routing/main_test.go:85–104` — `waitForPort` - `cmd/routing/main_test.go:116–122` — `osPath` - Surfaced during #14 verification (commit `937355c`).

mathias referenced this issue from a commit

2026-05-18 18:00:20 +00:00

test(routing): de-flake TestRoutingPodEndToEnd

mathias closed this issue

2026-05-18 18:00:20 +00:00

mathias commented

2026-05-18 18:00:34 +00:00

Fixed in fe18e4e.

Root cause (confirmed)

All three suspects from the issue body played a role:

Hardcoded port 33310 — primary trigger. Under task check parallel package execution another test or stray process could hold the port long enough that the routing binary bound it late or failed Listen. Now freePort(t) grabs :0, releases, passes the OS-assigned port via ROUTING_PORT.
5s waitForPort deadline — too tight when go build -race runs cold under load. Bumped to 30s; only paid in failure mode.
osPath() always returned empty — iterating exec.Command("env").Env reads the child Cmd's env (nil), not the parent's. The binary worked anyway (static Go), but the helper was a no-op masquerading as PATH inheritance. Replaced with explicit PATH= + HOME= via os.Getenv.

Why not `os.Environ()` for full inheritance

Tried that first. It leaked ROUTING_MCP_TOKEN from my shell into the test subprocess, flipping the routing pod into bearer-auth-required mode → all calls 401 unauthorized. Explicit minimal env keeps the test hermetic.

Verification

$ go clean -testcache && go test -race -count=10 ./cmd/routing/...
ok  github.com/mathiasbq/supervisor/cmd/routing  3.414s

$ task check   # ran 3 times consecutively
✓ context: canonical and adapters are in sync
0 issues. 0 issues. ok across all packages.
No vulnerabilities found.

Diff: +28/-16, single file cmd/routing/main_test.go.

Closing.

Fixed in `fe18e4e`. ### Root cause (confirmed) All three suspects from the issue body played a role: 1. **Hardcoded port 33310** — primary trigger. Under `task check` parallel package execution another test or stray process could hold the port long enough that the routing binary bound it late or failed `Listen`. Now `freePort(t)` grabs `:0`, releases, passes the OS-assigned port via `ROUTING_PORT`. 2. **5s `waitForPort` deadline** — too tight when `go build -race` runs cold under load. Bumped to 30s; only paid in failure mode. 3. **`osPath()` always returned empty** — iterating `exec.Command("env").Env` reads the *child* `Cmd`'s env (nil), not the parent's. The binary worked anyway (static Go), but the helper was a no-op masquerading as PATH inheritance. Replaced with explicit `PATH=` + `HOME=` via `os.Getenv`. ### Why not `os.Environ()` for full inheritance Tried that first. It leaked `ROUTING_MCP_TOKEN` from my shell into the test subprocess, flipping the routing pod into bearer-auth-required mode → all calls `401 unauthorized`. Explicit minimal env keeps the test hermetic. ### Verification ``` $ go clean -testcache && go test -race -count=10 ./cmd/routing/... ok github.com/mathiasbq/supervisor/cmd/routing 3.414s $ task check # ran 3 times consecutively ✓ context: canonical and adapters are in sync 0 issues. 0 issues. ok across all packages. No vulnerabilities found. ``` Diff: +28/-16, single file `cmd/routing/main_test.go`. Closing.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: mathias/hyperguild#15

flake: TestRoutingPodEndToEnd port-wait deadline exceeded under load #15