Skip to content

fix: synchronize prefixed output writer to fix concurrent-write panic - #2949

Open
ankit090701 wants to merge 1 commit into
go-task:mainfrom
ankit090701:fix/prefixed-output-concurrent-write-race
Open

fix: synchronize prefixed output writer to fix concurrent-write panic#2949
ankit090701 wants to merge 1 commit into
go-task:mainfrom
ankit090701:fix/prefixed-output-concurrent-write-race

Conversation

@ankit090701

Copy link
Copy Markdown

What's the bug

With output: prefixed enabled, Task can panic while a command writes to stdout and stderr concurrently:

panic: runtime error: slice bounds out of range [2687:2453]

goroutine 178 [running]:
bytes.(*Buffer).readSlice(...)
        bytes/buffer.go:440
bytes.(*Buffer).ReadString(...)
        bytes/buffer.go:459
github.com/go-task/task/v3/internal/output.(*prefixWriter).writeOutputLines(0xc0001bab90, 0x0)
        github.com/go-task/task/[email protected]/internal/output/prefixed.go:58 +0x3a
github.com/go-task/task/v3/internal/output.(*prefixWriter).Write(...)
        github.com/go-task/task/[email protected]/internal/output/prefixed.go:49 +0x45
io.copyBuffer(...)
        io/io.go:431
os/exec.(*Cmd).writerDescriptor.func1()
        os/exec/exec.go:580

Reproduces with:

version: "3"
output: prefixed
tasks:
  default:
    cmds:
      - |
        for i in $(seq 1 10000); do
          echo "stdout line ${i}" &
          echo "stderr line ${i}" >&2 &
        done
        wait

Root cause

WrapWriter in internal/output/prefixed.go returns the same *prefixWriter instance for both stdout and stderr:

pw := &prefixWriter{writer: stdOut, prefix: prefix, prefixed: p}
return pw, pw, func(error) error { return pw.close() }

os/exec copies a running command's stdout and stderr to their respective writers from two separate goroutines (io.copyBuffer in Cmd.writerDescriptor), so for prefixed output, Write can legitimately be called concurrently on the same prefixWriter by both the stdout- and stderr-copying goroutines of a single task. prefixWriter.Write and writeOutputLines read and write pw.buff (a bytes.Buffer) without any synchronization, and bytes.Buffer is explicitly documented as not safe for concurrent use - concurrent access corrupts its internal length/offset bookkeeping, which is exactly what produces a "slice bounds out of range" panic.

Note that Prefixed.mutex already exists and is held in writeLine, but it only protects the struct shared across all prefixes (the seen map and counter) - it does nothing to protect an individual prefixWriter's own buffer from its two concurrent callers.

The fix

Add a sync.Mutex to prefixWriter and hold it for the full duration of both Write and close (both of which read/mutate pw.buff). This is a distinct, narrower lock than Prefixed.mutex, so there's no risk of the two interacting or deadlocking - writeOutputLines (called while holding prefixWriter.mutex) calls writeLine, which acquires the separate Prefixed.mutex.

Testing

  • Added TestPrefixedConcurrentStdoutStderr (internal/output/output_test.go): spawns two goroutines writing 5000 lines each to stdout and stderr concurrently through the same prefixed writer, then calls cleanup.
  • Verified with go test -race: without the fix, this reliably reproduces both the underlying data race and the exact reported panic (slice bounds out of range) within a handful of runs. With the fix, it passes cleanly (no race, no panic) across repeated runs (-count=5, and again in isolation with -race).
  • Ran the full test suite (go build ./... && go vet ./... && go test ./...) - clean aside from TestEvaluateSymlinksInPaths, which I confirmed is unrelated: it fails the same way with a filesystem/symlink error on an unmodified checkout too, due to how real NTFS symlinks don't survive a Windows→Linux Docker bind mount (I don't have a native Go toolchain on this machine, so I built/tested via Docker).

Fixes #2945

WrapWriter in internal/output/prefixed.go returns the same *prefixWriter
instance for both a task's stdout and stderr:

    pw := &prefixWriter{writer: stdOut, prefix: prefix, prefixed: p}
    return pw, pw, func(error) error { return pw.close() }

os/exec copies a running command's stdout and stderr to their respective
writers from two separate goroutines, so for the "prefixed" output mode,
Write can legitimately be called concurrently on the same prefixWriter by
both the stdout- and stderr-copying goroutines of a single task.
prefixWriter.Write and writeOutputLines read and write pw.buff (a
bytes.Buffer) without any synchronization, and bytes.Buffer is not safe
for concurrent use, so this corrupts its internal state and can panic -
reported as "slice bounds out of range" - whenever a command produces
enough concurrent stdout/stderr output.

Add a mutex to prefixWriter and hold it for the duration of both Write
and close, matching the pattern already used for the separate
Prefixed.mutex that protects the shared prefix/counter map (which does
not, on its own, protect each writer's buffer).

Added TestPrefixedConcurrentStdoutStderr, which spawns two goroutines
writing thousands of lines to stdout and stderr concurrently through the
same prefixed writer. Verified under `go test -race`: without the fix,
this reliably reproduces the exact reported panic (and the underlying
data race); with the fix, it passes cleanly across repeated runs.

Fixes go-task#2945

Signed-off-by: ankit090701 <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

panic in prefixed output when stdout and stderr are written concurrently

1 participant