Compare commits

...
Author SHA1 Message Date
Vasanthdev2004 780d47f31b 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.
2026-07-27 01:31:43 +05:30
2 changed files with 78 additions and 25 deletions

No files matched your search

+7 -1
View File
@@ -77,7 +77,13 @@ func runProviderCommand(command string, timeout time.Duration) ([]byte, []byte,
proc.Terminate()
}
if errors.Is(err, exec.ErrWaitDelay) {
return stdout.Bytes(), stderr.Bytes(), errProviderCommandTimeout
// Wrap rather than replace. A descendant holding the inherited pipes
// open and the command never finishing at all are different failures
// that both collapsed into the same bare sentinel, which left callers
// and tests unable to tell which one happened. Callers that only ask
// errors.Is(err, errProviderCommandTimeout) are unaffected, so the
// message LoadProviderCommand reports is unchanged.
return stdout.Bytes(), stderr.Bytes(), fmt.Errorf("%w: %w", errProviderCommandTimeout, err)
}
return stdout.Bytes(), stderr.Bytes(), err
case <-timer.C:
+71 -24
View File
@@ -3,6 +3,7 @@ package config
import (
"errors"
"os"
"os/exec"
"path/filepath"
"runtime"
"strconv"
@@ -91,6 +92,29 @@ func TestLoadProviderCommandTimeout(t *testing.T) {
assertProcessTerminatedIfStarted(t, pidFile)
}
// providerCommandTestBudget bounds the two background-child tests below, and is
// deliberately NOT providerCommandTimeout. Those tests assert which error each
// cmd.Wait path yields and that the leftover descendant is killed; neither is a
// claim about how fast Windows can start a process. Driving them through
// LoadProviderCommand billed the fixture's own startup to the production 5s
// budget, so on a loaded runner the outer timer won the select in
// runProviderCommand: the nonzero-exit test saw a timeout instead of the exit
// status it asserts, and the timer's Terminate killed the background child
// before it recorded its PID, putting the PID file permanently out of reach no
// matter how long the assertion polled for it.
//
// This is a hang-breaker, not a tuned margin. Nothing in a healthy run waits on
// it, since both tests return about one WaitDelay after the fixture exits.
const providerCommandTestBudget = 60 * time.Second
// backgroundChildLifetime must exceed providerCommandTestBudget so that a child
// dying of old age is unobservable: any run where runProviderCommand has not
// returned yet trips the budget first. That is what lets both tests drop their
// old elapsed-versus-lifetime bounds. "Still alive when the call returned" is
// now true by construction, so a child found dead afterwards can only have been
// killed by proc.Terminate.
const backgroundChildLifetime = 120 * time.Second
// TestLoadProviderCommandTerminatesBackgroundChild covers a command that
// exits immediately but leaves a detached child holding the inherited
// stdout/stderr pipes open (e.g. `sleep 600 & exit`). cmd.Wait() only
@@ -98,24 +122,22 @@ func TestLoadProviderCommandTimeout(t *testing.T) {
// leftover child instead of just returning and leaking it.
func TestLoadProviderCommandTerminatesBackgroundChild(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "bg.pid")
childLifetime := 10 * time.Second
command := writeCommand(t, commandScript{
Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-command","model":"gpt-command"}`,
BackgroundSleepSeconds: int(childLifetime / time.Second),
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
BackgroundPidFile: pidFile,
})
start := time.Now()
_, err := LoadProviderCommand(command)
elapsed := time.Since(start)
_, _, err := runProviderCommand(command, providerCommandTestBudget)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want error from WaitDelay-bounded wait")
t.Fatal("runProviderCommand() error = nil, want error from WaitDelay-bounded wait")
}
if !strings.Contains(err.Error(), "timed out after 5s") {
t.Fatalf("error = %q, want timeout", err.Error())
}
if elapsed >= childLifetime {
t.Fatalf("returned after %s, want before the background child finishes naturally after %s", elapsed, childLifetime)
// Name the exact path. The outer-timer path reports the bare sentinel, so
// matching only that, or the "timed out after 5s" text this test used to
// match, would also be satisfied by a slow runner taking precisely the path
// this test exists to rule out.
if !errors.Is(err, errProviderCommandTimeout) || !errors.Is(err, exec.ErrWaitDelay) {
t.Fatalf("error = %v, want errProviderCommandTimeout wrapping exec.ErrWaitDelay", err)
}
assertProcessTerminated(t, pidFile)
}
@@ -128,25 +150,25 @@ func TestLoadProviderCommandTerminatesBackgroundChild(t *testing.T) {
// be terminated on that path.
func TestLoadProviderCommandTerminatesBackgroundChildOnFailure(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "bg-fail.pid")
childLifetime := 10 * time.Second
command := writeCommand(t, commandScript{
Stderr: "boom",
ExitCode: 7,
BackgroundSleepSeconds: int(childLifetime / time.Second),
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
BackgroundPidFile: pidFile,
})
start := time.Now()
_, err := LoadProviderCommand(command)
elapsed := time.Since(start)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want failure from nonzero exit")
_, _, err := runProviderCommand(command, providerCommandTestBudget)
// The shell's own exit status has to survive. A timeout here means the
// budget swallowed it, which is exactly what this test kept reporting on CI.
if errors.Is(err, errProviderCommandTimeout) {
t.Fatalf("error = %v, want the shell's exit status rather than a timeout", err)
}
if !strings.Contains(err.Error(), "exit status") {
t.Fatalf("error = %q, want exit status failure", err.Error())
var exitErr *exec.ExitError
if !errors.As(err, &exitErr) {
t.Fatalf("error = %v, want *exec.ExitError from the nonzero exit", err)
}
if elapsed >= childLifetime {
t.Fatalf("returned after %s, want before the background child finishes naturally after %s", elapsed, childLifetime)
if exitErr.ExitCode() != 7 {
t.Fatalf("exit code = %d, want 7", exitErr.ExitCode())
}
assertProcessTerminated(t, pidFile)
}
@@ -305,8 +327,33 @@ func writeCommand(t *testing.T, script commandScript) string {
"Set-Content -LiteralPath '" + psSingleQuote(readyFile) + "' -Value ready -Encoding Ascii; " +
"Start-Sleep -Seconds " + itoa(script.BackgroundSleepSeconds)
lines = append(lines, "start /B powershell -NoProfile -Command \""+bgSleep+"\"")
waitForReady := "while (-not (Test-Path -LiteralPath '" + psSingleQuote(readyFile) + "')) { Start-Sleep -Milliseconds 10 }"
lines = append(lines, "powershell -NoProfile -Command \""+waitForReady+"\"")
// Wait for the child to record its PID before exiting, so the PID is
// on disk while the tree is still alive: runProviderCommand kills the
// tree one WaitDelay after the script exits, and a child that has not
// written by then never will.
//
// This waits in cmd itself. Spawning a second PowerShell just to poll
// cost another interpreter cold start, and that start is pure overhead
// added AFTER the PID is already written. On a loaded runner it pushed
// the script's exit past the 5s provider-command timeout, so the
// nonzero-exit test saw a timeout instead of the exit status it
// asserts. The wait is also bounded now: giving up and letting the PID
// assertion fail is far more diagnosable than blocking until the
// timeout fires and reporting an unrelated error. Each iteration is
// about a second, since `ping -n 2` sleeps between its two echoes,
// so the ceiling is roughly 15s: far longer than any cold PowerShell
// start seen on a runner, and far shorter than
// providerCommandTestBudget, so giving up surfaces a legible
// PID-file failure rather than a timeout that hides the real cause.
lines = append(lines,
":zeroWaitReady",
"if exist \""+readyFile+"\" goto zeroReady",
"set /a ZERO_READY_TRIES+=1",
"if %ZERO_READY_TRIES% GEQ 15 goto zeroReady",
"ping -n 2 127.0.0.1 >nul",
"goto zeroWaitReady",
":zeroReady",
)
}
lines = append(lines, "exit /b "+itoa(script.ExitCode))
if err := os.WriteFile(path, []byte(strings.Join(lines, "\r\n")), 0o700); err != nil {