diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c52027..732f996 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,25 @@ All notable packetcode changes are recorded here. The project is pre-1.0; `Unrel ### Fixed +- `TestRunUserPromptSubmit_CollectsStdout` failed on `test (windows-latest)` + about two runs in three and never on a developer machine. The cause was + measured rather than guessed: on four GitHub `windows-latest` runners the + first `powershell -Command "exit 0"` in a job took 4.33-4.87s while every + later one took 0.16-0.19s, and a bare `cmd.exe` CreateProcess at the same + instant took 15-38ms. The machine was not busy, the stdin plumbing cost + nothing (170ms with no stdin, 175ms with it attached, 180ms running the full + hook script) and `internal/hooks` added nothing (184ms with the tree-cancel + wiring, 194ms end to end through `Runner`). It was Windows PowerShell's own + start-up, paid once per machine, and it landed entirely on whichever test + spawned first -- whose 5s budget sat a few hundred milliseconds above a 4.6s + constant. `internal/hooks` now pays that cost in `TestMain`, before any + test's budget is running, and the budgets themselves scale through + `internal/testwait` like every other deadline in the suite. `pwsh` was + measured as an alternative and is slower warm (265-285ms), so the tests still + run the interpreter production uses. The same trap was latent in + `internal/statusline` and `internal/jobs`, which spawn the same interpreter + and were surviving only because `internal/hooks` happened to run first; their + budgets scale now too. - Bugfix pass, 2026-09-03. Six read-only reviewers swept the packages and the confirmed findings were fixed with regression tests: - **Permissions.** A session or skill allow rule for `execute_command` diff --git a/docs/runbooks.md b/docs/runbooks.md index 2b57165..9ddb2b5 100644 --- a/docs/runbooks.md +++ b/docs/runbooks.md @@ -571,6 +571,19 @@ go test ./internal/jobs/ -count=1 -run -timeout 240s git worktree remove /tmp/pc-bisect ``` +**If a Windows test that runs a hook or status line command fails on its +timeout**, suspect the interpreter before the code. The first +`powershell -Command` on a machine costs 4.3-4.9s on GitHub's `windows-latest` +runners; every later one costs under 0.2s. `internal/hooks` pays that once in +`TestMain` and every such budget scales through `internal/testwait`, so a +failure here usually means either a new package spawned PowerShell before +`internal/hooks` did, or a hook budget was written as a bare number instead of +`testwait.Seconds(...)`. Confirm which before changing a timeout: + +```bash +go test ./internal/hooks/ -count=1 -run TestRunUserPromptSubmit_CollectsStdout -v +``` + --- ## R17. Reset to a known-good state diff --git a/internal/hooks/hooks_test.go b/internal/hooks/hooks_test.go index db1088f..8aa20c3 100644 --- a/internal/hooks/hooks_test.go +++ b/internal/hooks/hooks_test.go @@ -2,6 +2,7 @@ package hooks import ( "context" + "os" "runtime" "strings" "testing" @@ -11,17 +12,58 @@ import ( "github.com/stretchr/testify/require" "github.com/packetcode/packetcode/internal/config" + "github.com/packetcode/packetcode/internal/testwait" ) +// TestMain spawns the hook interpreter once before any test's budget is +// running, because on Windows the first one costs about twenty-five times what +// every later one does and that cost has nothing to do with what these tests +// assert. +// +// Measured on four GitHub `windows-latest` runners: the first +// `powershell -Command "exit 0"` in a job took 4.33s, 4.66s, 4.63s and 4.87s, +// while every subsequent one took 0.16-0.19s and a bare `cmd.exe` CreateProcess +// at the same instant took 15-38ms. So the machine was not busy, the stdin +// plumbing was not slow (no-stdin 170ms, stdin attached 175ms, full hook script +// 180ms) and internal/hooks added nothing (184ms with the tree-cancel wiring, +// 194ms end to end through Runner). It is Windows PowerShell's own start-up -- +// faulting in and JITing the assemblies behind System.Management.Automation +// from a cold image -- paid once per machine rather than once per spawn. +// +// Whichever test spawned first absorbed all of it. That was +// TestRunUserPromptSubmit_CollectsStdout, whose 5s budget sat 0.1-0.7s above a +// 4.6s constant, so whether it passed was decided by noise: it failed roughly +// two runs in three on CI and never once on a developer machine, which is the +// one result a test must never produce. Paying the cost here makes every +// budget in this file mean the same thing, instead of loading the whole +// per-machine cost onto whichever test happens to run first. +func TestMain(m *testing.M) { + warmShellInterpreter() + os.Exit(m.Run()) +} + +// warmShellInterpreter runs the cheapest possible command through the same +// shellCommand the hooks use, so the warm-up covers whatever interpreter +// production actually picks rather than a copy of that choice that can drift. +// +// Its result is deliberately ignored. It asserts nothing, and a machine where +// it fails is one where the tests below should report the problem themselves +// against their own scaled budgets -- not one where the suite refuses to start. +func warmShellInterpreter() { + ctx, cancel := context.WithTimeout(context.Background(), testwait.Timeout(5*time.Second)) + defer cancel() + cmd := shellCommand(ctx, "exit 0") + cmd.Stdin = strings.NewReader("") + _ = cmd.Run() +} + func TestRunUserPromptSubmit_CollectsStdout(t *testing.T) { command := "input=$(cat); case \"$input\" in *hello*) printf injected-context;; *) exit 1;; esac" - timeoutSec := 2 if runtime.GOOS == "windows" { command = "$data = [Console]::In.ReadToEnd(); if ($data -match 'hello') { 'injected-context' } else { exit 1 }" - timeoutSec = 5 } r := New(config.HooksConfig{ - UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: timeoutSec}}, + UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: testwait.Seconds(2 * time.Second)}}, }, t.TempDir()) out, err := r.RunUserPromptSubmit(context.Background(), PromptPayload{Prompt: "hello"}) @@ -34,8 +76,13 @@ func TestRunPreToolUse_MatcherCanBlock(t *testing.T) { if runtime.GOOS == "windows" { command = "Write-Error blocked; exit 7" } + // Scaled for the same reason as the hook above, and with less room to + // spare than the 2 looks: on the runners measured this hook took 1.0-1.7s + // against its two-second budget, because Write-Error builds and formats a + // full ErrorRecord and so costs several times a bare spawn. It survived + // only because the test above it absorbed the interpreter's start-up. r := New(config.HooksConfig{ - PreToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: 2}}, + PreToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: testwait.Seconds(2 * time.Second)}}, }, t.TempDir()) _, err := r.RunPreToolUse(context.Background(), ToolPayload{ToolName: "execute_command"}) @@ -51,6 +98,17 @@ func TestRunPreToolUse_TimeoutMessage(t *testing.T) { if runtime.GOOS == "windows" { command = "Start-Sleep -Seconds 5" } + // Not scaled, unlike every other budget in this file, and not an oversight. + // Here the timeout is the subject rather than the scaffolding: the test + // asserts the hook gives up at one second instead of waiting out the + // five-second sleep, so a scaled budget would assert nothing. Scaling the + // three-second ceiling would be worse still -- past five seconds it can no + // longer tell a cancelled hook from one that ran to completion. + // + // It does not need the slack either. Measured on the same runs that put the + // hook above 0.6s over its budget, this path took 1.02-1.05s, because the + // deadline starts at Run and fires while the interpreter is still starting: + // what it measures is when cancellation happened, not how long a spawn took. r := New(config.HooksConfig{ PreToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: 1}}, }, t.TempDir()) @@ -69,7 +127,7 @@ func TestRunPostToolUse_TruncatesStdoutAndStderr(t *testing.T) { command = "$out = 'o' * 70000; $err = 'e' * 70000; [Console]::Out.Write($out); [Console]::Error.Write($err); exit 3" } r := New(config.HooksConfig{ - PostToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: 5}}, + PostToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: testwait.Seconds(5 * time.Second)}}, }, t.TempDir()) out, err := r.RunPostToolUse(context.Background(), ToolPayload{ToolName: "execute_command"}) diff --git a/internal/jobs/worker_test.go b/internal/jobs/worker_test.go index 7e3b703..104e0fa 100644 --- a/internal/jobs/worker_test.go +++ b/internal/jobs/worker_test.go @@ -5,11 +5,13 @@ import ( "runtime" "strings" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/packetcode/packetcode/internal/config" "github.com/packetcode/packetcode/internal/hooks" + "github.com/packetcode/packetcode/internal/testwait" ) // TestSummarise_TrimsAndCaps spot-checks summarise's behaviour: it @@ -114,8 +116,11 @@ func TestRunJob_PassesHooksToBackgroundAgent(t *testing.T) { } prov := &scriptedProvider{turns: scriptedHello()} mgr, _ := newTestManager(t, prov, func(c *Config) { + // Scaled for the reason given in internal/hooks' TestMain: on Windows + // this is a PowerShell spawn, and the first one on a machine costs + // about 4.6s against a two-second budget. c.Hooks = hooks.New(config.HooksConfig{ - UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: 2}}, + UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: testwait.Seconds(2 * time.Second)}}, }, t.TempDir()) }) diff --git a/internal/statusline/statusline_test.go b/internal/statusline/statusline_test.go index eab5109..452a842 100644 --- a/internal/statusline/statusline_test.go +++ b/internal/statusline/statusline_test.go @@ -13,6 +13,7 @@ import ( "github.com/stretchr/testify/require" "github.com/packetcode/packetcode/internal/config" + "github.com/packetcode/packetcode/internal/testwait" ) // TestSnapshotClaudeCodeCompat verifies the emitted JSON carries both @@ -106,12 +107,17 @@ func TestModelDisplayNameHonoured(t *testing.T) { func TestRunner_RenderPassesJSONOnStdin(t *testing.T) { command := "read input; case \"$input\" in *gpt-test*) printf custom-status;; *) exit 1;; esac" - timeoutSec := 2 if runtime.GOOS == "windows" { command = "$data = [Console]::In.ReadToEnd(); if ($data -match 'gpt-test') { 'custom-status' } else { exit 1 }" - timeoutSec = 5 } - r := New(config.StatusLineConfig{Command: command, TimeoutSec: timeoutSec}, t.TempDir()) + // This spawns the same Windows PowerShell that internal/hooks does, so it + // carries the same trap: the first one on a machine costs about 4.6s + // against what used to be a five-second budget, and every later one costs + // under 0.2s. Today internal/hooks runs earlier and absorbs that cost, + // which is the only reason this test is not the flaky one -- a dependency + // on package scheduling that nothing here states or enforces. See the + // TestMain comment in internal/hooks for the measurements. + r := New(config.StatusLineConfig{Command: command, TimeoutSec: testwait.Seconds(2 * time.Second)}, t.TempDir()) require.NotNil(t, r) out, err := r.Render(context.Background(), Snapshot{ diff --git a/internal/testwait/testwait.go b/internal/testwait/testwait.go index e192617..cadf90c 100644 --- a/internal/testwait/testwait.go +++ b/internal/testwait/testwait.go @@ -21,6 +21,7 @@ package testwait import ( "fmt" + "math" "os" "strconv" "time" @@ -79,6 +80,18 @@ func Timeout(baseline time.Duration) time.Duration { return d } +// Seconds is Timeout in whole seconds, for the config fields that spell a +// budget as a `timeout_sec` int rather than a Duration -- hook and status line +// commands, which are the subprocess equivalent of the waits above and go +// wrong for the same reason. +// +// It rounds up. Truncation would silently hand back less than the scale asked +// for, and a budget that is quietly shorter than it claims is the exact defect +// this package exists to prevent. +func Seconds(baseline time.Duration) int { + return int(math.Ceil(Timeout(baseline).Seconds())) +} + // TB is the subset of testing.TB used here, so this package does not import // testing into a non-test build. type TB interface { diff --git a/internal/testwait/testwait_test.go b/internal/testwait/testwait_test.go index 83d0277..3d54af8 100644 --- a/internal/testwait/testwait_test.go +++ b/internal/testwait/testwait_test.go @@ -105,6 +105,25 @@ func TestTimeout_ScalesAndFloors(t *testing.T) { } } +func TestSeconds_RoundsUpAndNeverShortensTheBudget(t *testing.T) { + t.Setenv(ScaleEnv, "2") + if got := Seconds(10 * time.Second); got != 20 { + t.Fatalf("Seconds(10s) at scale 2 = %d, want 20", got) + } + // The floor applies before the conversion, so a small baseline still gets + // a usable whole number rather than zero. + if got := Seconds(time.Millisecond); got != int(minTimeout.Seconds()) { + t.Fatalf("Seconds(1ms) = %d, want the %s floor", got, minTimeout) + } + // A budget that does not land on a whole second must round up: truncating + // would hand back less time than the scale asked for, which is the defect + // this package exists to prevent. + t.Setenv(ScaleEnv, "1.05") + if got := Seconds(10 * time.Second); got != 11 { + t.Fatalf("Seconds(10s) at scale 1.05 = %d, want 11 (10.5s rounded up)", got) + } +} + func TestFactor_DefaultsWhenUnsetOrInvalid(t *testing.T) { for _, raw := range []string{"", "not-a-number", "0", "-3"} { t.Setenv(ScaleEnv, raw)