Skip to content

Commit 93b5136

Browse files
committed
fix(internal/syncwriter): stop corrupting test output on sink write errors
syncwriter reported sink write/sync failures with the builtin println, which writes raw, unsynchronized bytes to fd 2. The message and its trailing newline are emitted as separate syscalls, so under concurrency a test framework's "--- PASS:"/"--- FAIL:" line can interleave inside the message. test2json then fails to record that test's terminal action, and tools like gotestsum report an innocent passing test as unknown/failed. - Write now suppresses benign "destination closed" errors (io.ErrClosedPipe, os.ErrClosed, syscall.EPIPE), mirroring the existing Sync suppression of EINVAL/ENOTTY/EBADF. - The default error handler reports through os.Stderr as a single newline-terminated write instead of the builtin println. Fixes #225.
1 parent 284c50f commit 93b5136

2 files changed

Lines changed: 89 additions & 1 deletion

File tree

internal/syncwriter/syncwriter.go

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,9 @@ func New(w io.Writer) *Writer {
2424
w: w,
2525

2626
errorf: func(f string, v ...interface{}) {
27-
println(fmt.Sprintf(f, v...))
27+
// Avoid the builtin println, which writes to fd 2
28+
// unsynchronized and can corrupt concurrent go test output.
29+
fmt.Fprintf(os.Stderr, f+"\n", v...)
2830
},
2931
}
3032
}
@@ -34,6 +36,12 @@ func (w *Writer) Write(name string, p []byte) {
3436
defer w.mu.Unlock()
3537
_, err := w.w.Write(p)
3638
if err != nil {
39+
// A closed destination is benign: the reader is gone, so the
40+
// entry is undeliverable and not worth reporting.
41+
// See https://github.com/coder/slog/issues/225
42+
if errorsIsAny(err, io.ErrClosedPipe, syscall.EPIPE) {
43+
return
44+
}
3745
w.errorf("%v: failed to write entry: %+v", name, err)
3846
}
3947
}

internal/syncwriter/syncwriter_test.go

Lines changed: 80 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,11 @@
11
package syncwriter
22

33
import (
4+
"fmt"
45
"io"
56
"os"
7+
"strings"
8+
"syscall"
69
"testing"
710

811
"cdr.dev/slog/v3/internal/assert"
@@ -74,6 +77,83 @@ func TestWriter_Sync(t *testing.T) {
7477
})
7578
}
7679

80+
// Benign "destination closed" errors must not be reported.
81+
func TestWriter_Write_suppressesClosedDestinationErrors(t *testing.T) {
82+
t.Parallel()
83+
84+
benign := []error{
85+
io.ErrClosedPipe,
86+
syscall.EPIPE,
87+
fmt.Errorf("wrapped: %w", io.ErrClosedPipe),
88+
}
89+
90+
for _, target := range benign {
91+
target := target
92+
t.Run(fmt.Sprintf("%v", target), func(t *testing.T) {
93+
t.Parallel()
94+
95+
errors := 0
96+
w := New(syncWriter{
97+
wf: func([]byte) (int, error) { return 0, target },
98+
sf: func() error { return nil },
99+
})
100+
w.errorf = func(string, ...interface{}) { errors++ }
101+
102+
w.Write("sloghuman", []byte("entry"))
103+
assert.Equal(t, "errors", 0, errors)
104+
})
105+
}
106+
}
107+
108+
func TestWriter_Write_reportsOtherErrors(t *testing.T) {
109+
t.Parallel()
110+
111+
// os.ErrClosed is not suppressed: it usually means a write to an
112+
// already-closed writer, which is worth surfacing.
113+
for _, target := range []error{io.EOF, os.ErrClosed} {
114+
target := target
115+
t.Run(fmt.Sprintf("%v", target), func(t *testing.T) {
116+
t.Parallel()
117+
118+
errors := 0
119+
w := New(syncWriter{
120+
wf: func([]byte) (int, error) { return 0, target },
121+
sf: func() error { return nil },
122+
})
123+
w.errorf = func(string, ...interface{}) { errors++ }
124+
125+
w.Write("sloghuman", []byte("entry"))
126+
assert.Equal(t, "errors", 1, errors)
127+
})
128+
}
129+
}
130+
131+
// The default handler must report through the os.Stderr variable, not the
132+
// builtin println that bypasses it. Reverting to println fails this test.
133+
//
134+
// Not parallel: it swaps the process-wide os.Stderr.
135+
func TestWriter_defaultErrorReportsThroughStderr(t *testing.T) {
136+
r, w, err := os.Pipe()
137+
assert.Success(t, "pipe", err)
138+
139+
orig := os.Stderr
140+
os.Stderr = w
141+
New(syncWriter{
142+
wf: func([]byte) (int, error) { return 0, io.EOF },
143+
sf: func() error { return nil },
144+
}).Write("sinkname", []byte("entry"))
145+
os.Stderr = orig
146+
assert.Success(t, "close", w.Close())
147+
148+
out, err := io.ReadAll(r)
149+
assert.Success(t, "read", err)
150+
151+
got := string(out)
152+
assert.True(t, "reported via stderr", strings.Contains(got, "sinkname: failed to write entry"))
153+
assert.True(t, "single trailing newline", strings.HasSuffix(got, "\n"))
154+
assert.Equal(t, "newline count", 1, strings.Count(got, "\n"))
155+
}
156+
77157
func Test_errorsIsAny(t *testing.T) {
78158
t.Parallel()
79159

0 commit comments

Comments
 (0)