Skip to content

fix: synchronize test logs to prevent t.Log race condition #146

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
May 25, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
41 changes: 33 additions & 8 deletions sloggers/slogtest/t.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ import (
"context"
"log"
"os"
"sync"
"testing"

"cdr.dev/slog"
Expand All @@ -28,26 +29,50 @@ type Options struct {
// IgnoreErrors causes the test logger to not fatal the test
// on Fatal and not error the test on Error or Critical.
IgnoreErrors bool
// SkipCleanup skips adding a t.Cleanup call that prevents the logger from
// logging after a test has exited. This is necessary because race
// conditions exist when t.Log is called concurrently of a test exiting. Set
// to true if you don't need this behavior.
SkipCleanup bool
}

// Make creates a Logger that writes logs to tb in a human readable format.
func Make(tb testing.TB, opts *Options) slog.Logger {
if opts == nil {
opts = &Options{}
}
return slog.Make(testSink{

sink := &testSink{
tb: tb,
opts: opts,
})
}
if !opts.SkipCleanup {
tb.Cleanup(func() {
sink.mu.Lock()
defer sink.mu.Unlock()
sink.testDone = true
})
}

return slog.Make(sink)
}

type testSink struct {
tb testing.TB
opts *Options
stdlib bool
tb testing.TB
opts *Options
mu sync.RWMutex
testDone bool
}

func (ts testSink) LogEntry(ctx context.Context, ent slog.SinkEntry) {
func (ts *testSink) LogEntry(ctx context.Context, ent slog.SinkEntry) {
ts.mu.RLock()
defer ts.mu.RUnlock()

// Don't log after the test this sink was created in has finished.
if ts.testDone {
return
}

// The testing package logs to stdout and not stderr.
s := entryhuman.Fmt(os.Stdout, ent)

Expand All @@ -65,12 +90,12 @@ func (ts testSink) LogEntry(ctx context.Context, ent slog.SinkEntry) {
}
}

func (ts testSink) Sync() {}
func (ts *testSink) Sync() {}

var ctx = context.Background()

func l(t testing.TB) slog.Logger {
return Make(t, nil)
return Make(t, &Options{SkipCleanup: true})
}

// Debug logs the given msg and fields to t via t.Log at the debug level.
Expand Down
40 changes: 37 additions & 3 deletions sloggers/slogtest/t_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -45,18 +45,48 @@ func TestIgnoreErrors(t *testing.T) {
l.Fatal(bg, "hello")
}

func TestCleanup(t *testing.T) {
t.Parallel()

tb := &fakeTB{}
l := slogtest.Make(tb, &slogtest.Options{})

for _, fn := range tb.cleanups {
fn()
}

// This shoud not log since the logger was cleaned up.
l.Info(bg, "hello")
assert.Equal(t, "no logs", 0, tb.logs)
}

func TestSkipCleanup(t *testing.T) {
t.Parallel()

tb := &fakeTB{}
slogtest.Make(tb, &slogtest.Options{
SkipCleanup: true,
})

assert.Len(t, "no cleanups", 0, tb.cleanups)
}

var bg = context.Background()

type fakeTB struct {
testing.TB

errors int
fatals int
logs int
errors int
fatals int
cleanups []func()
}

func (tb *fakeTB) Helper() {}

func (tb *fakeTB) Log(v ...interface{}) {}
func (tb *fakeTB) Log(v ...interface{}) {
tb.logs++
}

func (tb *fakeTB) Error(v ...interface{}) {
tb.errors++
Expand All @@ -66,3 +96,7 @@ func (tb *fakeTB) Fatal(v ...interface{}) {
tb.fatals++
panic("")
}

func (tb *fakeTB) Cleanup(fn func()) {
tb.cleanups = append(tb.cleanups, fn)
}