// 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.", ) } }) }