123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452 |
- // 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 TestLoggerAddCallerFail(t *testing.T) {
- errBuf := &ztest.Buffer{}
- withLogger(t, DebugLevel, opts(AddCaller(), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) {
- log.callerSkip = 1e3
- 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.")
- })
- }
- 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.",
- )
- }
- })
- }
|