ESD-1644-fix(output): stop spinner from racing os.Stdout swaps#531
ESD-1644-fix(output): stop spinner from racing os.Stdout swaps#531Phil-Browne wants to merge 9 commits into
Conversation
The spinner animation goroutine wrote its ANSI frames straight to os.Stdout with an unsynchronized fmt.Printf, while RunWithPager and CaptureOutput/CaptureOutputErr reassign os.Stdout (and, for the latter two, os.Stderr) under their own mutexes. A live spinner overlapping one of those swaps is a data race under -race, and any frame that lands in the pager's temp file shows up as corruption in the paged output. Route spinner frames to os.Stderr, matching every other status message in the package, and add a narrowly-scoped mutex so a frame write and a CaptureOutput/CaptureOutputErr os.Stderr swap can never race. The lock is held only for the instant of each read or reassignment, never across a whole captured callback, so starting/stopping a spinner from inside a captured call cannot deadlock against it. RunWithPager and CaptureStdout only ever touch os.Stdout, which the spinner no longer writes to, so they need no new locking.
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #531 +/- ##
==========================================
+ Coverage 79.29% 79.33% +0.03%
==========================================
Files 193 193
Lines 18683 18699 +16
==========================================
+ Hits 14814 14834 +20
+ Misses 2820 2817 -3
+ Partials 1049 1048 -1
🚀 New features to boost your workflow:
|
setStderr's only caller (CaptureOutput/CaptureOutputErr) lives in output.go, which is //go:build !wasm. Defining setStderr in the untagged messages.go left it with no reference under a js/wasm build, which golangci-lint's unused check correctly flagged.
There was a problem hiding this comment.
Pull request overview
Fixes a concurrency issue in the internal/base/output package where the spinner’s background animation output could race with helpers that swap os.Stdout/os.Stderr (pager buffering and output capture), potentially triggering -race failures and corrupting captured/paged output.
Changes:
- Routes spinner animation frames to
os.Stderrand synchronizes frame writes withos.Stderrreassignment. - Updates
CaptureOutput/CaptureOutputErrto swapos.Stderrvia a synchronized helper. - Adjusts existing tests to assert spinner output on stderr and adds new
-raceregression tests for spinner vs pager/capture interactions.
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
| internal/base/output/spinner_stream_race_test.go | Adds race regression tests covering spinner concurrency with RunWithPager and CaptureOutput. |
| internal/base/output/output.go | Switches stderr swapping in capture helpers to a synchronized setStderr(...) call. |
| internal/base/output/messages.go | Moves spinner frame output to stderr and adds stdErrStreamMu + writeSpinnerLine(...) / setStderr(...) synchronization. |
| internal/base/output/messages_test.go | Updates spinner-related assertions to validate stderr output (and stdout cleanliness). |
Comments suppressed due to low confidence (1)
internal/base/output/messages.go:323
writeSpinnerLinenow synchronizes the animated TTY spinner frames againstsetStderr, butrunLoop's non-interactive path still writes toos.Stderrdirectly (fmt.Fprintf(os.Stderr, ...)). That write can still race withCaptureOutput/CaptureOutputErrswappingos.Stderr, so the spinner isn’t fully protected in non-interactive mode.
Consider routing the non-interactive write through writeSpinnerLine (or taking stdErrStreamMu) as well, so all spinner stderr writes are synchronized with setStderr.
s.mu.Lock()
runLoop's non-interactive prefix line and StopWithSuccess's non-interactive success line wrote straight to os.Stderr, bypassing stdErrStreamMu. Route both through writeSpinnerLine so they can't race CaptureOutput/CaptureOutputErr reassigning os.Stderr either.
… loop writeSpinnerLine(fmt.Sprintf(...)) built a formatted string on every animation tick before writing it. Add writeSpinnerLinef, a synchronized fmt.Fprintf wrapper, and use it in the hot loop to skip the extra allocation.
…test stdErrStreamMu guards os.Stderr reassignment for both the spinner (messages.go) and CaptureOutput/CaptureOutputErr (output.go), but lived in messages.go with a spinner-specific doc comment, making it easy to miss as a general stream-swap lock. Move it to common.go next to the equivalent stdoutMu. Also wrap TestSpinnerCaptureOutputRace's body in captureStderr so a live spinner's frames don't leak into test output on -v or failure.
…er writes Two more spinner writes built a string via fmt.Sprintf before handing it to writeSpinnerLine. Switch both to writeSpinnerLinef to drop the intermediate allocation, consistent with the animation loop.
|
The race fix is correct: frames now go to |
penzeliz-megaport
left a comment
penzeliz-megaport
left a comment
There was a problem hiding this comment.
Reviewed for correctness; findings noted in comments are non-blocking. LGTM.
…nerLine The animated-TTY branch still wrote its success line to stdout via an unsynchronized fmt.Printf, contradicting the package's stderr-only status-message convention and leaving the same unsynchronized stdout write class this PR fixes elsewhere. Route it through writeSpinnerLine so it's synchronized against stream reassignment and lands on stderr like every other status message.
|
Good catch, fixed in e537500. Routed the interactive branch of StopWithSuccess through writeSpinnerLine/writeSpinnerLinef, so it's now synchronized against stream reassignment and lands on stderr like every other status message in the package. Note this reverses the earlier call to leave it as-is: on reflection the stdout write was the same unsynchronized-stream-write pattern this PR exists to fix, just with lower odds of firing, so it's in scope. Updated TestSpinnerStopWithSuccess to assert on stderr instead of stdout. Full test suite, -race, and lint all pass. |
Fixes ESD-1644.
The spinner's animation goroutine wrote frames straight to
os.Stdoutwith an unsynchronizedfmt.Printf, whileRunWithPagerandCaptureOutput/CaptureOutputErrreassignos.Stdout(and, for the latter two,os.Stderr) under their own mutexes. A live spinner overlapping one of those swaps was a data race under-race, and any frame that landed in the pager's temp file showed up as visible corruption in the paged output.os.Stderr, matching every other status message in the package.stdErrStreamMuso a spinner frame write and aCaptureOutput/CaptureOutputErrstderr swap can never race. It's held only for the instant of each read or reassignment, never across a whole captured callback, so starting/stopping a spinner from inside a captured call can't deadlock against it.RunWithPagerandCaptureStdoutneed no changes: they only ever touchos.Stdout, and the spinner no longer writes there.-raceregression test that runs a live spinner concurrently withRunWithPagerandCaptureOutput, asserting no race and no frame bleed into captured output.Test plan
go build ./...go test ./...go test -race ./internal/base/output/...golangci-lint run-raceflags the exact write/read reported in the ticket, then restored the fix)