diff --git a/internal/base/output/common.go b/internal/base/output/common.go index 8e97c56c..2ab7fbc3 100644 --- a/internal/base/output/common.go +++ b/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 { diff --git a/internal/base/output/messages.go b/internal/base/output/messages.go index a07ea527..eed6854e 100644 --- a/internal/base/output/messages.go +++ b/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") } } } diff --git a/internal/base/output/messages_test.go b/internal/base/output/messages_test.go index 1bd9cb56..a49de53b 100644 --- a/internal/base/output/messages_test.go +++ b/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) diff --git a/internal/base/output/output.go b/internal/base/output/output.go index 7287bec6..a43fe73c 100644 --- a/internal/base/output/output.go +++ b/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() diff --git a/internal/base/output/spinner_stream_race_test.go b/internal/base/output/spinner_stream_race_test.go new file mode 100644 index 00000000..c7605141 --- /dev/null +++ b/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() + }) +}