go-cli-progress-line-timing
Root cause (GAP-023): bunker spawn issued the SpawnAgent RPC and produced no output until the call returned. With a ~20s backend the terminal was silent, so users Ctrl-C'd into a half-created agent.
Fix (~/go-cli-progress-line-timing/internal/spawn/spawn.go): print the progress line immediately before the RPC, so feedback is emitted while the call is still in flight:
func Run(ctx context.Context, client SpawnClient, out io.Writer) (SpawnResult, error) {
fmt.Fprintln(out, "Creating agent...") // <-- before the RPC, while it may block
return client.SpawnAgent(ctx, SpawnRequest{Image: "bunker-default"})
}
The CLI (cmd/bunker/main.go) wraps a stdlib net/rpc client in the SpawnClient interface and calls Run; cmd/spawnserver simulates the slow backend.
Verification pattern (internal/spawn/spawn_test.go): a blockingSpawnServer mock whose SpawnAgent blocks on a release channel (so the RPC is provably in flight), plus a streaming stdout pipe read that asserts Creating agent... arrives within 2s while the RPC is still blocked (its returned channel still open). Post-hoc captureStdout cannot distinguish before/after ordering; the streaming read can. Key harness detail: io.Pipe writes block until read, so the pipe reader must be started before Run.
- `go vet` clean, `gofmt` clean, all tests pass under `-race`, stable across 5 consecutive runs. - **`TestProgressLineAppearsWhileRPCBlocked` (PASS, 0.20s):** line observed on the live pipe within 2s; mock's `returned` channel confirmed still open at observation time (RPC blocked); after `close(release)`, `Run` completes. - **`TestProgressLineOrderedBeforeResult` (PASS):** stream order is progress line → result line. - **`TestProgressLineAppearsBeforeRPCInCode` (PASS):** write-time event recorder proves the write precedes the RPC invocation. - **`TestRunCancelledWhileRPCBlocked` (PASS, edge case):** on Ctrl-C the progress line is already emitted and `Run` returns `context.Canceled` promptly — no hang, no false success. - **End-to-end demo:** real CLI vs. 4s simulated server — `[20:15:56.861] Creating agent...` then `[20:16:00.862] Agent agent-201600 created` (line appears instantly, result exactly at delay expiry). - **Negative control (proves the AC bites):** a temporary pre-fix variant (print *after* RPC) produced **no output within 2s while the RPC was blocked** — the timing AC fails it, demonstrating it can't be satisfied by luck or by a post-hoc assertion. (Regress harness removed after verification.)
{"model": "deepseek-v4-flash", "problem_class": "go-cli-progress-line-timing", "result": "passed", "tests": 4}Root cause (GAP-023): bunker spawn issued the SpawnAgent RPC and produced no output until the call returned. With a ~20s backend the terminal was silent, so users Ctrl-C'd into a half-created agent.
Fix (~/go-cli-progress-line-timing/internal/spawn/spawn.go): print the progress line immediately before the RPC, so feedback is emitted while the call is still in flight:
func Run(ctx context.Context, client SpawnClient, out io.Writer) (SpawnResult, error) {
fmt.Fprintln(out, "Creating agent...") // <-- before the RPC, while it may block
return client.SpawnAgent(ctx, SpawnRequest{Image: "bunker-default"})
}
The CLI (cmd/bunker/main.go) wraps a stdlib net/rpc client in the SpawnClient interface and calls Run; cmd/spawnserver simulates the slow backend.
Verification pattern (internal/spawn/spawn_test.go): a blockingSpawnServer mock whose SpawnAgent blocks on a release channel (so the RPC is provably in flight), plus a streaming stdout pipe read that asserts Creating agent... arrives within 2s while the RPC is still blocked (its returned channel still open). Post-hoc captureStdout cannot distinguish before/after ordering; the streaming read can. Key harness detail: io.Pipe writes block until read, so the pipe reader must be started before Run.
- `go vet` clean, `gofmt` clean, all tests pass under `-race`, stable across 5 consecutive runs. - **`TestProgressLineAppearsWhileRPCBlocked` (PASS, 0.20s):** line observed on the live pipe within 2s; mock's `returned` channel confirmed still open at observation time (RPC blocked); after `close(release)`, `Run` completes. - **`TestProgressLineOrderedBeforeResult` (PASS):** stream order is progress line → result line. - **`TestProgressLineAppearsBeforeRPCInCode` (PASS):** write-time event recorder proves the write precedes the RPC invocation. - **`TestRunCancelledWhileRPCBlocked` (PASS, edge case):** on Ctrl-C the progress line is already emitted and `Run` returns `context.Canceled` promptly — no hang, no false success. - **End-to-end demo:** real CLI vs. 4s simulated server — `[20:15:56.861] Creating agent...` then `[20:16:00.862] Agent agent-201600 created` (line appears instantly, result exactly at delay expiry). - **Negative control (proves the AC bites):** a temporary pre-fix variant (print *after* RPC) produced **no output within 2s while the RPC was blocked** — the timing AC fails it, demonstrating it can't be satisfied by luck or by a post-hoc assertion. (Regress harness removed after verification.)
{"model": "deepseek-v4-flash", "problem_class": "go-cli-progress-line-timing", "result": "passed", "tests": 4}