Skip to content

Commit 780d47f

Browse files
fix(config): stop billing provider-command fixtures to the 5s timeout
Both background-child tests fail intermittently on the Windows runner, and have since #690. #800 and #802 each relaxed an assertion, which is why neither held: the deadline itself was the problem. The tests drove LoadProviderCommand, so the fixture's own startup was billed to the production 5s budget. On a loaded runner the outer timer won the select in runProviderCommand, and both symptoms follow from that. The nonzero-exit test saw a timeout instead of the exit status it asserts, because the timer preempted the shell's exit. The other test lost its PID file, because the timer's Terminate killed the background child before it could record a PID, putting the file permanently out of reach however long the assertion polled. Neither test is a claim about the 5s budget. They assert which error each cmd.Wait path yields and that the leftover descendant is killed, so they now call runProviderCommand directly with a budget of their own and the production deadline stops competing with process startup. Making the child outlive that budget lets both drop their elapsed-versus-lifetime bounds as well, so no wall-clock assertion is left in either test. That is only worth doing if the two timeout paths can be told apart, and they could not: the WaitDelay path and the outer-timer path both returned the same bare sentinel, so asserting on it would have been satisfied by the very timeout the tests exist to rule out. The WaitDelay path now wraps rather than replaces. Callers asking errors.Is for the sentinel are unaffected, so no user-visible message changes. The Windows fixture also waited for its ready marker by launching a second PowerShell. That cold start is pure overhead added after the PID is already written, so the wait now runs in cmd itself and is bounded. Verified by looping both tests under CPU contention: 7 failures in 16 iterations before, none in 32 after, with per-iteration time going from a spread of 2.3s to 66s down to a steady 2.1s. Removing the wrap makes the WaitDelay assertion fail, so it is load-bearing rather than decorative.
1 parent ac50a5a commit 780d47f

2 files changed

Lines changed: 78 additions & 25 deletions

File tree

‎internal/config/command.go‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,7 +77,13 @@ func runProviderCommand(command string, timeout time.Duration) ([]byte, []byte,
7777
proc.Terminate()
7878
}
7979
if errors.Is(err, exec.ErrWaitDelay) {
80-
return stdout.Bytes(), stderr.Bytes(), errProviderCommandTimeout
80+
// Wrap rather than replace. A descendant holding the inherited pipes
81+
// open and the command never finishing at all are different failures
82+
// that both collapsed into the same bare sentinel, which left callers
83+
// and tests unable to tell which one happened. Callers that only ask
84+
// errors.Is(err, errProviderCommandTimeout) are unaffected, so the
85+
// message LoadProviderCommand reports is unchanged.
86+
return stdout.Bytes(), stderr.Bytes(), fmt.Errorf("%w: %w", errProviderCommandTimeout, err)
8187
}
8288
return stdout.Bytes(), stderr.Bytes(), err
8389
case <-timer.C:

‎internal/config/command_test.go‎

Lines changed: 71 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package config
33
import (
44
"errors"
55
"os"
6+
"os/exec"
67
"path/filepath"
78
"runtime"
89
"strconv"
@@ -91,31 +92,52 @@ func TestLoadProviderCommandTimeout(t *testing.T) {
9192
assertProcessTerminatedIfStarted(t, pidFile)
9293
}
9394

95+
// providerCommandTestBudget bounds the two background-child tests below, and is
96+
// deliberately NOT providerCommandTimeout. Those tests assert which error each
97+
// cmd.Wait path yields and that the leftover descendant is killed; neither is a
98+
// claim about how fast Windows can start a process. Driving them through
99+
// LoadProviderCommand billed the fixture's own startup to the production 5s
100+
// budget, so on a loaded runner the outer timer won the select in
101+
// runProviderCommand: the nonzero-exit test saw a timeout instead of the exit
102+
// status it asserts, and the timer's Terminate killed the background child
103+
// before it recorded its PID, putting the PID file permanently out of reach no
104+
// matter how long the assertion polled for it.
105+
//
106+
// This is a hang-breaker, not a tuned margin. Nothing in a healthy run waits on
107+
// it, since both tests return about one WaitDelay after the fixture exits.
108+
const providerCommandTestBudget = 60 * time.Second
109+
110+
// backgroundChildLifetime must exceed providerCommandTestBudget so that a child
111+
// dying of old age is unobservable: any run where runProviderCommand has not
112+
// returned yet trips the budget first. That is what lets both tests drop their
113+
// old elapsed-versus-lifetime bounds. "Still alive when the call returned" is
114+
// now true by construction, so a child found dead afterwards can only have been
115+
// killed by proc.Terminate.
116+
const backgroundChildLifetime = 120 * time.Second
117+
94118
// TestLoadProviderCommandTerminatesBackgroundChild covers a command that
95119
// exits immediately but leaves a detached child holding the inherited
96120
// stdout/stderr pipes open (e.g. `sleep 600 & exit`). cmd.Wait() only
97121
// unblocks once WaitDelay elapses, and that path must still terminate the
98122
// leftover child instead of just returning and leaking it.
99123
func TestLoadProviderCommandTerminatesBackgroundChild(t *testing.T) {
100124
pidFile := filepath.Join(t.TempDir(), "bg.pid")
101-
childLifetime := 10 * time.Second
102125
command := writeCommand(t, commandScript{
103126
Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-command","model":"gpt-command"}`,
104-
BackgroundSleepSeconds: int(childLifetime / time.Second),
127+
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
105128
BackgroundPidFile: pidFile,
106129
})
107130

108-
start := time.Now()
109-
_, err := LoadProviderCommand(command)
110-
elapsed := time.Since(start)
131+
_, _, err := runProviderCommand(command, providerCommandTestBudget)
111132
if err == nil {
112-
t.Fatal("LoadProviderCommand() error = nil, want error from WaitDelay-bounded wait")
133+
t.Fatal("runProviderCommand() error = nil, want error from WaitDelay-bounded wait")
113134
}
114-
if !strings.Contains(err.Error(), "timed out after 5s") {
115-
t.Fatalf("error = %q, want timeout", err.Error())
116-
}
117-
if elapsed >= childLifetime {
118-
t.Fatalf("returned after %s, want before the background child finishes naturally after %s", elapsed, childLifetime)
135+
// Name the exact path. The outer-timer path reports the bare sentinel, so
136+
// matching only that, or the "timed out after 5s" text this test used to
137+
// match, would also be satisfied by a slow runner taking precisely the path
138+
// this test exists to rule out.
139+
if !errors.Is(err, errProviderCommandTimeout) || !errors.Is(err, exec.ErrWaitDelay) {
140+
t.Fatalf("error = %v, want errProviderCommandTimeout wrapping exec.ErrWaitDelay", err)
119141
}
120142
assertProcessTerminated(t, pidFile)
121143
}
@@ -128,25 +150,25 @@ func TestLoadProviderCommandTerminatesBackgroundChild(t *testing.T) {
128150
// be terminated on that path.
129151
func TestLoadProviderCommandTerminatesBackgroundChildOnFailure(t *testing.T) {
130152
pidFile := filepath.Join(t.TempDir(), "bg-fail.pid")
131-
childLifetime := 10 * time.Second
132153
command := writeCommand(t, commandScript{
133154
Stderr: "boom",
134155
ExitCode: 7,
135-
BackgroundSleepSeconds: int(childLifetime / time.Second),
156+
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
136157
BackgroundPidFile: pidFile,
137158
})
138159

139-
start := time.Now()
140-
_, err := LoadProviderCommand(command)
141-
elapsed := time.Since(start)
142-
if err == nil {
143-
t.Fatal("LoadProviderCommand() error = nil, want failure from nonzero exit")
160+
_, _, err := runProviderCommand(command, providerCommandTestBudget)
161+
// The shell's own exit status has to survive. A timeout here means the
162+
// budget swallowed it, which is exactly what this test kept reporting on CI.
163+
if errors.Is(err, errProviderCommandTimeout) {
164+
t.Fatalf("error = %v, want the shell's exit status rather than a timeout", err)
144165
}
145-
if !strings.Contains(err.Error(), "exit status") {
146-
t.Fatalf("error = %q, want exit status failure", err.Error())
166+
var exitErr *exec.ExitError
167+
if !errors.As(err, &exitErr) {
168+
t.Fatalf("error = %v, want *exec.ExitError from the nonzero exit", err)
147169
}
148-
if elapsed >= childLifetime {
149-
t.Fatalf("returned after %s, want before the background child finishes naturally after %s", elapsed, childLifetime)
170+
if exitErr.ExitCode() != 7 {
171+
t.Fatalf("exit code = %d, want 7", exitErr.ExitCode())
150172
}
151173
assertProcessTerminated(t, pidFile)
152174
}
@@ -305,8 +327,33 @@ func writeCommand(t *testing.T, script commandScript) string {
305327
"Set-Content -LiteralPath '" + psSingleQuote(readyFile) + "' -Value ready -Encoding Ascii; " +
306328
"Start-Sleep -Seconds " + itoa(script.BackgroundSleepSeconds)
307329
lines = append(lines, "start /B powershell -NoProfile -Command \""+bgSleep+"\"")
308-
waitForReady := "while (-not (Test-Path -LiteralPath '" + psSingleQuote(readyFile) + "')) { Start-Sleep -Milliseconds 10 }"
309-
lines = append(lines, "powershell -NoProfile -Command \""+waitForReady+"\"")
330+
// Wait for the child to record its PID before exiting, so the PID is
331+
// on disk while the tree is still alive: runProviderCommand kills the
332+
// tree one WaitDelay after the script exits, and a child that has not
333+
// written by then never will.
334+
//
335+
// This waits in cmd itself. Spawning a second PowerShell just to poll
336+
// cost another interpreter cold start, and that start is pure overhead
337+
// added AFTER the PID is already written. On a loaded runner it pushed
338+
// the script's exit past the 5s provider-command timeout, so the
339+
// nonzero-exit test saw a timeout instead of the exit status it
340+
// asserts. The wait is also bounded now: giving up and letting the PID
341+
// assertion fail is far more diagnosable than blocking until the
342+
// timeout fires and reporting an unrelated error. Each iteration is
343+
// about a second, since `ping -n 2` sleeps between its two echoes,
344+
// so the ceiling is roughly 15s: far longer than any cold PowerShell
345+
// start seen on a runner, and far shorter than
346+
// providerCommandTestBudget, so giving up surfaces a legible
347+
// PID-file failure rather than a timeout that hides the real cause.
348+
lines = append(lines,
349+
":zeroWaitReady",
350+
"if exist \""+readyFile+"\" goto zeroReady",
351+
"set /a ZERO_READY_TRIES+=1",
352+
"if %ZERO_READY_TRIES% GEQ 15 goto zeroReady",
353+
"ping -n 2 127.0.0.1 >nul",
354+
"goto zeroWaitReady",
355+
":zeroReady",
356+
)
310357
}
311358
lines = append(lines, "exit /b "+itoa(script.ExitCode))
312359
if err := os.WriteFile(path, []byte(strings.Join(lines, "\r\n")), 0o700); err != nil {

0 commit comments

Comments
 (0)