mirror of
https://github.com/coder/coder.git
synced 2026-09-24 15:04:27 +08:00
fix(cli): discard log writes to closed pipes during shutdown (#26082)
Add clilog.DiscardOnPipeError, an io.Writer wrapper that drops writes failing with io.ErrClosedPipe or syscall.EPIPE, and apply it to the clilog stdout/stderr sinks and the port-forward verbose sink. Background goroutines (e.g. port-forward -v tailnet goroutines) keep logging after the reader on the log destination is gone. slog reports those failed writes to stderr, which is noise and can interleave with and corrupt go test/test2json output, misreporting passing tests as failed. os.ErrClosed and all other errors are still returned, so writes to a writer we closed ourselves are not hidden, and normal CLI pipe semantics are unchanged.
This commit is contained in:
+27
-2
@@ -2,11 +2,14 @@ package clilog
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"fmt"
|
||||
"io"
|
||||
"os"
|
||||
"regexp"
|
||||
"strings"
|
||||
"sync"
|
||||
"syscall"
|
||||
|
||||
"golang.org/x/xerrors"
|
||||
"gopkg.in/natefinch/lumberjack.v2"
|
||||
@@ -106,10 +109,10 @@ func (b *Builder) Build(inv *serpent.Invocation) (log slog.Logger, closeLog func
|
||||
switch loc {
|
||||
case "", "/dev/null":
|
||||
case "/dev/stdout":
|
||||
sinks = append(sinks, sinkFn(inv.Stdout))
|
||||
sinks = append(sinks, sinkFn(MaybeDiscardOnPipeError(inv.Stdout)))
|
||||
|
||||
case "/dev/stderr":
|
||||
sinks = append(sinks, sinkFn(inv.Stderr))
|
||||
sinks = append(sinks, sinkFn(MaybeDiscardOnPipeError(inv.Stderr)))
|
||||
|
||||
default:
|
||||
logWriter := &LumberjackWriteCloseFixer{Writer: &lumberjack.Logger{
|
||||
@@ -238,3 +241,25 @@ func (c *LumberjackWriteCloseFixer) Write(p []byte) (int, error) {
|
||||
}
|
||||
return c.Writer.Write(p)
|
||||
}
|
||||
|
||||
// MaybeDiscardOnPipeError wraps w so writes to alternate CLI sinks that fail
|
||||
// because the reader is gone are dropped. It leaves os.Stdout and os.Stderr
|
||||
// unchanged so production pipe errors keep their existing behavior.
|
||||
func MaybeDiscardOnPipeError(w io.Writer) io.Writer {
|
||||
if w == os.Stdout || w == os.Stderr {
|
||||
return w
|
||||
}
|
||||
return &discardOnPipeError{w: w}
|
||||
}
|
||||
|
||||
type discardOnPipeError struct {
|
||||
w io.Writer
|
||||
}
|
||||
|
||||
func (d *discardOnPipeError) Write(p []byte) (int, error) {
|
||||
n, err := d.w.Write(p)
|
||||
if err != nil && (errors.Is(err, io.ErrClosedPipe) || errors.Is(err, syscall.EPIPE)) {
|
||||
return len(p), nil
|
||||
}
|
||||
return n, err
|
||||
}
|
||||
|
||||
@@ -1,14 +1,18 @@
|
||||
package clilog_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"encoding/json"
|
||||
"io"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"strings"
|
||||
"syscall"
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"golang.org/x/xerrors"
|
||||
|
||||
"github.com/coder/coder/v2/cli/clilog"
|
||||
"github.com/coder/coder/v2/coderd/coderdtest"
|
||||
@@ -146,6 +150,57 @@ func TestBuilder(t *testing.T) {
|
||||
})
|
||||
}
|
||||
|
||||
func TestMaybeDiscardOnPipeError(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
const payload = "log entry"
|
||||
|
||||
t.Run("LeavesStdoutStderrUnchanged", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
require.Same(t, os.Stdout, clilog.MaybeDiscardOnPipeError(os.Stdout))
|
||||
require.Same(t, os.Stderr, clilog.MaybeDiscardOnPipeError(os.Stderr))
|
||||
})
|
||||
|
||||
t.Run("DiscardsClosedPipe", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for _, target := range []error{
|
||||
io.ErrClosedPipe,
|
||||
syscall.EPIPE,
|
||||
xerrors.Errorf("wrapped: %w", io.ErrClosedPipe),
|
||||
xerrors.Errorf("wrapped: %w", syscall.EPIPE),
|
||||
} {
|
||||
fw := &fakeWriter{err: target}
|
||||
n, err := clilog.MaybeDiscardOnPipeError(fw).Write([]byte(payload))
|
||||
require.NoError(t, err, "%v should be discarded", target)
|
||||
assert.Equal(t, len(payload), n)
|
||||
}
|
||||
})
|
||||
|
||||
t.Run("ReportsOtherErrors", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// os.ErrClosed stays reported: a write to a writer we closed ourselves
|
||||
// is worth surfacing.
|
||||
for _, target := range []error{os.ErrClosed, io.ErrShortWrite, xerrors.New("boom")} {
|
||||
fw := &fakeWriter{err: target}
|
||||
_, err := clilog.MaybeDiscardOnPipeError(fw).Write([]byte(payload))
|
||||
require.ErrorIs(t, err, target)
|
||||
}
|
||||
})
|
||||
|
||||
t.Run("PassesThroughSuccess", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
fw := &fakeWriter{}
|
||||
n, err := clilog.MaybeDiscardOnPipeError(fw).Write([]byte(payload))
|
||||
require.NoError(t, err)
|
||||
assert.Equal(t, len(payload), n)
|
||||
assert.Equal(t, payload, fw.buf.String())
|
||||
})
|
||||
}
|
||||
|
||||
var (
|
||||
debug = "DEBUG"
|
||||
info = "INFO"
|
||||
@@ -216,3 +271,15 @@ func assertLogsJSON(t testing.TB, path string, levelExpected ...string) {
|
||||
require.Equal(t, levelExpected[2*i+1], entry.Message)
|
||||
}
|
||||
}
|
||||
|
||||
type fakeWriter struct {
|
||||
buf bytes.Buffer
|
||||
err error
|
||||
}
|
||||
|
||||
func (f *fakeWriter) Write(p []byte) (int, error) {
|
||||
if f.err != nil {
|
||||
return 0, f.err
|
||||
}
|
||||
return f.buf.Write(p)
|
||||
}
|
||||
|
||||
+2
-1
@@ -18,6 +18,7 @@ import (
|
||||
"cdr.dev/slog/v3"
|
||||
"cdr.dev/slog/v3/sloggers/sloghuman"
|
||||
"github.com/coder/coder/v2/agent/agentssh"
|
||||
"github.com/coder/coder/v2/cli/clilog"
|
||||
"github.com/coder/coder/v2/cli/cliui"
|
||||
"github.com/coder/coder/v2/codersdk"
|
||||
"github.com/coder/coder/v2/codersdk/workspacesdk"
|
||||
@@ -111,7 +112,7 @@ func (r *RootCmd) portForward() *serpent.Command {
|
||||
|
||||
logger := inv.Logger
|
||||
if r.verbose {
|
||||
opts.Logger = logger.AppendSinks(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug)
|
||||
opts.Logger = logger.AppendSinks(sloghuman.Sink(clilog.MaybeDiscardOnPipeError(inv.Stdout))).Leveled(slog.LevelDebug)
|
||||
}
|
||||
|
||||
if r.disableDirect {
|
||||
|
||||
Reference in New Issue
Block a user