fix(config): make the provider-command timeout an upper bound (#811)

internal/config/command.go

@@ -8,6 +8,7 @@ import (
 	"os/exec"
 	"runtime"
 	"strings"
+	"sync"
 	"time"
 )
 
@@ -17,7 +18,11 @@ func LoadProviderCommand(command string) (FileConfig, error) {
 	stdout, stderr, err := runProviderCommand(command, providerCommandTimeout)
 	if err != nil {
 		if errors.Is(err, errProviderCommandTimeout) {
-			return FileConfig{}, fmt.Errorf("provider command timed out after 5s")
+			// Report which phase ran out of time, and anything the command
+			// managed to say. This used to be a bare string with the underlying
+			// error and stderr both dropped, which left a user whose command was
+			// slow on a cold machine with nothing to act on.
+			return FileConfig{}, fmt.Errorf("provider command timed out after %s: %w%s", providerCommandTimeout, err, commandOutput(stderr))
 		}
 		return FileConfig{}, fmt.Errorf("provider command failed: %w%s", err, commandOutput(stderr))
 	}
@@ -40,20 +45,111 @@ func LoadProviderCommand(command string) (FileConfig, error) {
 
 var errProviderCommandTimeout = errors.New("provider command timeout")
 
+// providerCommandDrainGrace bounds how long the timeout path waits for cmd.Wait
+// to return after the process tree has been terminated. Terminate normally makes
+// that immediate; this exists so a descendant that refuses to die cannot extend
+// a call whose deadline has already expired.
+const providerCommandDrainGrace = 2 * time.Second
+
+// syncBuffer serialises the command's I/O pump against reads from this package.
+// On the timeout path runProviderCommand can return while cmd.Wait is still
+// draining, so the buffers outlive the call and a plain bytes.Buffer would be
+// read and written concurrently.
+type syncBuffer struct {
+	mu  sync.Mutex
+	buf bytes.Buffer
+}
+
+func (b *syncBuffer) Write(p []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buf.Write(p)
+}
+
+// snapshot copies out what has been written so far. A copy rather than the
+// buffer's own slice, which the pump may still append to.
+func (b *syncBuffer) snapshot() []byte {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return append([]byte(nil), b.buf.Bytes()...)
+}
+
+// awaitWithGrace waits for done and gives up after grace, reporting whether the
+// wait completed rather than expired.
+//
+// Split out from the timeout path so the bound can be asserted on its own. In
+// place it is effectively untestable: Terminate kills the tree, so Wait returns
+// promptly and an unbounded receive would behave identically in every test that
+// is not pathological, which is exactly how the old unbounded receive survived.
+func awaitWithGrace(done <-chan error, grace time.Duration) bool {
+	timer := time.NewTimer(grace)
+	defer timer.Stop()
+	select {
+	case <-done:
+		return true
+	case <-timer.C:
+		return false
+	}
+}
+
+// runProviderCommand runs a provider command under a real deadline.
+//
+// "Real" is the point: timeout used to bound only the wait, so the call could
+// take arbitrarily longer than it. Two phases sat outside it. Starting the
+// process ran before the clock began, and on Windows that is CREATE_SUSPENDED,
+// job-object creation and assignment, and a system-wide thread snapshot, none of
+// which is fast on a cold or contended machine. Draining after termination was
+// unbounded as well. Both are inside the budget now, so the deadline is an upper
+// bound rather than a floor.
 func runProviderCommand(command string, timeout time.Duration) ([]byte, []byte, error) {
 	cmd := shellCommand(command)
 	// Bound the time Wait spends draining I/O pipes after the process exits,
 	// in case an orphaned descendant still holds the write ends open.
 	cmd.WaitDelay = time.Second
 
-	var stdout bytes.Buffer
-	var stderr bytes.Buffer
-	cmd.Stdout = &stdout
-	cmd.Stderr = &stderr
+	stdout := &syncBuffer{}
+	stderr := &syncBuffer{}
+	cmd.Stdout = stdout
+	cmd.Stderr = stderr
 
-	proc, err := startCommandProcess(cmd)
-	if err != nil {
-		return nil, nil, err
+	// Armed before the process is started, so process creation is inside the
+	// budget rather than ahead of it.
+	deadline := time.NewTimer(timeout)
+	defer deadline.Stop()
+
+	type startResult struct {
+		proc *commandProcess
+		err  error
+	}
+	// Buffered, so the goroutine can finish and exit even when nobody is left
+	// waiting on it because the deadline already fired.
+	started := make(chan startResult, 1)
+	go func() {
+		proc, err := startCommandProcess(cmd)
+		started <- startResult{proc: proc, err: err}
+	}()
+
+	var proc *commandProcess
+	select {
+	case result := <-started:
+		if result.err != nil {
+			return stdout.snapshot(), stderr.snapshot(), result.err
+		}
+		proc = result.proc
+	case <-deadline.C:
+		// The start is still in flight and will eventually hand back whatever it
+		// created, so cleanup is handed off rather than abandoned. Wait reaps the
+		// process; without it a started-but-orphaned command becomes a zombie.
+		go func() {
+			result := <-started
+			if result.err != nil {
+				return
+			}
+			result.proc.Terminate()
+			_ = cmd.Wait()
+			result.proc.Close()
+		}()
+		return stdout.snapshot(), stderr.snapshot(), fmt.Errorf("%w: starting the command exceeded %s", errProviderCommandTimeout, timeout)
 	}
 	defer proc.Close()
 
@@ -62,9 +158,6 @@ func runProviderCommand(command string, timeout time.Duration) ([]byte, []byte,
 		done <- cmd.Wait()
 	}()
 
-	timer := time.NewTimer(timeout)
-	defer timer.Stop()
-
 	select {
 	case err := <-done:
 		if err != nil {
@@ -83,13 +176,19 @@ func runProviderCommand(command string, timeout time.Duration) ([]byte, []byte,
 			// 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.snapshot(), stderr.snapshot(), fmt.Errorf("%w: %w", errProviderCommandTimeout, err)
 		}
-		return stdout.Bytes(), stderr.Bytes(), err
-	case <-timer.C:
+		return stdout.snapshot(), stderr.snapshot(), err
+	case <-deadline.C:
 		proc.Terminate()
-		<-done
-		return stdout.Bytes(), stderr.Bytes(), errProviderCommandTimeout
+		// Bounded, unlike the bare receive this replaces. Terminate kills the
+		// tree so Wait almost always returns at once, but "almost always" was
+		// doing real work here: a tree that resists termination used to hold the
+		// call open indefinitely, long past the deadline that had just expired.
+		// Returning early leaves cmd.Wait running, which is why the buffers are
+		// synchronised.
+		awaitWithGrace(done, providerCommandDrainGrace)
+		return stdout.snapshot(), stderr.snapshot(), fmt.Errorf("%w: the command did not finish within %s", errProviderCommandTimeout, timeout)
 	}
 }
 

internal/config/command_test.go

@@ -414,3 +414,133 @@ func itoa(value int) string {
 	}
 	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())
+	}
+}