Repository: uber-go/zap
File: logger_test.go (Go)

Code before:
// 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 (
	"bytes"
	"fmt"
	"io/ioutil"
	"os"
	"strings"
	"sync"
	"testing"

	"github.com/uber-go/zap/spywrite"

	"github.com/stretchr/testify/assert"
)

func opts(opts ...Option) []Option {
	return opts
}

type stubbedExit struct {
	Status *int
}

func (se *stubbedExit) Unstub() {
	_exit = os.Exit
}

func (se *stubbedExit) AssertNoExit(t testing.TB) {
	assert.Nil(t, se.Status, "Unexpected exit.")
}

func (se *stubbedExit) AssertStatus(t testing.TB, expected int) {
	if assert.NotNil(t, se.Status, "Expected to exit.") {
		assert.Equal(t, expected, *se.Status, "Unexpected exit code.")
	}
}

func stubExit() *stubbedExit {
	stub := &stubbedExit{}
	_exit = func(s int) { stub.Status = &s }
	return stub
}

func withJSONLogger(t testing.TB, opts []Option, f func(*jsonLogger, func() []string)) {
	sink := newTestBuffer()
	errSink := newTestBuffer()

	allOpts := make([]Option, 0, 3+len(opts))
	allOpts = append(allOpts, DebugLevel, Output(sink), ErrorOutput(errSink))
	allOpts = append(allOpts, opts...)
	jl := NewJSON(allOpts...)
	jl.StubTime()

	f(jl.(*jsonLogger), func() []string {
		output := strings.Split(sink.String(), "\n")
		return output[:len(output)-1]
	})
	assert.Empty(t, errSink.String(), "Expected error sink to be empty")
}

func assertMessage(t testing.TB, level, expectedMsg, actualLog string) {
	expectedLog := fmt.Sprintf(`{"msg":"%s","level":"%s","ts":0,"fields":{}}`, expectedMsg, level)
	assert.Equal(t, expectedLog, actualLog, "Unexpected log output.")
}

func assertFields(t testing.TB, jl Logger, getOutput func() []string, expectedFields ...string) {
	jl.Debug("")
	actualLogs := getOutput()
	for i, fields := range expectedFields {
		expectedLog := fmt.Sprintf(`{"msg":"","level":"debug","ts":0,"fields":%s}`, fields)
		assert.Equal(t, expectedLog, actualLogs[i], "Unexpected log output.")
	}
}

func TestJSONLoggerSetLevel(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, _ func() []string) {
		assert.Equal(t, DebugLevel, jl.Level(), "Unexpected initial level.")
		jl.SetLevel(DebugLevel)
		assert.Equal(t, DebugLevel, jl.Level(), "Unexpected level after SetLevel.")
	})
}

func TestJSONLoggerConcurrentLevelMutation(t *testing.T) {
	// Trigger races for non-atomic level mutations.
	proceed := make(chan struct{})
	jl := NewJSON()

	for i := 0; i < 50; i++ {
		go func(l Logger) {
			<-proceed
			jl.Level()
		}(jl)
		go func(l Logger) {
			<-proceed
			jl.SetLevel(WarnLevel)
		}(jl)
	}
	close(proceed)
}

func TestJSONLoggerInitialFields(t *testing.T) {
	fieldOpts := opts(Fields(Int("foo", 42), String("bar", "baz")))
	withJSONLogger(t, fieldOpts, func(jl *jsonLogger, output func() []string) {
		assertFields(t, jl, output, `{"foo":42,"bar":"baz"}`)
	})
}

func TestJSONLoggerWith(t *testing.T) {
	fieldOpts := opts(Fields(Int("foo", 42)))
	withJSONLogger(t, fieldOpts, func(jl *jsonLogger, output func() []string) {
		// 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.
		jl.With().Debug("")
		jl.With(String("one", "two")).Debug("")
		jl.With(String("three", "four")).Debug("")
		assertFields(t, jl, output,
			`{"foo":42}`,
			`{"foo":42,"one":"two"}`,
			`{"foo":42,"three":"four"}`,
			`{"foo":42}`,
		)
	})
}

func TestJSONLoggerLog(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Log(DebugLevel, "foo")
		assertMessage(t, "debug", "foo", output()[0])
	})

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		assert.Panics(t, func() { jl.Log(PanicLevel, "foo") }, "Expected logging at Panic level to panic.")
		assertMessage(t, "panic", "foo", output()[0])
	})

	stub := stubExit()
	defer stub.Unstub()
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Log(FatalLevel, "foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerDebug(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Debug("foo")
		assertMessage(t, "debug", "foo", output()[0])
	})
}

func TestJSONLoggerInfo(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Info("foo")
		assertMessage(t, "info", "foo", output()[0])
	})
}

func TestJSONLoggerWarn(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Warn("foo")
		assertMessage(t, "warn", "foo", output()[0])
	})
}

func TestJSONLoggerError(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Error("foo")
		assertMessage(t, "error", "foo", output()[0])
	})
}

func TestJSONLoggerPanic(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		assert.Panics(t, func() {
			jl.Panic("foo")
		})
		assertMessage(t, "panic", "foo", output()[0])
	})
}

func TestJSONLoggerFatal(t *testing.T) {
	stub := stubExit()
	defer stub.Unstub()

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Fatal("foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerDFatal(t *testing.T) {
	stub := stubExit()
	defer stub.Unstub()

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.DFatal("foo")
		assertMessage(t, "error", "foo", output()[0])
		stub.AssertNoExit(t)
	})

	withJSONLogger(t, []Option{Development()}, func(jl *jsonLogger, output func() []string) {
		jl.DFatal("foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerNoOpsDisabledLevels(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.SetLevel(WarnLevel)
		jl.Info("silence!")
		assert.Equal(t, []string{}, output(), "Expected logging at a disabled level to produce no output.")
	})
}

func TestJSONLoggerWriteEntryFailure(t *testing.T) {
	errBuf := &bytes.Buffer{}
	errSink := &spywrite.WriteSyncer{Writer: errBuf}
	logger := NewJSON(DebugLevel, Output(AddSync(spywrite.FailWriter{})), ErrorOutput(errSink))

	logger.Info("foo")
	// Should log the error.
	assert.Equal(t, "failed\n", errBuf.String(), "Expected to log the error to the error output.")
	assert.True(t, errSink.Called(), "Expected logging an internal error to Sync error WriteSyncer.")
}

func TestJSONLoggerRuntimeLevelChange(t *testing.T) {
	// Test that changing a logger's level also changes the level of all
	// ancestors and descendants.
	grandparent := NewJSON(Fields(Int("generation", 1)))
	parent := grandparent.With(Int("generation", 2))
	child := parent.With(Int("generation", 3))

	all := []Logger{grandparent, parent, child}
	for _, logger := range all {
		assert.Equal(t, InfoLevel, logger.Level(), "Expected all loggers to start at Info level.")
	}

	parent.SetLevel(DebugLevel)
	for _, logger := range all {
		assert.Equal(t, DebugLevel, logger.Level(), "Expected all loggers to switch to Debug level.")
	}
}

func TestJSONLoggerSyncsOutput(t *testing.T) {
	sink := &spywrite.WriteSyncer{Writer: ioutil.Discard}
	logger := NewJSON(DebugLevel, Output(sink))

	logger.Error("foo")
	assert.False(t, sink.Called(), "Didn't expect logging at error level to Sync underlying WriteCloser.")

	assert.Panics(t, func() { logger.Panic("foo") }, "Expected panic when logging at Panic level.")
	assert.True(t, sink.Called(), "Expected logging at panic level to Sync underlying WriteSyncer.")
}

func TestLoggerConcurrent(t *testing.T) {
	buf := &bytes.Buffer{}
	withJSONLogger(t, []Option{Output(AddSync(buf))}, func(jl *jsonLogger, output func() []string) {
		jl.StubTime()
		jl2 := jl.With(String("foo", "bar"))

		wg := &sync.WaitGroup{}
		runNTimes(5, wg, func() {
			for i := 0; i < 10; i++ {
				jl.Info("info", String("foo", "bar"))
				jl.Info("info", String("foo", "bar"))
			}
		})
		runNTimes(5, wg, func() {
			for i := 0; i < 10; i++ {
				jl2.Info("info")
				jl2.Info("info")
			}
		})

		wg.Wait()

		// Make sure the output doesn't contain interspersed entries.
		expected := `{"msg":"info","level":"info","ts":0,"fields":{"foo":"bar"}}` + "\n"
		assert.Equal(t, strings.Repeat(expected, 200), buf.String())
	})
}

func runNTimes(n int, wg *sync.WaitGroup, f func()) {
	wg.Add(n)
	for i := 0; i < n; i++ {
		go func() {
			defer wg.Done()
			f()
		}()
	}
}


Review comment (refactor):
Is it worth capturing the full pattern you're using? This helper could easily be `runNTimes(n numGoroutines, m iterationsPerGoroutine, wg *sync.WaitGroup, f func())`.


Code after:
// 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 (
	"bytes"
	"fmt"
	"io/ioutil"
	"os"
	"strings"
	"sync"
	"testing"

	"github.com/uber-go/zap/spywrite"

	"github.com/stretchr/testify/assert"
)

func opts(opts ...Option) []Option {
	return opts
}

type stubbedExit struct {
	Status *int
}

func (se *stubbedExit) Unstub() {
	_exit = os.Exit
}

func (se *stubbedExit) AssertNoExit(t testing.TB) {
	assert.Nil(t, se.Status, "Unexpected exit.")
}

func (se *stubbedExit) AssertStatus(t testing.TB, expected int) {
	if assert.NotNil(t, se.Status, "Expected to exit.") {
		assert.Equal(t, expected, *se.Status, "Unexpected exit code.")
	}
}

func stubExit() *stubbedExit {
	stub := &stubbedExit{}
	_exit = func(s int) { stub.Status = &s }
	return stub
}

func withJSONLogger(t testing.TB, opts []Option, f func(*jsonLogger, func() []string)) {
	sink := newTestBuffer()
	errSink := newTestBuffer()

	allOpts := make([]Option, 0, 3+len(opts))
	allOpts = append(allOpts, DebugLevel, Output(sink), ErrorOutput(errSink))
	allOpts = append(allOpts, opts...)
	jl := NewJSON(allOpts...)
	jl.StubTime()

	f(jl.(*jsonLogger), func() []string {
		output := strings.Split(sink.String(), "\n")
		return output[:len(output)-1]
	})
	assert.Empty(t, errSink.String(), "Expected error sink to be empty")
}

func assertMessage(t testing.TB, level, expectedMsg, actualLog string) {
	expectedLog := fmt.Sprintf(`{"msg":"%s","level":"%s","ts":0,"fields":{}}`, expectedMsg, level)
	assert.Equal(t, expectedLog, actualLog, "Unexpected log output.")
}

func assertFields(t testing.TB, jl Logger, getOutput func() []string, expectedFields ...string) {
	jl.Debug("")
	actualLogs := getOutput()
	for i, fields := range expectedFields {
		expectedLog := fmt.Sprintf(`{"msg":"","level":"debug","ts":0,"fields":%s}`, fields)
		assert.Equal(t, expectedLog, actualLogs[i], "Unexpected log output.")
	}
}

func TestJSONLoggerSetLevel(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, _ func() []string) {
		assert.Equal(t, DebugLevel, jl.Level(), "Unexpected initial level.")
		jl.SetLevel(DebugLevel)
		assert.Equal(t, DebugLevel, jl.Level(), "Unexpected level after SetLevel.")
	})
}

func TestJSONLoggerConcurrentLevelMutation(t *testing.T) {
	// Trigger races for non-atomic level mutations.
	proceed := make(chan struct{})
	jl := NewJSON()

	for i := 0; i < 50; i++ {
		go func(l Logger) {
			<-proceed
			jl.Level()
		}(jl)
		go func(l Logger) {
			<-proceed
			jl.SetLevel(WarnLevel)
		}(jl)
	}
	close(proceed)
}

func TestJSONLoggerInitialFields(t *testing.T) {
	fieldOpts := opts(Fields(Int("foo", 42), String("bar", "baz")))
	withJSONLogger(t, fieldOpts, func(jl *jsonLogger, output func() []string) {
		assertFields(t, jl, output, `{"foo":42,"bar":"baz"}`)
	})
}

func TestJSONLoggerWith(t *testing.T) {
	fieldOpts := opts(Fields(Int("foo", 42)))
	withJSONLogger(t, fieldOpts, func(jl *jsonLogger, output func() []string) {
		// 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.
		jl.With().Debug("")
		jl.With(String("one", "two")).Debug("")
		jl.With(String("three", "four")).Debug("")
		assertFields(t, jl, output,
			`{"foo":42}`,
			`{"foo":42,"one":"two"}`,
			`{"foo":42,"three":"four"}`,
			`{"foo":42}`,
		)
	})
}

func TestJSONLoggerLog(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Log(DebugLevel, "foo")
		assertMessage(t, "debug", "foo", output()[0])
	})

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		assert.Panics(t, func() { jl.Log(PanicLevel, "foo") }, "Expected logging at Panic level to panic.")
		assertMessage(t, "panic", "foo", output()[0])
	})

	stub := stubExit()
	defer stub.Unstub()
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Log(FatalLevel, "foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerDebug(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Debug("foo")
		assertMessage(t, "debug", "foo", output()[0])
	})
}

func TestJSONLoggerInfo(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Info("foo")
		assertMessage(t, "info", "foo", output()[0])
	})
}

func TestJSONLoggerWarn(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Warn("foo")
		assertMessage(t, "warn", "foo", output()[0])
	})
}

func TestJSONLoggerError(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Error("foo")
		assertMessage(t, "error", "foo", output()[0])
	})
}

func TestJSONLoggerPanic(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		assert.Panics(t, func() {
			jl.Panic("foo")
		})
		assertMessage(t, "panic", "foo", output()[0])
	})
}

func TestJSONLoggerFatal(t *testing.T) {
	stub := stubExit()
	defer stub.Unstub()

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.Fatal("foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerDFatal(t *testing.T) {
	stub := stubExit()
	defer stub.Unstub()

	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.DFatal("foo")
		assertMessage(t, "error", "foo", output()[0])
		stub.AssertNoExit(t)
	})

	withJSONLogger(t, []Option{Development()}, func(jl *jsonLogger, output func() []string) {
		jl.DFatal("foo")
		assertMessage(t, "fatal", "foo", output()[0])
		stub.AssertStatus(t, 1)
	})
}

func TestJSONLoggerNoOpsDisabledLevels(t *testing.T) {
	withJSONLogger(t, nil, func(jl *jsonLogger, output func() []string) {
		jl.SetLevel(WarnLevel)
		jl.Info("silence!")
		assert.Equal(t, []string{}, output(), "Expected logging at a disabled level to produce no output.")
	})
}

func TestJSONLoggerWriteEntryFailure(t *testing.T) {
	errBuf := &bytes.Buffer{}
	errSink := &spywrite.WriteSyncer{Writer: errBuf}
	logger := NewJSON(DebugLevel, Output(AddSync(spywrite.FailWriter{})), ErrorOutput(errSink))

	logger.Info("foo")
	// Should log the error.
	assert.Equal(t, "failed\n", errBuf.String(), "Expected to log the error to the error output.")
	assert.True(t, errSink.Called(), "Expected logging an internal error to Sync error WriteSyncer.")
}

func TestJSONLoggerRuntimeLevelChange(t *testing.T) {
	// Test that changing a logger's level also changes the level of all
	// ancestors and descendants.
	grandparent := NewJSON(Fields(Int("generation", 1)))
	parent := grandparent.With(Int("generation", 2))
	child := parent.With(Int("generation", 3))

	all := []Logger{grandparent, parent, child}
	for _, logger := range all {
		assert.Equal(t, InfoLevel, logger.Level(), "Expected all loggers to start at Info level.")
	}

	parent.SetLevel(DebugLevel)
	for _, logger := range all {
		assert.Equal(t, DebugLevel, logger.Level(), "Expected all loggers to switch to Debug level.")
	}
}

func TestJSONLoggerSyncsOutput(t *testing.T) {
	sink := &spywrite.WriteSyncer{Writer: ioutil.Discard}
	logger := NewJSON(DebugLevel, Output(sink))

	logger.Error("foo")
	assert.False(t, sink.Called(), "Didn't expect logging at error level to Sync underlying WriteCloser.")

	assert.Panics(t, func() { logger.Panic("foo") }, "Expected panic when logging at Panic level.")
	assert.True(t, sink.Called(), "Expected logging at panic level to Sync underlying WriteSyncer.")
}

func TestLoggerConcurrent(t *testing.T) {
	buf := &bytes.Buffer{}
	withJSONLogger(t, []Option{Output(AddSync(buf))}, func(jl *jsonLogger, output func() []string) {
		jl.StubTime()
		jl2 := jl.With(String("foo", "bar"))

		wg := &sync.WaitGroup{}
		runNTimes(5 /* goroutines */, 10 /* iterations */, wg, func() {
			jl.Info("info", String("foo", "bar"))
		})
		runNTimes(5 /* goroutines */, 10 /* iterations */, wg, func() {
			jl2.Info("info")
		})

		wg.Wait()

		// Make sure the output doesn't contain interspersed entries.
		expected := `{"msg":"info","level":"info","ts":0,"fields":{"foo":"bar"}}` + "\n"
		assert.Equal(t, strings.Repeat(expected, 100), buf.String())
	})
}

func runNTimes(goroutines, iterations int, wg *sync.WaitGroup, f func()) {
	wg.Add(goroutines)
	for g := 0; g < goroutines; g++ {
		go func() {
			defer wg.Done()
			for i := 0; i < iterations; i++ {
				f()
			}
		}()
	}
}