From 79e323d6b1f9ae9e6cf94b78eb3ac12ec8db9a7f Mon Sep 17 00:00:00 2001 From: bill fumerola Date: Tue, 14 Mar 2017 10:26:47 -0700 Subject: [PATCH] Export zap's internal observing logger (#372) Simplify `internal/observer` and export it as `zaptest/observer`. --- Makefile | 2 +- common_test.go | 7 +- global_test.go | 2 +- logger_test.go | 2 +- sugar_test.go | 8 +-- zapcore/hook_test.go | 9 ++- zapcore/sampler_test.go | 13 ++-- zapcore/tee_test.go | 28 ++++---- {internal => zaptest}/observer/observer.go | 57 ++++------------ .../observer/observer_test.go | 65 +++++++++---------- 10 files changed, 74 insertions(+), 119 deletions(-) rename {internal => zaptest}/observer/observer.go (75%) rename {internal => zaptest}/observer/observer_test.go (68%) diff --git a/Makefile b/Makefile index 48398e19d..d772c7ca5 100644 --- a/Makefile +++ b/Makefile @@ -3,7 +3,7 @@ export GO15VENDOREXPERIMENT=1 BENCH_FLAGS ?= -cpuprofile=cpu.pprof -memprofile=mem.pprof -benchmem PKGS ?= $(shell glide novendor) # Many Go tools take file globs or directories as arguments instead of packages. -PKG_FILES ?= *.go zapcore benchmarks buffer zaptest internal/bufferpool internal/exit internal/multierror internal/observer internal/color +PKG_FILES ?= *.go zapcore benchmarks buffer zaptest zaptest/observer internal/bufferpool internal/exit internal/multierror internal/color COVERALLS_IGNORE := internal/readme/readme.go diff --git a/common_test.go b/common_test.go index f057ac272..b0a4a2e52 100644 --- a/common_test.go +++ b/common_test.go @@ -24,8 +24,8 @@ import ( "sync" "testing" - "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" ) func opts(opts ...Option) []Option { @@ -35,10 +35,9 @@ func opts(opts ...Option) []Option { // Here specifically to introduce an easily-identifiable filename for testing // stacktraces and caller skips. func withLogger(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(*Logger, *observer.ObservedLogs)) { - var logs observer.ObservedLogs - fac := observer.New(e, logs.Add, true) + fac, logs := observer.New(e) log := New(fac, opts...) - f(log, &logs) + f(log, logs) } func withSugar(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(*SugaredLogger, *observer.ObservedLogs)) { diff --git a/global_test.go b/global_test.go index b6407f430..ff4f4df1f 100644 --- a/global_test.go +++ b/global_test.go @@ -26,9 +26,9 @@ import ( "testing" "time" - "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" diff --git a/logger_test.go b/logger_test.go index 4883b820d..edd895094 100644 --- a/logger_test.go +++ b/logger_test.go @@ -26,9 +26,9 @@ import ( "testing" "go.uber.org/zap/internal/exit" - "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" diff --git a/sugar_test.go b/sugar_test.go index 5bea33535..69eb1fa63 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -23,13 +23,13 @@ package zap import ( "testing" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "go.uber.org/zap/internal/exit" - "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestSugarWith(t *testing.T) { diff --git a/zapcore/hook_test.go b/zapcore/hook_test.go index 787e3d3f5..0764888ab 100644 --- a/zapcore/hook_test.go +++ b/zapcore/hook_test.go @@ -23,10 +23,10 @@ package zapcore_test import ( "testing" - "github.com/stretchr/testify/assert" - - "go.uber.org/zap/internal/observer" . "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/stretchr/testify/assert" ) func TestHooks(t *testing.T) { @@ -41,8 +41,7 @@ func TestHooks(t *testing.T) { } for _, tt := range tests { - var logs observer.ObservedLogs - fac := observer.New(tt.coreLevel, logs.Add, true) + fac, logs := observer.New(tt.coreLevel) intField := makeInt64Field("foo", 42) ent := Entry{Message: "bar", Level: tt.entryLevel} diff --git a/zapcore/sampler_test.go b/zapcore/sampler_test.go index 0cf6c2c16..82588c9a9 100644 --- a/zapcore/sampler_test.go +++ b/zapcore/sampler_test.go @@ -26,20 +26,19 @@ import ( "testing" "time" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "go.uber.org/atomic" - "go.uber.org/zap/internal/observer" . "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func fakeSampler(lvl LevelEnabler, tick time.Duration, first, thereafter int) (Core, *observer.ObservedLogs) { - var logs observer.ObservedLogs - core := observer.New(lvl, logs.Add, true) + core, logs := observer.New(lvl) core = NewSampler(core, tick, first, thereafter) - return core, &logs + return core, logs } func assertSequence(t testing.TB, logs []observer.LoggedEntry, lvl Level, seq ...int64) { diff --git a/zapcore/tee_test.go b/zapcore/tee_test.go index 48e83a8f4..754abbb83 100644 --- a/zapcore/tee_test.go +++ b/zapcore/tee_test.go @@ -24,26 +24,24 @@ import ( "errors" "testing" - "go.uber.org/zap/internal/observer" . "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" "github.com/stretchr/testify/assert" ) func withTee(f func(core Core, debugLogs, warnLogs *observer.ObservedLogs)) { - var debugLogs, warnLogs observer.ObservedLogs - tee := NewTee( - observer.New(DebugLevel, debugLogs.Add, true), - observer.New(WarnLevel, warnLogs.Add, true), - ) - f(tee, &debugLogs, &warnLogs) + debugLogger, debugLogs := observer.New(DebugLevel) + warnLogger, warnLogs := observer.New(WarnLevel) + tee := NewTee(debugLogger, warnLogger) + f(tee, debugLogs, warnLogs) } func TestTeeUnusualInput(t *testing.T) { // Verify that Tee handles receiving one and no inputs correctly. t.Run("one input", func(t *testing.T) { - obs := observer.New(DebugLevel, nil, true) + obs, _ := observer.New(DebugLevel) assert.Equal(t, obs, NewTee(obs), "Expected to return single inputs unchanged.") }) t.Run("no input", func(t *testing.T) { @@ -114,10 +112,9 @@ func TestTeeWith(t *testing.T) { } func TestTeeEnabled(t *testing.T) { - tee := NewTee( - observer.New(InfoLevel, nil, false), - observer.New(WarnLevel, nil, false), - ) + infoLogger, _ := observer.New(InfoLevel) + warnLogger, _ := observer.New(WarnLevel) + tee := NewTee(infoLogger, warnLogger) tests := []struct { lvl Level enabled bool @@ -137,10 +134,9 @@ func TestTeeEnabled(t *testing.T) { } func TestTeeSync(t *testing.T) { - tee := NewTee( - observer.New(InfoLevel, nil, false), - observer.New(WarnLevel, nil, false), - ) + infoLogger, _ := observer.New(InfoLevel) + warnLogger, _ := observer.New(WarnLevel) + tee := NewTee(infoLogger, warnLogger) assert.NoError(t, tee.Sync(), "Unexpected error from Syncing a tee.") sink := &zaptest.Discarder{} diff --git a/internal/observer/observer.go b/zaptest/observer/observer.go similarity index 75% rename from internal/observer/observer.go rename to zaptest/observer/observer.go index 819f7a1e6..0f6462d3d 100644 --- a/internal/observer/observer.go +++ b/zaptest/observer/observer.go @@ -40,15 +40,6 @@ type ObservedLogs struct { logs []LoggedEntry } -// Add appends a new observed log to the collection. It always returns nil -// error, but does so that it can be used as an observer sink function. -func (o *ObservedLogs) Add(log LoggedEntry) error { - o.mu.Lock() - o.logs = append(o.logs, log) - o.mu.Unlock() - return nil -} - // Len returns the number of items in the collection. func (o *ObservedLogs) Len() int { o.mu.RLock() @@ -89,48 +80,25 @@ func (o *ObservedLogs) AllUntimed() []LoggedEntry { return ret } -type observer struct { - zapcore.LevelEnabler - sink func(LoggedEntry) error +func (o *ObservedLogs) add(log LoggedEntry) { + o.mu.Lock() + o.logs = append(o.logs, log) + o.mu.Unlock() } // New creates a new Core that buffers logs in memory (without any encoding). // It's particularly useful in tests. -func New(enab zapcore.LevelEnabler, sink func(LoggedEntry) error, withContext bool) zapcore.Core { - if withContext { - return &contextObserver{ - LevelEnabler: enab, - sink: sink, - } - } - return &observer{ +func New(enab zapcore.LevelEnabler) (zapcore.Core, *ObservedLogs) { + ol := &ObservedLogs{} + return &contextObserver{ LevelEnabler: enab, - sink: sink, - } -} - -func (o *observer) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { - if o.Enabled(ent.Level) { - return ce.AddCore(ent, o) - } - return ce -} - -func (o *observer) With(fields []zapcore.Field) zapcore.Core { - return &observer{LevelEnabler: o.LevelEnabler, sink: o.sink} -} - -func (o *observer) Write(ent zapcore.Entry, fields []zapcore.Field) error { - return o.sink(LoggedEntry{ent, fields}) -} - -func (o *observer) Sync() error { - return nil + logs: ol, + }, ol } type contextObserver struct { zapcore.LevelEnabler - sink func(LoggedEntry) error + logs *ObservedLogs context []zapcore.Field } @@ -144,7 +112,7 @@ func (co *contextObserver) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *z func (co *contextObserver) With(fields []zapcore.Field) zapcore.Core { return &contextObserver{ LevelEnabler: co.LevelEnabler, - sink: co.sink, + logs: co.logs, context: append(co.context[:len(co.context):len(co.context)], fields...), } } @@ -153,7 +121,8 @@ func (co *contextObserver) Write(ent zapcore.Entry, fields []zapcore.Field) erro all := make([]zapcore.Field, 0, len(fields)+len(co.context)) all = append(all, co.context...) all = append(all, fields...) - return co.sink(LoggedEntry{ent, all}) + co.logs.add(LoggedEntry{ent, all}) + return nil } func (co *contextObserver) Sync() error { diff --git a/internal/observer/observer_test.go b/zaptest/observer/observer_test.go similarity index 68% rename from internal/observer/observer_test.go rename to zaptest/observer/observer_test.go index 36ac1275b..cb02d046b 100644 --- a/internal/observer/observer_test.go +++ b/zaptest/observer/observer_test.go @@ -21,7 +21,6 @@ package observer_test import ( - "fmt" "testing" "time" @@ -29,8 +28,8 @@ import ( "github.com/stretchr/testify/require" "go.uber.org/zap" - . "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" + . "go.uber.org/zap/zaptest/observer" ) func assertEmpty(t testing.TB, logs *ObservedLogs) { @@ -39,43 +38,37 @@ func assertEmpty(t testing.TB, logs *ObservedLogs) { } func TestObserver(t *testing.T) { - for _, includeContext := range []bool{false, true} { - t.Run(fmt.Sprint("withContext ", includeContext), func(t *testing.T) { - logs := &ObservedLogs{} - assertEmpty(t, logs) - - obs := zap.New(New(zap.InfoLevel, logs.Add, includeContext)).With(zap.Int("i", 1)) - obs.Info("foo") - obs.Debug("bar") - want := []LoggedEntry{{ - Entry: zapcore.Entry{Level: zap.InfoLevel, Message: "foo"}, - Context: nil, - }} - if includeContext { - want[0].Context = []zapcore.Field{zap.Int("i", 1)} - } - - assert.Equal(t, 1, logs.Len(), "Unexpected observed logs Len.") - assert.Equal(t, want, logs.AllUntimed(), "Unexpected contents from AllUntimed.") - - all := logs.All() - require.Equal(t, 1, len(all), "Unexpected numbed of LoggedEntries returned from All.") - assert.NotEqual(t, time.Time{}, all[0].Time, "Expected non-zero time on LoggedEntry.") - - // copy & zero time for stable assertions - untimed := append([]LoggedEntry{}, all...) - untimed[0].Time = time.Time{} - assert.Equal(t, want, untimed, "Unexpected LoggedEntries from All.") - - assert.Equal(t, all, logs.TakeAll(), "Expected All and TakeAll to return identical results.") - assertEmpty(t, logs) - }) - } + observer, logs := New(zap.InfoLevel) + assertEmpty(t, logs) + + assert.NoError(t, observer.Sync(), "Unexpected failure in no-op Sync") + + obs := zap.New(observer).With(zap.Int("i", 1)) + obs.Info("foo") + obs.Debug("bar") + want := []LoggedEntry{{ + Entry: zapcore.Entry{Level: zap.InfoLevel, Message: "foo"}, + Context: []zapcore.Field{zap.Int("i", 1)}, + }} + + assert.Equal(t, 1, logs.Len(), "Unexpected observed logs Len.") + assert.Equal(t, want, logs.AllUntimed(), "Unexpected contents from AllUntimed.") + + all := logs.All() + require.Equal(t, 1, len(all), "Unexpected numbed of LoggedEntries returned from All.") + assert.NotEqual(t, time.Time{}, all[0].Time, "Expected non-zero time on LoggedEntry.") + + // copy & zero time for stable assertions + untimed := append([]LoggedEntry{}, all...) + untimed[0].Time = time.Time{} + assert.Equal(t, want, untimed, "Unexpected LoggedEntries from All.") + + assert.Equal(t, all, logs.TakeAll(), "Expected All and TakeAll to return identical results.") + assertEmpty(t, logs) } func TestObserverWith(t *testing.T) { - var logs ObservedLogs - sf1 := New(zap.InfoLevel, logs.Add, true) + sf1, logs := New(zap.InfoLevel) // need to pad out enough initial fields so that the underlying slice cap() // gets ahead of its len() so that the sf3/4 With append's could choose