test: pay Windows PowerShell's cold start outside the hook budgets

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`

docs/runbooks.md

@@ -571,6 +571,19 @@ go test ./internal/jobs/ -count=1 -run <TestName> -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

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"})

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())
 	})
 

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{

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 {

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)