zaptest/NewLogger: fail test on internal errors

Zap's errorOutput is used exclusively to log internal errors. If this
ever gets used in a test, something catastrophic happened and we should
fail the test.

This changes the logger returned by zaptest.NewLogger to implement this
behavior by passing a `WriteSyncer` to `zap.ErrorOutput` that marks the
test as failed upon being used.

To test this, we set up a test logger and replace its core with one that
will always fail to write.

zaptest/logger.go

@@ -65,17 +65,39 @@ func NewLogger(t TestingT, opts ...LoggerOption) *zap.Logger {
 		o.applyLoggerOption(&cfg)
 	}
 
+	writer := newTestingWriter(t)
 	return zap.New(
 		zapcore.NewCore(
 			zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
-			testingWriter{t},
+			writer,
 			cfg.Level,
 		),
+
+		// Send zap errors to the same writer and mark the test as failed if
+		// that happens.
+		zap.ErrorOutput(writer.WithMarkFailed(true)),
 	)
 }
 
 // testingWriter is a WriteSyncer that writes to the given testing.TB.
-type testingWriter struct{ t TestingT }
+type testingWriter struct {
+	t TestingT
+
+	// If true, the test will be marked as failed if this testingWriter is
+	// ever used.
+	markFailed bool
+}
+
+func newTestingWriter(t TestingT) testingWriter {
+	return testingWriter{t: t}
+}
+
+// WithMarkFailed returns a copy of this testingWriter with markFailed set to
+// the provided value.
+func (w testingWriter) WithMarkFailed(v bool) testingWriter {
+	w.markFailed = v
+	return w
+}
 
 func (w testingWriter) Write(p []byte) (n int, err error) {
 	n = len(p)
@@ -85,6 +107,10 @@ func (w testingWriter) Write(p []byte) (n int, err error) {
 
 	// Note: t.Log is safe for concurrent use.
 	w.t.Logf("%s", p)
+	if w.markFailed {
+		w.t.Fail()
+	}
+
 	return n, nil
 }
 

zaptest/logger_test.go

@@ -29,12 +29,16 @@ import (
 	"testing"
 
 	"go.uber.org/zap"
+	"go.uber.org/zap/internal/ztest"
+	"go.uber.org/zap/zapcore"
 
 	"github.com/stretchr/testify/assert"
 )
 
 func TestTestLogger(t *testing.T) {
 	ts := newTestLogSpy(t)
+	defer ts.AssertPassed()
+
 	log := NewLogger(ts)
 
 	log.Info("received work order")
@@ -57,6 +61,8 @@ func TestTestLogger(t *testing.T) {
 
 func TestTestLoggerSupportsLevels(t *testing.T) {
 	ts := newTestLogSpy(t)
+	defer ts.AssertPassed()
+
 	log := NewLogger(ts, Level(zap.WarnLevel))
 
 	log.Info("received work order")
@@ -77,25 +83,69 @@ func TestTestLoggerSupportsLevels(t *testing.T) {
 
 func TestTestingWriter(t *testing.T) {
 	ts := newTestLogSpy(t)
-	w := testingWriter{ts}
+	w := newTestingWriter(ts)
 
 	n, err := io.WriteString(w, "hello\n\n")
 	assert.NoError(t, err, "WriteString must not fail")
 	assert.Equal(t, 7, n)
 }
 
+func TestTestLoggerErrorOutput(t *testing.T) {
+	// This test verifies that the test logger logs internal messages to the
+	// testing.T and marks the test as failed.
+
+	ts := newTestLogSpy(t)
+	defer ts.AssertFailed()
+
+	log := NewLogger(ts)
+
+	// Replace with a core that fails.
+	log = log.WithOptions(zap.WrapCore(func(zapcore.Core) zapcore.Core {
+		return zapcore.NewCore(
+			zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
+			zapcore.Lock(zapcore.AddSync(ztest.FailWriter{})),
+			zapcore.DebugLevel,
+		)
+	}))
+
+	log.Info("foo") // this fails
+
+	if assert.Len(t, ts.Messages, 1, "expected a log message") {
+		assert.Regexp(t, `write error: failed`, ts.Messages[0])
+	}
+}
+
 // testLogSpy is a testing.TB that captures logged messages.
 type testLogSpy struct {
 	testing.TB
 
-	mu       sync.Mutex
+	mu       sync.RWMutex
+	failed   bool
 	Messages []string
 }
 
 func newTestLogSpy(t testing.TB) *testLogSpy {
 	return &testLogSpy{TB: t}
 }
 
+func (t *testLogSpy) Fail() {
+	t.mu.Lock()
+	t.failed = true
+	t.mu.Unlock()
+}
+
+func (t *testLogSpy) Failed() bool {
+	t.mu.RLock()
+	failed := t.failed
+	t.mu.RUnlock()
+	return failed
+}
+
+func (t *testLogSpy) FailNow() {
+	t.Fail()
+	t.TB.FailNow()
+}
+
 func (t *testLogSpy) Logf(format string, args ...interface{}) {
 	// Log messages are in the format,
 	//
@@ -106,7 +156,6 @@ func (t *testLogSpy) Logf(format string, args ...interface{}) {
 	m := fmt.Sprintf(format, args...)
 	m = m[strings.IndexByte(m, '\t')+1:]
 
-	// t.Log should be thread-safe.
 	t.mu.Lock()
 	t.Messages = append(t.Messages, m)
 	t.mu.Unlock()
@@ -115,5 +164,17 @@ func (t *testLogSpy) Logf(format string, args ...interface{}) {
 }
 
 func (t *testLogSpy) AssertMessages(msgs ...string) {
-	assert.Equal(t, msgs, t.Messages)
+	assert.Equal(t.TB, msgs, t.Messages, "logged messages did not match")
+}
+
+func (t *testLogSpy) AssertPassed() {
+	t.assertFailed(false, "expected test to pass")
+}
+
+func (t *testLogSpy) AssertFailed() {
+	t.assertFailed(true, "expected test to fail")
+}
+
+func (t *testLogSpy) assertFailed(v bool, msg string) {
+	assert.Equal(t.TB, v, t.failed, msg)
 }