ESD-1644-fix(output): stop spinner from racing os.Stdout swaps

internal/base/output/common.go

@@ -16,6 +16,14 @@ import (
 // Both native and WASM builds use this mutex.
 var stdoutMu sync.Mutex
 
+// stdErrStreamMu guards os.Stderr reassignment (CaptureOutput/CaptureOutputErr,
+// via setStderr in output.go) against concurrent stderr writes (the spinner's
+// animation frames and status lines, via writeSpinnerLine/writeSpinnerLinef in
+// messages.go). It is held only for the instant of a single read-and-write or
+// a single reassignment, never across an entire captured callback, so a
+// callback that itself starts and stops a spinner cannot deadlock against it.
+var stdErrStreamMu sync.RWMutex
+
 // OutputConfig holds all user-facing output configuration as a single struct.
 // Use ApplyOutputConfig to write and GetOutputConfig to read atomically.
 type OutputConfig struct {

internal/base/output/messages.go

@@ -240,6 +240,23 @@ func (s *Spinner) renderFrame(i int) string {
 	return color.CyanString(frame)
 }
 
+// writeSpinnerLine writes s to os.Stderr, matching the rest of the package's
+// status-message convention, synchronized against concurrent os.Stderr
+// reassignment via stdErrStreamMu.
+func writeSpinnerLine(s string) {
+	stdErrStreamMu.RLock()
+	defer stdErrStreamMu.RUnlock()
+	fmt.Fprint(os.Stderr, s)
+}
+
+// writeSpinnerLinef is the formatted counterpart to writeSpinnerLine, used in
+// the animation loop to avoid a fmt.Sprintf allocation on every frame.
+func writeSpinnerLinef(format string, args ...interface{}) {
+	stdErrStreamMu.RLock()
+	defer stdErrStreamMu.RUnlock()
+	fmt.Fprintf(os.Stderr, format, args...)
+}
+
 // nonInteractive reports whether the spinner's sink is non-interactive: a
 // machine-readable output format, or output not attached to a TTY. In those
 // sinks the carriage-return/clear-line escapes don't collapse anything, so the
@@ -271,7 +288,7 @@ func (s *Spinner) runLoop(prefix string, startTime *time.Time) {
 	s.mu.Unlock()
 
 	if s.nonInteractive() {
-		fmt.Fprintf(os.Stderr, "%s\n", prefix)
+		writeSpinnerLinef("%s\n", prefix)
 		return
 	}
 
@@ -295,7 +312,7 @@ func (s *Spinner) runLoop(prefix string, startTime *time.Time) {
 					msg = fmt.Sprintf("%s (%s elapsed)", prefix, elapsed)
 				}
 
-				fmt.Printf("\r\033[K%s %s", styledFrame, msg)
+				writeSpinnerLinef("\r\033[K%s %s", styledFrame, msg)
 				s.mu.Unlock()
 				time.Sleep(s.frameRate)
 			}
@@ -322,10 +339,10 @@ func (s *Spinner) Stop() {
 	s.stopped = true
 	s.mu.Unlock()
 	s.stop <- true
-	// Only the animated TTY path leaves a frame on stdout to clear; in a
-	// non-interactive sink a bare clear sequence would just be junk in logs.
+	// Only the animated TTY path leaves a frame to clear; in a non-interactive
+	// sink a bare clear sequence would just be junk in logs.
 	if !s.nonInteractive() {
-		fmt.Print("\r\033[K")
+		writeSpinnerLine("\r\033[K")
 	}
 }
 
@@ -351,17 +368,15 @@ func (s *Spinner) StopWithSuccess(msg string) {
 	// corrupting machine-readable output streams.
 	if s.nonInteractive() {
 		if s.noColor {
-			fmt.Fprintf(os.Stderr, "✓ %s\n", msg)
+			writeSpinnerLinef("✓ %s\n", msg)
 		} else {
-			fmt.Fprint(os.Stderr, color.GreenString("✓ "))
-			fmt.Fprintln(os.Stderr, msg)
+			writeSpinnerLine(color.GreenString("✓ ") + msg + "\n")
 		}
 	} else {
 		if s.noColor {
-			fmt.Printf("✓ %s\n", msg)
+			writeSpinnerLinef("✓ %s\n", msg)
 		} else {
-			fmt.Print(color.GreenString("✓ "))
-			fmt.Println(msg)
+			writeSpinnerLine(color.GreenString("✓ ") + msg + "\n")
 		}
 	}
 }

internal/base/output/messages_test.go

@@ -181,12 +181,16 @@ func TestSpinner(t *testing.T) {
 	assert.Equal(t, 100*time.Millisecond, spinner.frameRate)
 	assert.True(t, spinner.noColor)
 
-	output := captureOutput(func() {
-		spinner.Start("Testing spinner")
-		time.Sleep(500 * time.Millisecond)
-		spinner.Stop()
+	var stdout string
+	stderr := captureStderr(t, func() {
+		stdout = captureOutput(func() {
+			spinner.Start("Testing spinner")
+			time.Sleep(500 * time.Millisecond)
+			spinner.Stop()
+		})
 	})
-	assert.NotEmpty(t, output)
+	assert.NotEmpty(t, stderr, "spinner frames must be written to stderr")
+	assert.Empty(t, stdout, "spinner frames must never be written to stdout")
 }
 
 func TestPrintResourceSpinners(t *testing.T) {
@@ -241,7 +245,7 @@ func TestPrintResourceSpinners(t *testing.T) {
 
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			output := captureOutput(func() {
+			output := captureStderr(t, func() {
 				spinner := tt.function(tt.resourceType, tt.uid, tt.noColor)
 				time.Sleep(200 * time.Millisecond)
 				spinner.Stop()
@@ -259,7 +263,7 @@ func TestPrintResourceListing(t *testing.T) {
 	t.Cleanup(func() { SetIsTerminal(orig) })
 	SetIsTerminal(true)
 
-	output := captureOutput(func() {
+	output := captureStderr(t, func() {
 		spinner := PrintResourceListing("Port", true)
 		time.Sleep(200 * time.Millisecond)
 		spinner.Stop()
@@ -513,7 +517,7 @@ func TestPrintResourceProvisioning(t *testing.T) {
 	SetIsTerminal(true)
 
 	t.Run("shows provisioning message with elapsed time", func(t *testing.T) {
-		output := captureOutput(func() {
+		output := captureStderr(t, func() {
 			spinner := PrintResourceProvisioning("Port", "port-123", true)
 			time.Sleep(200 * time.Millisecond)
 			spinner.Stop()
@@ -541,7 +545,7 @@ func TestStartWithElapsed(t *testing.T) {
 
 	t.Run("appends elapsed time to message", func(t *testing.T) {
 		spinner := NewSpinner(true)
-		output := captureOutput(func() {
+		output := captureStderr(t, func() {
 			spinner.StartWithElapsed("Provisioning Port...")
 			time.Sleep(1100 * time.Millisecond)
 			spinner.Stop()
@@ -566,7 +570,7 @@ func TestStartWithElapsed(t *testing.T) {
 	t.Run("wasm style uses wasm chars", func(t *testing.T) {
 		spinner := NewSpinner(true)
 		spinner.style = "wasm"
-		output := captureOutput(func() {
+		output := captureStderr(t, func() {
 			spinner.StartWithElapsed("Provisioning...")
 			time.Sleep(200 * time.Millisecond)
 			spinner.Stop()
@@ -603,7 +607,7 @@ func TestSpinnerStopWithSuccess(t *testing.T) {
 	t.Cleanup(func() { SetIsTerminal(orig) })
 	SetIsTerminal(true)
 
-	output := captureOutput(func() {
+	output := captureStderr(t, func() {
 		spinner := NewSpinner(true)
 		spinner.Start("Testing")
 		time.Sleep(200 * time.Millisecond)

internal/base/output/output.go

@@ -176,6 +176,15 @@ var createTempFile = func() (*os.File, error) {
 	return os.CreateTemp("", "capture-stdout-*")
 }
 
+// setStderr reassigns os.Stderr under stdErrStreamMu (declared in common.go),
+// synchronizing the change against concurrent spinner writes. Held only for
+// the instant of the reassignment, never across the caller's function.
+func setStderr(f *os.File) {
+	stdErrStreamMu.Lock()
+	os.Stderr = f
+	stdErrStreamMu.Unlock()
+}
+
 // CaptureOutput runs f and returns everything it writes to stdout and stderr
 // combined. Status messages route to stderr and data to stdout, so a test that
 // wants all user-facing output captures both. Use CaptureStdout when asserting
@@ -197,8 +206,11 @@ func CaptureOutput(f func()) string {
 	defer tmp.Close()
 
 	os.Stdout = tmp
-	os.Stderr = tmp
-	defer func() { os.Stdout = oldOut; os.Stderr = oldErr }()
+	setStderr(tmp)
+	defer func() {
+		os.Stdout = oldOut
+		setStderr(oldErr)
+	}()
 
 	f()
 
@@ -254,8 +266,11 @@ func CaptureOutputErr(f func() error) (string, error) {
 	defer tmp.Close()
 
 	os.Stdout = tmp
-	os.Stderr = tmp
-	defer func() { os.Stdout = oldOut; os.Stderr = oldErr }()
+	setStderr(tmp)
+	defer func() {
+		os.Stdout = oldOut
+		setStderr(oldErr)
+	}()
 
 	runErr := f()
 

internal/base/output/spinner_stream_race_test.go

@@ -0,0 +1,90 @@
+//go:build !wasm
+
+package output
+
+import (
+	"fmt"
+	"sync"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+// TestSpinnerRunWithPagerRace is a regression test for ESD-1644: a live
+// spinner animating in the background must not race with RunWithPager
+// concurrently swapping os.Stdout, and its frames (now routed to stderr)
+// must never bleed into the pager's captured stdout content. Run with
+// -race to exercise the regression this guards against.
+func TestSpinnerRunWithPagerRace(t *testing.T) {
+	if testing.Short() {
+		t.Skip("skipping timing-sensitive race regression test")
+	}
+	orig := isTerminalCached.Load()
+	t.Cleanup(func() { SetIsTerminal(orig) })
+	SetIsTerminal(true)
+
+	// Tall terminal so RunWithPager always takes the direct-write path.
+	setTerminalHeightForTesting(1000)
+	t.Cleanup(func() { setTerminalHeightForTesting(0) })
+
+	const iterations = 30
+
+	stdout := captureStdout(t, func() {
+		captureStderr(t, func() {
+			spinner := NewSpinner(true)
+			spinner.Start("Racing...")
+
+			var wg sync.WaitGroup
+			for i := 0; i < iterations; i++ {
+				wg.Add(1)
+				go func(i int) {
+					defer wg.Done()
+					_ = RunWithPager(func() error {
+						fmt.Printf("row%d\n", i)
+						return nil
+					})
+				}(i)
+			}
+			wg.Wait()
+			spinner.Stop()
+		})
+	})
+
+	for i := 0; i < iterations; i++ {
+		assert.Contains(t, stdout, fmt.Sprintf("row%d", i))
+	}
+	assert.NotContains(t, stdout, "\r\033[K",
+		"spinner frames must never bleed into the pager's stdout content")
+}
+
+// TestSpinnerCaptureOutputRace is a regression test for ESD-1644: a live
+// spinner writing to os.Stderr must not race with CaptureOutput
+// concurrently reassigning both os.Stdout and os.Stderr. Run with -race to
+// exercise the regression this guards against.
+func TestSpinnerCaptureOutputRace(t *testing.T) {
+	if testing.Short() {
+		t.Skip("skipping timing-sensitive race regression test")
+	}
+	orig := isTerminalCached.Load()
+	t.Cleanup(func() { SetIsTerminal(orig) })
+	SetIsTerminal(true)
+
+	captureStderr(t, func() {
+		spinner := NewSpinner(true)
+		spinner.Start("Racing...")
+
+		var wg sync.WaitGroup
+		const iterations = 30
+		for i := 0; i < iterations; i++ {
+			wg.Add(1)
+			go func(i int) {
+				defer wg.Done()
+				CaptureOutput(func() {
+					fmt.Printf("captured%d\n", i)
+				})
+			}(i)
+		}
+		wg.Wait()
+		spinner.Stop()
+	})
+}