logger_test.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].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].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)), `.+/logger_test.go:[\d]+$`},
		{opts(AddCaller(), AddCallerSkip(1)), `.+/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].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.Caller.Function,
					"Expected to find function name in output.",
				)
			}
			assert.Regexp(
				t,
				tt.sugaredFunction,
				entries[1].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].Message,
			"Failure.",
			"Expected original message to survive failures in runtime.Caller.")
		assert.Equal(
			t,
			logs.AllUntimed()[0].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].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")
			})
		})
	}
}

type customWriteHook struct {
	called bool
}

func (h *customWriteHook) OnWrite(_ *zapcore.CheckedEntry, _ []Field) {
	h.called = true
}

func TestLoggerWithFatalHook(t *testing.T) {
	h := &customWriteHook{}
	withLogger(t, InfoLevel, opts(WithFatalHook(h)), func(logger *Logger, logs *observer.ObservedLogs) {
		recovered := make(chan interface{})
		go func() {
			defer func() {
				recovered <- recover()
			}()
			logger.Fatal("")
		}()
		<-recovered
		assert.True(t, h.called)
	})
}

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...)
}