2021-12-04 16:42:11 +00:00

610 lines
18 KiB
Go

// Copyright (c) 2016 Uber Technologies, Inc.
//
// Permission is hereby granted, free of charge, to any person obtaining a copy
// of this software and associated documentation files (the "Software"), to deal
// in the Software without restriction, including without limitation the rights
// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
// copies of the Software, and to permit persons to whom the Software is
// furnished to do so, subject to the following conditions:
//
// The above copyright notice and this permission notice shall be included in
// all copies or substantial portions of the Software.
//
// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
// THE SOFTWARE.
package zap
import (
"errors"
"sync"
"testing"
"go.uber.org/zap/internal/exit"
"go.uber.org/zap/internal/ztest"
"go.uber.org/zap/zapcore"
"go.uber.org/zap/zaptest/observer"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.uber.org/atomic"
)
func makeCountingHook() (func(zapcore.Entry) error, *atomic.Int64) {
count := &atomic.Int64{}
h := func(zapcore.Entry) error {
count.Inc()
return nil
}
return h, count
}
func TestLoggerAtomicLevel(t *testing.T) {
// Test that the dynamic level applies to all ancestors and descendants.
dl := NewAtomicLevel()
withLogger(t, dl, nil, func(grandparent *Logger, _ *observer.ObservedLogs) {
parent := grandparent.With(Int("generation", 1))
child := parent.With(Int("generation", 2))
tests := []struct {
setLevel zapcore.Level
testLevel zapcore.Level
enabled bool
}{
{DebugLevel, DebugLevel, true},
{InfoLevel, DebugLevel, false},
{WarnLevel, PanicLevel, true},
}
for _, tt := range tests {
dl.SetLevel(tt.setLevel)
for _, logger := range []*Logger{grandparent, parent, child} {
if tt.enabled {
assert.NotNil(
t,
logger.Check(tt.testLevel, ""),
"Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel,
)
} else {
assert.Nil(
t,
logger.Check(tt.testLevel, ""),
"Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel,
)
}
}
}
})
}
func TestLoggerInitialFields(t *testing.T) {
fieldOpts := opts(Fields(Int("foo", 42), String("bar", "baz")))
withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) {
logger.Info("")
assert.Equal(
t,
observer.LoggedEntry{Context: []Field{Int("foo", 42), String("bar", "baz")}},
logs.AllUntimed()[0],
"Unexpected output with initial fields set.",
)
})
}
func TestLoggerWith(t *testing.T) {
fieldOpts := opts(Fields(Int("foo", 42)))
withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) {
// Child loggers should have copy-on-write semantics, so two children
// shouldn't stomp on each other's fields or affect the parent's fields.
logger.With(String("one", "two")).Info("")
logger.With(String("three", "four")).Info("")
logger.Info("")
assert.Equal(t, []observer.LoggedEntry{
{Context: []Field{Int("foo", 42), String("one", "two")}},
{Context: []Field{Int("foo", 42), String("three", "four")}},
{Context: []Field{Int("foo", 42)}},
}, logs.AllUntimed(), "Unexpected cross-talk between child loggers.")
})
}
func TestLoggerLogPanic(t *testing.T) {
for _, tt := range []struct {
do func(*Logger)
should bool
expected string
}{
{func(logger *Logger) { logger.Check(PanicLevel, "bar").Write() }, true, "bar"},
{func(logger *Logger) { logger.Panic("baz") }, true, "baz"},
} {
withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
if tt.should {
assert.Panics(t, func() { tt.do(logger) }, "Expected panic")
} else {
assert.NotPanics(t, func() { tt.do(logger) }, "Expected no panic")
}
output := logs.AllUntimed()
assert.Equal(t, 1, len(output), "Unexpected number of logs.")
assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.")
assert.Equal(
t,
zapcore.Entry{Message: tt.expected, Level: PanicLevel},
output[0].Entry,
"Unexpected output from panic-level Log.",
)
})
}
}
func TestLoggerLogFatal(t *testing.T) {
for _, tt := range []struct {
do func(*Logger)
expected string
}{
{func(logger *Logger) { logger.Check(FatalLevel, "bar").Write() }, "bar"},
{func(logger *Logger) { logger.Fatal("baz") }, "baz"},
} {
withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
stub := exit.WithStub(func() {
tt.do(logger)
})
assert.True(t, stub.Exited, "Expected Fatal logger call to terminate process.")
output := logs.AllUntimed()
assert.Equal(t, 1, len(output), "Unexpected number of logs.")
assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.")
assert.Equal(
t,
zapcore.Entry{Message: tt.expected, Level: FatalLevel},
output[0].Entry,
"Unexpected output from fatal-level Log.",
)
})
}
}
func TestLoggerLeveledMethods(t *testing.T) {
withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
tests := []struct {
method func(string, ...Field)
expectedLevel zapcore.Level
}{
{logger.Debug, DebugLevel},
{logger.Info, InfoLevel},
{logger.Warn, WarnLevel},
{logger.Error, ErrorLevel},
{logger.DPanic, DPanicLevel},
}
for i, tt := range tests {
tt.method("")
output := logs.AllUntimed()
assert.Equal(t, i+1, len(output), "Unexpected number of logs.")
assert.Equal(t, 0, len(output[i].Context), "Unexpected context on first log.")
assert.Equal(
t,
zapcore.Entry{Level: tt.expectedLevel},
output[i].Entry,
"Unexpected output from %s-level logger method.", tt.expectedLevel)
}
})
}
func TestLoggerAlwaysPanics(t *testing.T) {
// Users can disable writing out panic-level logs, but calls to logger.Panic()
// should still call panic().
withLogger(t, FatalLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
msg := "Even if output is disabled, logger.Panic should always panic."
assert.Panics(t, func() { logger.Panic("foo") }, msg)
assert.Panics(t, func() {
if ce := logger.Check(PanicLevel, "foo"); ce != nil {
ce.Write()
}
}, msg)
assert.Equal(t, 0, logs.Len(), "Panics shouldn't be written out if PanicLevel is disabled.")
})
}
func TestLoggerAlwaysFatals(t *testing.T) {
// Users can disable writing out fatal-level logs, but calls to logger.Fatal()
// should still terminate the process.
withLogger(t, FatalLevel+1, nil, func(logger *Logger, logs *observer.ObservedLogs) {
stub := exit.WithStub(func() { logger.Fatal("") })
assert.True(t, stub.Exited, "Expected calls to logger.Fatal to terminate process.")
stub = exit.WithStub(func() {
if ce := logger.Check(FatalLevel, ""); ce != nil {
ce.Write()
}
})
assert.True(t, stub.Exited, "Expected calls to logger.Check(FatalLevel, ...) to terminate process.")
assert.Equal(t, 0, logs.Len(), "Shouldn't write out logs when fatal-level logging is disabled.")
})
}
func TestLoggerDPanic(t *testing.T) {
withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
assert.NotPanics(t, func() { logger.DPanic("") })
assert.Equal(
t,
[]observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}},
logs.AllUntimed(),
"Unexpected log output from DPanic in production mode.",
)
})
withLogger(t, DebugLevel, opts(Development()), func(logger *Logger, logs *observer.ObservedLogs) {
assert.Panics(t, func() { logger.DPanic("") })
assert.Equal(
t,
[]observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}},
logs.AllUntimed(),
"Unexpected log output from DPanic in development mode.",
)
})
}
func TestLoggerNoOpsDisabledLevels(t *testing.T) {
withLogger(t, WarnLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
logger.Info("silence!")
assert.Equal(
t,
[]observer.LoggedEntry{},
logs.AllUntimed(),
"Expected logging at a disabled level to produce no output.",
)
})
}
func TestLoggerNames(t *testing.T) {
tests := []struct {
names []string
expected string
}{
{nil, ""},
{[]string{""}, ""},
{[]string{"foo"}, "foo"},
{[]string{"foo", ""}, "foo"},
{[]string{"foo", "bar"}, "foo.bar"},
{[]string{"foo.bar", "baz"}, "foo.bar.baz"},
// Garbage in, garbage out.
{[]string{"foo.", "bar"}, "foo..bar"},
{[]string{"foo", ".bar"}, "foo..bar"},
{[]string{"foo.", ".bar"}, "foo...bar"},
}
for _, tt := range tests {
withLogger(t, DebugLevel, nil, func(log *Logger, logs *observer.ObservedLogs) {
for _, n := range tt.names {
log = log.Named(n)
}
log.Info("")
require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.")
assert.Equal(t, tt.expected, logs.AllUntimed()[0].Entry.LoggerName, "Unexpected logger name.")
})
withSugar(t, DebugLevel, nil, func(log *SugaredLogger, logs *observer.ObservedLogs) {
for _, n := range tt.names {
log = log.Named(n)
}
log.Infow("")
require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.")
assert.Equal(t, tt.expected, logs.AllUntimed()[0].Entry.LoggerName, "Unexpected logger name.")
})
}
}
func TestLoggerWriteFailure(t *testing.T) {
errSink := &ztest.Buffer{}
logger := New(
zapcore.NewCore(
zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
zapcore.Lock(zapcore.AddSync(ztest.FailWriter{})),
DebugLevel,
),
ErrorOutput(errSink),
)
logger.Info("foo")
// Should log the error.
assert.Regexp(t, `write error: failed`, errSink.Stripped(), "Expected to log the error to the error output.")
assert.True(t, errSink.Called(), "Expected logging an internal error to call Sync the error sink.")
}
func TestLoggerSync(t *testing.T) {
withLogger(t, DebugLevel, nil, func(logger *Logger, _ *observer.ObservedLogs) {
assert.NoError(t, logger.Sync(), "Expected syncing a test logger to succeed.")
assert.NoError(t, logger.Sugar().Sync(), "Expected syncing a sugared logger to succeed.")
})
}
func TestLoggerSyncFail(t *testing.T) {
noSync := &ztest.Buffer{}
err := errors.New("fail")
noSync.SetError(err)
logger := New(zapcore.NewCore(
zapcore.NewJSONEncoder(zapcore.EncoderConfig{}),
noSync,
DebugLevel,
))
assert.Equal(t, err, logger.Sync(), "Expected Logger.Sync to propagate errors.")
assert.Equal(t, err, logger.Sugar().Sync(), "Expected SugaredLogger.Sync to propagate errors.")
}
func TestLoggerAddCaller(t *testing.T) {
tests := []struct {
options []Option
pat string
}{
{opts(), `^undefined$`},
{opts(WithCaller(false)), `^undefined$`},
{opts(AddCaller()), `.+/logger_test.go:[\d]+$`},
{opts(AddCaller(), WithCaller(false)), `^undefined$`},
{opts(WithCaller(true)), `.+/logger_test.go:[\d]+$`},
{opts(WithCaller(true), WithCaller(false)), `^undefined$`},
{opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), `.+/zap/logger_test.go:[\d]+$`},
{opts(AddCaller(), AddCallerSkip(1)), `.+/zap/common_test.go:[\d]+$`},
{opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(3)), `.+/src/runtime/.*:[\d]+$`},
}
for _, tt := range tests {
withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) {
// Make sure that sugaring and desugaring resets caller skip properly.
logger = logger.Sugar().Desugar()
logger.Info("")
output := logs.AllUntimed()
assert.Equal(t, 1, len(output), "Unexpected number of logs written out.")
assert.Regexp(
t,
tt.pat,
output[0].Entry.Caller,
"Expected to find package name and file name in output.",
)
})
}
}
func TestLoggerAddCallerFunction(t *testing.T) {
tests := []struct {
options []Option
loggerFunction string
sugaredFunction string
}{
{
options: opts(),
loggerFunction: "",
sugaredFunction: "",
},
{
options: opts(WithCaller(false)),
loggerFunction: "",
sugaredFunction: "",
},
{
options: opts(AddCaller()),
loggerFunction: "go.uber.org/zap.infoLog",
sugaredFunction: "go.uber.org/zap.infoLogSugared",
},
{
options: opts(AddCaller(), WithCaller(false)),
loggerFunction: "",
sugaredFunction: "",
},
{
options: opts(WithCaller(true)),
loggerFunction: "go.uber.org/zap.infoLog",
sugaredFunction: "go.uber.org/zap.infoLogSugared",
},
{
options: opts(WithCaller(true), WithCaller(false)),
loggerFunction: "",
sugaredFunction: "",
},
{
options: opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)),
loggerFunction: "go.uber.org/zap.infoLog",
sugaredFunction: "go.uber.org/zap.infoLogSugared",
},
{
options: opts(AddCaller(), AddCallerSkip(2)),
loggerFunction: "go.uber.org/zap.withLogger",
sugaredFunction: "go.uber.org/zap.withLogger",
},
{
options: opts(AddCaller(), AddCallerSkip(2), AddCallerSkip(3)),
loggerFunction: "runtime.goexit",
sugaredFunction: "runtime.goexit",
},
}
for _, tt := range tests {
withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) {
// Make sure that sugaring and desugaring resets caller skip properly.
logger = logger.Sugar().Desugar()
infoLog(logger, "")
infoLogSugared(logger.Sugar(), "")
infoLog(logger.Sugar().Desugar(), "")
entries := logs.AllUntimed()
assert.Equal(t, 3, len(entries), "Unexpected number of logs written out.")
for _, entry := range []observer.LoggedEntry{entries[0], entries[2]} {
assert.Regexp(
t,
tt.loggerFunction,
entry.Entry.Caller.Function,
"Expected to find function name in output.",
)
}
assert.Regexp(
t,
tt.sugaredFunction,
entries[1].Entry.Caller.Function,
"Expected to find function name in output.",
)
})
}
}
func TestLoggerAddCallerFail(t *testing.T) {
errBuf := &ztest.Buffer{}
withLogger(t, DebugLevel, opts(AddCaller(), AddCallerSkip(1e3), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) {
log.Info("Failure.")
assert.Regexp(
t,
`Logger.check error: failed to get caller`,
errBuf.String(),
"Didn't find expected failure message.",
)
assert.Equal(
t,
logs.AllUntimed()[0].Entry.Message,
"Failure.",
"Expected original message to survive failures in runtime.Caller.")
assert.Equal(
t,
logs.AllUntimed()[0].Entry.Caller.Function,
"",
"Expected function name to be empty string.")
})
}
func TestLoggerReplaceCore(t *testing.T) {
replace := WrapCore(func(zapcore.Core) zapcore.Core {
return zapcore.NewNopCore()
})
withLogger(t, DebugLevel, opts(replace), func(logger *Logger, logs *observer.ObservedLogs) {
logger.Debug("")
logger.Info("")
logger.Warn("")
assert.Equal(t, 0, logs.Len(), "Expected no-op core to write no logs.")
})
}
func TestLoggerIncreaseLevel(t *testing.T) {
withLogger(t, DebugLevel, opts(IncreaseLevel(WarnLevel)), func(logger *Logger, logs *observer.ObservedLogs) {
logger.Info("logger.Info")
logger.Warn("logger.Warn")
logger.Error("logger.Error")
require.Equal(t, 2, logs.Len(), "expected only warn + error logs due to IncreaseLevel.")
assert.Equal(
t,
logs.AllUntimed()[0].Entry.Message,
"logger.Warn",
"Expected first logged message to be warn level message",
)
})
}
func TestLoggerHooks(t *testing.T) {
hook, seen := makeCountingHook()
withLogger(t, DebugLevel, opts(Hooks(hook)), func(logger *Logger, logs *observer.ObservedLogs) {
logger.Debug("")
logger.Info("")
})
assert.Equal(t, int64(2), seen.Load(), "Hook saw an unexpected number of logs.")
}
func TestLoggerConcurrent(t *testing.T) {
withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) {
child := logger.With(String("foo", "bar"))
wg := &sync.WaitGroup{}
runConcurrently(5, 10, wg, func() {
logger.Info("", String("foo", "bar"))
})
runConcurrently(5, 10, wg, func() {
child.Info("")
})
wg.Wait()
// Make sure the output doesn't contain interspersed entries.
assert.Equal(t, 100, logs.Len(), "Unexpected number of logs written out.")
for _, obs := range logs.AllUntimed() {
assert.Equal(
t,
observer.LoggedEntry{
Entry: zapcore.Entry{Level: InfoLevel},
Context: []Field{String("foo", "bar")},
},
obs,
"Unexpected log output.",
)
}
})
}
func TestLoggerCustomOnFatal(t *testing.T) {
tests := []struct {
msg string
onFatal zapcore.CheckWriteAction
recoverValue interface{}
}{
{
msg: "panic",
onFatal: zapcore.WriteThenPanic,
recoverValue: "fatal",
},
{
msg: "goexit",
onFatal: zapcore.WriteThenGoexit,
recoverValue: nil,
},
}
for _, tt := range tests {
t.Run(tt.msg, func(t *testing.T) {
withLogger(t, InfoLevel, opts(OnFatal(tt.onFatal)), func(logger *Logger, logs *observer.ObservedLogs) {
var finished bool
recovered := make(chan interface{})
go func() {
defer func() {
recovered <- recover()
}()
logger.Fatal("fatal")
finished = true
}()
assert.Equal(t, tt.recoverValue, <-recovered, "unexpected value from recover()")
assert.False(t, finished, "expect goroutine to not finish after Fatal")
assert.Equal(t, []observer.LoggedEntry{{
Entry: zapcore.Entry{Level: FatalLevel, Message: "fatal"},
Context: []Field{},
}}, logs.AllUntimed(), "unexpected logs")
})
})
}
}
func TestNopLogger(t *testing.T) {
logger := NewNop()
t.Run("basic levels", func(t *testing.T) {
logger.Debug("foo", String("k", "v"))
logger.Info("bar", Int("x", 42))
logger.Warn("baz", Strings("ks", []string{"a", "b"}))
logger.Error("qux", Error(errors.New("great sadness")))
})
t.Run("DPanic", func(t *testing.T) {
logger.With(String("component", "whatever")).DPanic("stuff")
})
t.Run("Panic", func(t *testing.T) {
assert.Panics(t, func() {
logger.Panic("great sadness")
}, "Nop logger should still cause panics.")
})
}
func infoLog(logger *Logger, msg string, fields ...Field) {
logger.Info(msg, fields...)
}
func infoLogSugared(logger *SugaredLogger, args ...interface{}) {
logger.Info(args...)
}