Files
zero/internal/config/command_test.go
Vasanth T 1c38e8cba5 fix(config): make the provider-command timeout an upper bound (#811) (#813)
providerCommandTimeout bounded only the wait, so the call could take arbitrarily
longer than the 5s its error text promised. Two phases sat outside it.

Starting the process ran before the clock began. On Windows that is
CREATE_SUSPENDED, job-object creation and assignment, and a system-wide thread
snapshot, none of it fast on a cold or contended machine. The deadline is now
armed first and the start races it, so process creation is inside the budget.

Draining after termination was unbounded too: the timer path called Terminate
and then received on the wait with no limit. Terminate normally makes that
immediate, which is exactly why it survived unnoticed, but a tree that resists
termination held the call open long past the deadline that had just expired.
That receive is now bounded, and a call that gives up leaves cmd.Wait running,
so the output buffers are synchronised: the I/O pump keeps writing into buffers
the caller already holds, which a plain bytes.Buffer cannot survive.

The timeout error also carried nothing actionable. It was a bare string with the
underlying error and the command's stderr both dropped, so a user whose provider
command was slow got no clue which phase ran out or what the command had said.
It now names the phase, wraps the cause, and includes the redacted output the
failure path already had.

Both bounds are asserted on extracted helpers rather than end to end, because
end to end they are untestable: a terminated command stops writing and its wait
returns at once, so an unbounded drain and an unsynchronised buffer both pass a
whole-call test. The first version of these tests did exactly that and proved
nothing. Removing either bound now fails, as does arming the deadline after the
start, which reports the wrong phase.
2026-07-28 22:41:09 +08:00

547 lines
20 KiB
Go

package config
import (
"errors"
"os"
"os/exec"
"path/filepath"
"runtime"
"strconv"
"strings"
"testing"
"time"
)
func TestLoadProviderCommandSuccess(t *testing.T) {
command := writeCommand(t, commandScript{
Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-command","model":"gpt-command"}`,
})
cfg, err := LoadProviderCommand(command)
if err != nil {
t.Fatalf("LoadProviderCommand() error = %v", err)
}
if len(cfg.Providers) != 1 {
t.Fatalf("providers length = %d, want 1", len(cfg.Providers))
}
provider := cfg.Providers[0]
if provider.Name != "cmd" || provider.APIKey != "sk-command" || provider.Model != "gpt-command" {
t.Fatalf("provider = %#v, want command provider", provider)
}
}
func TestLoadProviderCommandDoesNotResolveAPIKeyEnvFromProcess(t *testing.T) {
t.Setenv("ZERO_CMD_API_KEY", "sk-process")
command := writeCommand(t, commandScript{
Stdout: `{"name":"cmd","provider":"openai","apiKeyEnv":"ZERO_CMD_API_KEY","model":"gpt-command"}`,
})
cfg, err := LoadProviderCommand(command)
if err != nil {
t.Fatalf("LoadProviderCommand() error = %v", err)
}
provider := cfg.Providers[0]
if provider.APIKey != "" {
t.Fatalf("APIKey = %q, want unresolved provider-command apiKeyEnv", provider.APIKey)
}
if provider.APIKeyEnv != "ZERO_CMD_API_KEY" {
t.Fatalf("APIKeyEnv = %q, want command apiKeyEnv preserved", provider.APIKeyEnv)
}
}
func TestLoadProviderCommandFailureIncludesExitAndRedactsOutput(t *testing.T) {
command := writeCommand(t, commandScript{
Stderr: "failed with sk-command-secret",
ExitCode: 7,
})
_, err := LoadProviderCommand(command)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want command failure")
}
if !strings.Contains(err.Error(), "provider command failed") || !strings.Contains(err.Error(), "exit status") {
t.Fatalf("error = %q, want command failure with exit status", err.Error())
}
if strings.Contains(err.Error(), "sk-command-secret") {
t.Fatalf("error leaked command secret: %q", err.Error())
}
}
func TestLoadProviderCommandTimeout(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "sleep.pid")
command := writeCommand(t, commandScript{SleepSeconds: 10, PidFile: pidFile})
start := time.Now()
_, err := LoadProviderCommand(command)
elapsed := time.Since(start)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want timeout")
}
if !strings.Contains(err.Error(), "timed out after 5s") {
t.Fatalf("error = %q, want timeout", err.Error())
}
maxElapsed := 7 * time.Second
if runtime.GOOS == "windows" {
maxElapsed = 9 * time.Second
}
if elapsed > maxElapsed {
t.Fatalf("timeout returned after %s, want roughly 5s", elapsed)
}
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
// unblocks once WaitDelay elapses, and that path must still terminate the
// leftover child instead of just returning and leaking it.
func TestLoadProviderCommandTerminatesBackgroundChild(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "bg.pid")
command := writeCommand(t, commandScript{
Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-command","model":"gpt-command"}`,
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
BackgroundPidFile: pidFile,
})
_, _, err := runProviderCommand(command, providerCommandTestBudget)
if err == nil {
t.Fatal("runProviderCommand() error = nil, want error from WaitDelay-bounded wait")
}
// 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)
}
// TestLoadProviderCommandTerminatesBackgroundChildOnFailure covers the same
// leaked-descendant scenario as TestLoadProviderCommandTerminatesBackgroundChild,
// but with a shell that exits nonzero. Go's exec.Cmd.Wait only returns
// exec.ErrWaitDelay when the command itself exited successfully; a nonzero
// exit yields the bare *ExitError instead, so the leftover child must still
// be terminated on that path.
func TestLoadProviderCommandTerminatesBackgroundChildOnFailure(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "bg-fail.pid")
command := writeCommand(t, commandScript{
Stderr: "boom",
ExitCode: 7,
BackgroundSleepSeconds: int(backgroundChildLifetime / time.Second),
BackgroundPidFile: pidFile,
})
_, _, 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)
}
var exitErr *exec.ExitError
if !errors.As(err, &exitErr) {
t.Fatalf("error = %v, want *exec.ExitError from the nonzero exit", err)
}
if exitErr.ExitCode() != 7 {
t.Fatalf("exit code = %d, want 7", exitErr.ExitCode())
}
assertProcessTerminated(t, pidFile)
}
func TestAssertProcessTerminatedWaitsForDelayedPIDFile(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "delayed.pid")
firstMissing := make(chan struct{})
writeDone := make(chan error, 1)
go func() {
<-firstMissing
tempFile := pidFile + ".tmp"
if err := os.WriteFile(tempFile, []byte("2147483647\n"), 0o600); err != nil {
writeDone <- err
return
}
writeDone <- os.Rename(tempFile, pidFile)
}()
missingObserved := false
assertProcessTerminatedAfterMissing(t, pidFile, func() {
missingObserved = true
close(firstMissing)
})
if !missingObserved {
t.Fatal("PID file existed before the missing-file polling path was exercised")
}
if err := <-writeDone; err != nil {
t.Fatalf("write delayed pid file: %v", err)
}
}
func assertProcessTerminatedIfStarted(t *testing.T, pidFile string) {
t.Helper()
// The basic timeout fixture is intentionally unsynchronized. On a loaded
// Windows runner, the cold PowerShell child can be terminated before it
// records its PID; the synchronized background-child tests below retain
// the strict PID and liveness checks.
if _, err := os.Stat(pidFile); errors.Is(err, os.ErrNotExist) {
return
}
assertProcessTerminated(t, pidFile)
}
func assertProcessTerminated(t *testing.T, pidFile string) {
t.Helper()
assertProcessTerminatedAfterMissing(t, pidFile, nil)
}
func assertProcessTerminatedAfterMissing(t *testing.T, pidFile string, onMissing func()) {
t.Helper()
deadline := time.Now().Add(3 * time.Second)
var data []byte
var err error
missingObserved := false
for time.Now().Before(deadline) {
data, err = os.ReadFile(pidFile)
if err == nil {
break
}
if !errors.Is(err, os.ErrNotExist) {
t.Fatalf("read sleeper pid file: %v", err)
}
if !missingObserved {
missingObserved = true
if onMissing != nil {
onMissing()
}
}
time.Sleep(10 * time.Millisecond)
}
if err != nil {
t.Fatalf("read sleeper pid file before timeout: %v", err)
}
pid, err := strconv.Atoi(strings.TrimSpace(string(data)))
if err != nil {
t.Fatalf("parse sleeper pid %q: %v", data, err)
}
deadline = time.Now().Add(3 * time.Second)
for time.Now().Before(deadline) {
if !processAlive(pid) {
return
}
time.Sleep(100 * time.Millisecond)
}
t.Fatalf("sleeper process %d still alive after timeout", pid)
}
func TestLoadProviderCommandInvalidJSON(t *testing.T) {
command := writeCommand(t, commandScript{Stdout: `{not-json`})
_, err := LoadProviderCommand(command)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want JSON error")
}
if !strings.Contains(err.Error(), "invalid provider command JSON") {
t.Fatalf("error = %q, want invalid JSON", err.Error())
}
}
func TestLoadProviderCommandMissingModel(t *testing.T) {
command := writeCommand(t, commandScript{
Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-command"}`,
})
_, err := LoadProviderCommand(command)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want missing model")
}
if !strings.Contains(err.Error(), "provider cmd requires model") {
t.Fatalf("error = %q, want missing model", err.Error())
}
}
type commandScript struct {
Stdout string
Stderr string
ExitCode int
SleepSeconds int
PidFile string
// BackgroundSleepSeconds, if set, spawns a detached child that keeps the
// inherited stdout/stderr handles open well after the script itself
// exits, simulating a `sleep 600 & exit` style command. BackgroundPidFile
// records the detached child's PID.
BackgroundSleepSeconds int
BackgroundPidFile string
}
func writeCommand(t *testing.T, script commandScript) string {
t.Helper()
dir := t.TempDir()
if runtime.GOOS == "windows" {
path := filepath.Join(dir, "provider.cmd")
lines := []string{"@echo off"}
if script.SleepSeconds > 0 {
sleep := "Start-Sleep -Seconds " + itoa(script.SleepSeconds)
if script.PidFile != "" {
sleep = "Set-Content -Path '" + psSingleQuote(script.PidFile) + "' -Value $PID -Encoding Ascii; " + sleep
}
lines = append(lines, "powershell -NoProfile -Command \""+sleep+"\"")
}
if script.Stdout != "" {
lines = append(lines, "echo "+script.Stdout)
}
if script.Stderr != "" {
lines = append(lines, "echo "+script.Stderr+" 1>&2")
}
if script.BackgroundSleepSeconds > 0 {
readyFile := script.BackgroundPidFile + ".ready"
bgSleep := "Set-Content -LiteralPath '" + psSingleQuote(script.BackgroundPidFile) + "' -Value $PID -Encoding Ascii; " +
"Set-Content -LiteralPath '" + psSingleQuote(readyFile) + "' -Value ready -Encoding Ascii; " +
"Start-Sleep -Seconds " + itoa(script.BackgroundSleepSeconds)
lines = append(lines, "start /B powershell -NoProfile -Command \""+bgSleep+"\"")
// 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 {
t.Fatalf("write command: %v", err)
}
return path
}
path := filepath.Join(dir, "provider.sh")
lines := []string{"#!/bin/sh"}
if script.SleepSeconds > 0 {
if script.PidFile != "" {
lines = append(lines, "echo $$ > '"+shSingleQuote(script.PidFile)+"'")
}
lines = append(lines, "sleep "+itoa(script.SleepSeconds))
}
if script.Stdout != "" {
lines = append(lines, "printf '%s\\n' '"+script.Stdout+"'")
}
if script.Stderr != "" {
lines = append(lines, "printf '%s\\n' '"+script.Stderr+"' >&2")
}
if script.BackgroundSleepSeconds > 0 {
lines = append(lines, "sleep "+itoa(script.BackgroundSleepSeconds)+" &")
lines = append(lines, "echo $! > '"+shSingleQuote(script.BackgroundPidFile)+"'")
}
lines = append(lines, "exit "+itoa(script.ExitCode))
if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")), 0o700); err != nil {
t.Fatalf("write command: %v", err)
}
return path
}
// psSingleQuote escapes a value for interpolation inside a PowerShell
// single-quoted string literal, where a literal quote is doubled.
func psSingleQuote(value string) string {
return strings.ReplaceAll(value, "'", "''")
}
// shSingleQuote escapes a value for interpolation inside a POSIX shell
// single-quoted string literal, where a literal quote must close the
// quoted section, emit an escaped quote, then reopen it.
func shSingleQuote(value string) string {
return strings.ReplaceAll(value, "'", `'\''`)
}
func itoa(value int) string {
if value == 0 {
return "0"
}
var digits [20]byte
index := len(digits)
for value > 0 {
index--
digits[index] = byte('0' + value%10)
value /= 10
}
return string(digits[index:])
}
// The whole point of #811: providerCommandTimeout has to be an upper bound on
// how long the call takes, not a floor. Process creation used to run before the
// clock started and the post-termination drain was unbounded, so a slow or
// contended machine could block startup for far longer than the error text
// promised.
//
// This one guards the end-to-end contract against gross regressions. It is NOT
// the assertion that pins the drain bound: Terminate kills the tree, so Wait
// returns promptly and this passes even with the drain unbounded. That property
// is pinned by TestAwaitWithGraceGivesUp, and the start-phase bound by
// TestRunProviderCommandCountsProcessStartAgainstTheDeadline.
func TestRunProviderCommandBoundsTotalDuration(t *testing.T) {
pidFile := filepath.Join(t.TempDir(), "bound.pid")
command := writeCommand(t, commandScript{SleepSeconds: 60, PidFile: pidFile})
const budget = 2 * time.Second
start := time.Now()
_, _, err := runProviderCommand(command, budget)
elapsed := time.Since(start)
if !errors.Is(err, errProviderCommandTimeout) {
t.Fatalf("error = %v, want the timeout sentinel", err)
}
// Budget, plus the bounded drain, plus room for a loaded runner. A failure
// here means some phase is outside the deadline again, which is the bug.
ceiling := budget + providerCommandDrainGrace + 8*time.Second
if elapsed > ceiling {
t.Fatalf("returned after %s with a %s budget; the timeout is not bounding the call (ceiling %s)", elapsed, budget, ceiling)
}
assertProcessTerminatedIfStarted(t, pidFile)
}
// The timeout error has to carry something an operator can act on. It used to be
// a bare string with the underlying error and the command's stderr both dropped,
// so a user whose provider command was slow got no clue which phase ran out or
// what the command had said.
func TestLoadProviderCommandTimeoutReportsDiagnostics(t *testing.T) {
command := writeCommand(t, commandScript{
Stderr: "provider is warming up",
SleepSeconds: 30,
PidFile: filepath.Join(t.TempDir(), "diag.pid"),
})
_, err := LoadProviderCommand(command)
if err == nil {
t.Fatal("LoadProviderCommand() error = nil, want timeout")
}
if !strings.Contains(err.Error(), "timed out") {
t.Fatalf("error = %q, want a timeout message", err.Error())
}
// Wrapped, so callers can still classify it.
if !errors.Is(err, errProviderCommandTimeout) {
t.Fatalf("error = %v, want errors.Is against the timeout sentinel", err)
}
// And it must say which phase, rather than only that time ran out.
if !strings.Contains(err.Error(), "did not finish") && !strings.Contains(err.Error(), "starting the command") {
t.Fatalf("error = %q, want it to name the phase that exceeded the deadline", err.Error())
}
}
// The output buffers are written by cmd.Wait's I/O pump, which keeps running
// after the timeout path has returned them to the caller, so a plain
// bytes.Buffer would be read and written concurrently. Asserted on the buffer
// directly: driving it end to end does not reliably produce the overlap, because
// a terminated command usually stops writing before the snapshot is taken, so
// such a test passes with the locking removed and proves nothing.
//
// Only meaningful under -race, which CI runs.
func TestSyncBufferAllowsConcurrentWriteAndSnapshot(t *testing.T) {
buffer := &syncBuffer{}
writing := make(chan struct{})
go func() {
defer close(writing)
for i := 0; i < 2000; i++ {
_, _ = buffer.Write([]byte("x"))
}
}()
for i := 0; i < 2000; i++ {
_ = buffer.snapshot()
}
<-writing
if len(buffer.snapshot()) != 2000 {
t.Fatalf("buffer holds %d bytes, want 2000", len(buffer.snapshot()))
}
}
// The drain after termination must be bounded. Asserted directly on the helper,
// because in place it is untestable without a tree that refuses to die: Wait
// normally returns at once, which is precisely why an unbounded receive sat
// there unnoticed. A channel that never fires is the pathological case made
// cheap.
func TestAwaitWithGraceGivesUp(t *testing.T) {
never := make(chan error)
start := time.Now()
if awaitWithGrace(never, 50*time.Millisecond) {
t.Fatal("reported completion for a wait that never finished")
}
if elapsed := time.Since(start); elapsed > 5*time.Second {
t.Fatalf("gave up after %s, want roughly the grace period", elapsed)
}
// Still reports completion when the wait does finish, or the timeout path
// would always claim the tree hung.
done := make(chan error, 1)
done <- nil
if !awaitWithGrace(done, time.Second) {
t.Fatal("reported expiry for a wait that had already finished")
}
}
// Process creation has to be inside the budget. It used to run before the clock
// started, and on Windows that phase is CREATE_SUSPENDED plus job-object setup
// plus a system-wide thread snapshot, none of it fast on a contended machine.
//
// A budget that is already spent when the call begins can only be exceeded
// during the start, so the phase named in the error is what distinguishes the
// two orderings: with the clock started afterwards, the start would always
// complete first and the failure would come from the wait instead.
func TestRunProviderCommandCountsProcessStartAgainstTheDeadline(t *testing.T) {
command := writeCommand(t, commandScript{Stdout: `{"name":"cmd","provider":"openai","apiKey":"sk-x","model":"m"}`})
_, _, err := runProviderCommand(command, time.Nanosecond)
if !errors.Is(err, errProviderCommandTimeout) {
t.Fatalf("error = %v, want the timeout sentinel", err)
}
if !strings.Contains(err.Error(), "starting the command") {
t.Fatalf("error = %q, want the start phase to be the one that exceeded the deadline; "+
"anything else means process creation is outside the budget again", err.Error())
}
}