Improve test coverage

Add tests for a variety of poorly-covered portions of the code. Most of these
sections are actually well-covered, but the tests live in a different package.

internal/exit/exit_test.go

@@ -0,0 +1,42 @@
+// 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 exit
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestStub(t *testing.T) {
+	tests := []struct {
+		f    func()
+		want bool
+	}{
+		{Exit, true},
+		{func() {}, false},
+	}
+
+	for _, tt := range tests {
+		s := WithStub(tt.f)
+		assert.Equal(t, tt.want, s.Exited, "Stub captured unexpected exit value.")
+	}
+}

internal/observer/observer.go

@@ -117,7 +117,7 @@ func (o *observer) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.C
 }
 
 func (o *observer) With(fields []zapcore.Field) zapcore.Core {
-	return &observer{sink: o.sink}
+	return &observer{LevelEnabler: o.LevelEnabler, sink: o.sink}
 }
 
 func (o *observer) Write(ent zapcore.Entry, fields []zapcore.Field) error {

internal/observer/observer_test.go

@@ -0,0 +1,127 @@
+// 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 observer_test
+
+import (
+	"fmt"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+
+	"go.uber.org/zap"
+	. "go.uber.org/zap/internal/observer"
+	"go.uber.org/zap/zapcore"
+)
+
+func assertEmpty(t testing.TB, logs *ObservedLogs) {
+	assert.Equal(t, 0, logs.Len(), "Expected empty ObservedLogs to have zero length.")
+	assert.Equal(t, []LoggedEntry{}, logs.All(), "Unexpected LoggedEntries in empty ObservedLogs.")
+}
+
+func TestObserver(t *testing.T) {
+	for _, includeContext := range []bool{false, true} {
+		t.Run(fmt.Sprint("withContext ", includeContext), func(t *testing.T) {
+			logs := &ObservedLogs{}
+			assertEmpty(t, logs)
+
+			obs := zap.New(New(zap.InfoLevel, logs.Add, includeContext)).With(zap.Int("i", 1))
+			obs.Info("foo")
+			obs.Debug("bar")
+			want := []LoggedEntry{{
+				Entry:   zapcore.Entry{Level: zap.InfoLevel, Message: "foo"},
+				Context: nil,
+			}}
+			if includeContext {
+				want[0].Context = []zapcore.Field{zap.Int("i", 1)}
+			}
+
+			assert.Equal(t, 1, logs.Len(), "Unexpected observed logs Len.")
+			assert.Equal(t, want, logs.AllUntimed(), "Unexpected contents from AllUntimed.")
+
+			all := logs.All()
+			require.Equal(t, 1, len(all), "Unexpected numbed of LoggedEntries returned from All.")
+			assert.NotEqual(t, time.Time{}, all[0].Time, "Expected non-zero time on LoggedEntry.")
+
+			// copy & zero time for stable assertions
+			untimed := append([]LoggedEntry{}, all...)
+			untimed[0].Time = time.Time{}
+			assert.Equal(t, want, untimed, "Unexpected LoggedEntries from All.")
+
+			assert.Equal(t, all, logs.TakeAll(), "Expected All and TakeAll to return identical results.")
+			assertEmpty(t, logs)
+		})
+	}
+}
+
+func TestObserverWith(t *testing.T) {
+	var logs ObservedLogs
+	sf1 := New(zap.InfoLevel, logs.Add, true)
+
+	// need to pad out enough initial fields so that the underlying slice cap()
+	// gets ahead of its len() so that the sf3/4 With append's could choose
+	// not to copy (if the implementation doesn't force them)
+	sf1 = sf1.With([]zapcore.Field{zap.Int("a", 1), zap.Int("b", 2)})
+
+	sf2 := sf1.With([]zapcore.Field{zap.Int("c", 3)})
+	sf3 := sf2.With([]zapcore.Field{zap.Int("d", 4)})
+	sf4 := sf2.With([]zapcore.Field{zap.Int("e", 5)})
+	ent := zapcore.Entry{Level: zap.InfoLevel, Message: "hello"}
+
+	for i, core := range []zapcore.Core{sf2, sf3, sf4} {
+		if ce := core.Check(ent, nil); ce != nil {
+			ce.Write(zap.Int("i", i))
+		}
+	}
+
+	assert.Equal(t, []LoggedEntry{
+		{
+			Entry: ent,
+			Context: []zapcore.Field{
+				zap.Int("a", 1),
+				zap.Int("b", 2),
+				zap.Int("c", 3),
+				zap.Int("i", 0),
+			},
+		},
+		{
+			Entry: ent,
+			Context: []zapcore.Field{
+				zap.Int("a", 1),
+				zap.Int("b", 2),
+				zap.Int("c", 3),
+				zap.Int("d", 4),
+				zap.Int("i", 1),
+			},
+		},
+		{
+			Entry: ent,
+			Context: []zapcore.Field{
+				zap.Int("a", 1),
+				zap.Int("b", 2),
+				zap.Int("c", 3),
+				zap.Int("e", 5),
+				zap.Int("i", 2),
+			},
+		},
+	}, logs.All(), "expected no field sharing between With siblings")
+}

level.go

@@ -92,15 +92,15 @@ func (lvl AtomicLevel) SetLevel(l zapcore.Level) {
 // representation as zapcore.Level ("debug", "info", "warn", "error", "dpanic",
 // "panic", and "fatal").
 func (lvl *AtomicLevel) UnmarshalText(text []byte) error {
+	if lvl.l == nil {
+		lvl.l = &atomic.Int32{}
+	}
+
 	var l zapcore.Level
 	if err := l.UnmarshalText(text); err != nil {
 		return err
 	}
 
-	if lvl.l == nil {
-		lvl.l = atomic.NewInt32(int32(l))
-		return nil
-	}
 	lvl.SetLevel(l)
 	return nil
 }

level_test.go

@@ -87,15 +87,20 @@ func TestDynamicLevelUnmarshalText(t *testing.T) {
 		{"dpanic", DPanicLevel, false},
 		{"panic", PanicLevel, false},
 		{"fatal", FatalLevel, false},
+		{"foobar", InfoLevel, true},
 	}
 
 	for _, tt := range tests {
 		var lvl AtomicLevel
-		if tt.err {
-			assert.Error(t, lvl.UnmarshalText([]byte(tt.text)), "Expected unmarshaling %q to fail.", tt.text)
-		} else {
-			assert.NoError(t, lvl.UnmarshalText([]byte(tt.text)), "Expected unmarshaling %q to succeed.", tt.text)
+		// Test both initial unmarshaling and overwriting existing value.
+		for i := 0; i < 2; i++ {
+			if tt.err {
+				assert.Error(t, lvl.UnmarshalText([]byte(tt.text)), "Expected unmarshaling %q to fail.", tt.text)
+			} else {
+				assert.NoError(t, lvl.UnmarshalText([]byte(tt.text)), "Expected unmarshaling %q to succeed.", tt.text)
+			}
+			assert.Equal(t, tt.expect, lvl.Level(), "Unexpected level after unmarshaling.")
+			lvl.SetLevel(InfoLevel)
 		}
-		assert.Equal(t, tt.expect, lvl.Level(), "Unexpected level after unmarshaling.")
 	}
 }

logger_test.go

@@ -265,7 +265,9 @@ func TestLoggerNames(t *testing.T) {
 		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.
@@ -323,6 +325,8 @@ func TestLoggerAddCaller(t *testing.T) {
 	}
 	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.")

sugar.go

@@ -245,7 +245,7 @@ func (s *SugaredLogger) sweetenFields(args []interface{}) []zapcore.Field {
 		}
 
 		// Consume this value and the next, treating them as a key-value pair. If the
-		// key isn't a string, add it to the slice of invalid pairs.
+		// key isn't a string, add this pair to the slice of invalid pairs.
 		key, val := args[i], args[i+1]
 		if keyStr, ok := key.(string); !ok {
 			// Subsequent errors are likely, so allocate once up front.

sugar_test.go

@@ -24,6 +24,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 
 	"go.uber.org/zap/internal/exit"
 	"go.uber.org/zap/internal/observer"
@@ -138,6 +139,26 @@ func TestSugarWith(t *testing.T) {
 	}
 }
 
+func TestSugarFieldsInvalidPairs(t *testing.T) {
+	withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) {
+		logger.With(42, "foo", []string{"bar"}, "baz").Info("")
+		output := logs.AllUntimed()
+
+		// Double-check that the actual message was logged.
+		require.Equal(t, 2, len(output), "Unexpected number of entries logged.")
+		require.Equal(t, observer.LoggedEntry{Context: []zapcore.Field{}}, output[1], "Unexpected non-error log entry.")
+
+		// Assert that the error message's structured fields serialize properly.
+		require.Equal(t, 1, len(output[0].Context), "Expected one field in error entry context.")
+		enc := zapcore.NewMapObjectEncoder()
+		output[0].Context[0].AddTo(enc)
+		assert.Equal(t, []interface{}{
+			map[string]interface{}{"position": int64(0), "key": int64(42), "value": "foo"},
+			map[string]interface{}{"position": int64(2), "key": []interface{}{"bar"}, "value": "baz"},
+		}, enc.Fields["invalid"], "Unexpected output when logging invalid key-value pairs.")
+	})
+}
+
 type stringerF func() string
 
 func (f stringerF) String() string { return f() }

zapcore/core_test.go

@@ -21,14 +21,16 @@
 package zapcore_test
 
 import (
+	"io/ioutil"
+	"os"
 	"testing"
 	"time"
 
-	"go.uber.org/zap/internal/observer"
 	"go.uber.org/zap/testutils"
 	. "go.uber.org/zap/zapcore"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func makeInt64Field(key string, val int) Field {
@@ -63,57 +65,41 @@ func TestNopCore(t *testing.T) {
 	}
 }
 
-func TestObserverWith(t *testing.T) {
-	var logs observer.ObservedLogs
-	sf1 := observer.New(InfoLevel, logs.Add, true)
+func TestIOCore(t *testing.T) {
+	temp, err := ioutil.TempFile("", "zapcore-test-iocore")
+	require.NoError(t, err, "Failed to create temp file.")
+	defer os.Remove(temp.Name())
 
-	// need to pad out enough initial fields so that the underlying slice cap()
-	// gets ahead of its len() so that the sf3/4 With append's could choose
-	// not to copy (if the implementation doesn't force them)
-	sf1 = sf1.With([]Field{makeInt64Field("a", 1), makeInt64Field("b", 2)})
+	// Drop timestamps for simpler assertions (timestamp encoding is tested
+	// elsewhere).
+	cfg := testEncoderConfig()
+	cfg.TimeKey = ""
 
-	sf2 := sf1.With([]Field{makeInt64Field("c", 3)})
-	sf3 := sf2.With([]Field{makeInt64Field("d", 4)})
-	sf4 := sf2.With([]Field{makeInt64Field("e", 5)})
-	ent := Entry{Level: InfoLevel, Message: "hello"}
+	core := NewCore(
+		NewJSONEncoder(cfg),
+		temp,
+		InfoLevel,
+	).With([]Field{makeInt64Field("k", 1)})
 
-	for i, core := range []Core{sf2, sf3, sf4} {
-		if ce := core.Check(ent, nil); ce != nil {
-			ce.Write(makeInt64Field("i", i))
-		}
+	if ce := core.Check(Entry{Level: DebugLevel, Message: "debug"}, nil); ce != nil {
+		ce.Write(makeInt64Field("k", 2))
+	}
+	if ce := core.Check(Entry{Level: InfoLevel, Message: "info"}, nil); ce != nil {
+		ce.Write(makeInt64Field("k", 3))
+	}
+	if ce := core.Check(Entry{Level: WarnLevel, Message: "warn"}, nil); ce != nil {
+		ce.Write(makeInt64Field("k", 4))
 	}
 
-	assert.Equal(t, []observer.LoggedEntry{
-		{
-			Entry: ent,
-			Context: []Field{
-				makeInt64Field("a", 1),
-				makeInt64Field("b", 2),
-				makeInt64Field("c", 3),
-				makeInt64Field("i", 0),
-			},
-		},
-		{
-			Entry: ent,
-			Context: []Field{
-				makeInt64Field("a", 1),
-				makeInt64Field("b", 2),
-				makeInt64Field("c", 3),
-				makeInt64Field("d", 4),
-				makeInt64Field("i", 1),
-			},
-		},
-		{
-			Entry: ent,
-			Context: []Field{
-				makeInt64Field("a", 1),
-				makeInt64Field("b", 2),
-				makeInt64Field("c", 3),
-				makeInt64Field("e", 5),
-				makeInt64Field("i", 2),
-			},
-		},
-	}, logs.All(), "expected no field sharing between With siblings")
+	logged, err := ioutil.ReadFile(temp.Name())
+	require.NoError(t, err, "Failed to read from temp file.")
+	require.Equal(
+		t,
+		`{"level":"info","msg":"info","k":1,"k":3}`+"\n"+
+			`{"level":"warn","msg":"warn","k":1,"k":4}`+"\n",
+		string(logged),
+		"Unexpected log output.",
+	)
 }
 
 func TestIOCoreSyncsOutput(t *testing.T) {