mirror of
https://github.com/coder/coder.git
synced 2026-09-01 14:53:15 +08:00
Bobby Ho
511c3cddc0
## Summary Partial fix for the flake in [PLAT-251](https://linear.app/codercom/issue/PLAT-251/flake-test-go-pg-macos-job-timeoutcancelled) / [coder/internal#1365](https://github.com/coder/internal/issues/1365) (`test-go-pg (macos-latest)` timing out and getting cancelled after 25 minutes). ## Problem `testutil/expecter.Expecter` drains a command's stdout/stderr through `io.Copy` into an internal buffer, but it also teed every write through a **second, independent unbuffered `io.Pipe()`**, read by a `bufio.Scanner`, purely to produce human-readable debug logs: ```go logr, logw := io.Pipe() w := io.MultiWriter(logw, out) // out never blocks; logw is a second unbuffered pipe go func() { io.Copy(w, r) }() // drains the command's real stdout/stderr go func() { bufio.NewScanner(logr).Scan() ... }() // only reads when scheduled ``` `io.MultiWriter` only returns once **every** writer succeeds. If the scanner goroutine is ever delayed (GC pause, scheduler contention under CI's `-parallel=16` test config), the write into `logw` blocks, which blocks the `io.Copy` write, which stops it from reading the command's actual output pipe, which means the **command's own write can never complete either**, since nobody is left reading it. Nothing on this path has a timeout, so once wedged it stays wedged until `go test`'s own `-timeout 20m` kills the whole binary. This reproduced locally in `TestConfigSSH_FileWriteAndOptionsFlow` under the macOS CI job's exact parallelism, stuck writing a routine "executable not in `$PATH`" warning (`cli.currentBinPath`) that the test wasn't actively reading at that instant. It's a flake, not a deterministic failure, because under light load the scanner always keeps up trivially. ### Race condition ```mermaid sequenceDiagram participant TG as Test goroutine participant CmdG as Command goroutine<br/>(inv.Run) participant P1 as Pipe 1<br/>(inv.Stdout) participant Copy as io.Copy goroutine participant P2 as Pipe 2<br/>(logw/logr, debug logging only) participant Scan as Scanner goroutine participant Buf as stdbuf (out)<br/>unbounded, never blocks CmdG->>P1: Write(warning output) P1-->>Copy: Read() unblocks Copy->>P2: MultiWriter step 1: write to logw Copy->>Buf: MultiWriter step 2: write to out rect rgb(255, 230, 230) Note over Scan: Under heavy parallel test load,<br/>Scan()'s next Read() is delayed P2--xCopy: Write(logw) blocks: nobody reading yet end Copy--xP1: Read() no longer called: Copy is stuck writing to P2 CmdG--xP1: Write() can't complete either: nobody reads Pipe 1 Note over CmdG: Command write blocks FOREVER<br/>(confirmed: 17-18 min in a goroutine dump) TG->>TG: ExpectMatch times out (got ""), fails the test Note over TG,CmdG: Test goroutine exits, but CmdG is<br/>orphaned and permanently blocked until<br/>go test's own -timeout kills the binary ``` ## Fix Remove the second pipe. `io.Copy` now writes only to the unbounded, non-blocking `stdbuf`. Debug logging is forwarded via a **bounded, non-blocking channel** instead of a second unbuffered pipe: a full channel just drops the chunk rather than propagating backpressure. This works because the only thing the command's real output pipe depends on is `io.Copy(out, r)`, and `out.Write()` can never block, so `io.Copy` always keeps calling `Read()`, so the command's write always has an active reader. Debug logging becomes provably unable to backpressure the command under test, since losing an occasional log line under extreme load is an acceptable tradeoff, unlike losing a whole CI job to a silent deadlock. The fix lives in the shared harness rather than in `cli/configssh.go` because the warning it's tripping over is legitimate, unrelated product behavior; every other test using this harness that happens to emit output the test isn't actively matching at that instant was exposed to the same bug. **Note:** this addresses one of two distinct root causes bundled under PLAT-251. The other is a Depot `GOCACHEPROG` shutdown hang in CI infrastructure (outside this repo, previously diagnosed by a maintainer on the Feb 2026 incident), which this change cannot affect. Locally this fix measurably improves things, but a residual, load-dependent hang was still observed under extreme synthetic contention on a shared dev machine; watching several real CI runs is the next step before considering the flake fully resolved. --------- Co-authored-by: Cian Johnston <cian@coder.com>