Skip to content
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

Export zap's internal observing logger #372

Merged
merged 2 commits into from
Mar 14, 2017
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
2 changes: 1 addition & 1 deletion Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
7 changes: 3 additions & 4 deletions common_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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)) {
Expand Down
2 changes: 1 addition & 1 deletion global_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
2 changes: 1 addition & 1 deletion logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
8 changes: 4 additions & 4 deletions sugar_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
9 changes: 4 additions & 5 deletions zapcore/hook_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand All @@ -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}

Expand Down
13 changes: 6 additions & 7 deletions zapcore/sampler_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 Thanks for the import reordering.

)

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) {
Expand Down
28 changes: 12 additions & 16 deletions zapcore/tee_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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
Expand All @@ -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)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do we need real loggers here, can we pass NopLoggers or something?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The NopCore is always disabled, so it's not helpful here.

assert.NoError(t, tee.Sync(), "Unexpected error from Syncing a tee.")

sink := &zaptest.Discarder{}
Expand Down
57 changes: 13 additions & 44 deletions internal/observer/observer.go → zaptest/observer/observer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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
}

Expand All @@ -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...),
}
}
Expand All @@ -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 {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -21,16 +21,15 @@
package observer_test

import (
"fmt"
"testing"
"time"

"github.com/stretchr/testify/assert"
"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) {
Expand All @@ -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
Expand Down