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

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.

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