Replace io.Writer with zap.WriteSyncer (#27)

* Remove global default error writer var

Since we can configure this when we construct loggers, there's no longer
a good reason for this global variable.

* Replace io.Writer with zap.WriteSyncer

We want to flush our output files whenever we log at the panic or fatal
levels, otherwise there's a chance the program will crash before we
actually write our logs. This is particularly important if we use
a buffered output writer.

To accomodate this, replace our use of io.Writer with zap.WriteSyncer.
All *os.Files already satisfy our interface, and this diff adds
a wrapper for other io.Writers.

* Address comments from CR

benchmarks/zap_bench_test.go

@@ -22,7 +22,6 @@ package benchmarks
 
 import (
 	"errors"
-	"io/ioutil"
 	"testing"
 	"time"
 
@@ -51,7 +50,7 @@ var _jane = user{
 }
 
 func BenchmarkZapAddingFields(b *testing.B) {
-	logger := zap.NewJSON(zap.All, zap.Output(ioutil.Discard))
+	logger := zap.NewJSON(zap.All, zap.Output(zap.Discard))
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
@@ -72,7 +71,7 @@ func BenchmarkZapAddingFields(b *testing.B) {
 }
 
 func BenchmarkZapWithAccumulatedContext(b *testing.B) {
-	logger := zap.NewJSON(zap.All, zap.Output(ioutil.Discard), zap.Fields(
+	logger := zap.NewJSON(zap.All, zap.Output(zap.Discard), zap.Fields(
 		zap.Int("int", 1),
 		zap.Int64("int64", 2),
 		zap.Float64("float", 3.0),
@@ -93,7 +92,7 @@ func BenchmarkZapWithAccumulatedContext(b *testing.B) {
 }
 
 func BenchmarkZapWithoutFields(b *testing.B) {
-	logger := zap.NewJSON(zap.All, zap.Output(ioutil.Discard))
+	logger := zap.NewJSON(zap.All, zap.Output(zap.Discard))
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {

hook_test.go

@@ -21,7 +21,6 @@
 package zap
 
 import (
-	"bytes"
 	"regexp"
 	"testing"
 
@@ -30,7 +29,7 @@ import (
 )
 
 func TestHookAddCaller(t *testing.T) {
-	buf := &bytes.Buffer{}
+	buf := newTestBuffer()
 	logger := NewJSON(All, Output(buf), AddCaller())
 	logger.Info("Callers.")
 
@@ -39,8 +38,8 @@ func TestHookAddCaller(t *testing.T) {
 }
 
 func TestHookAddCallerFail(t *testing.T) {
-	buf := &bytes.Buffer{}
-	errBuf := &bytes.Buffer{}
+	buf := newTestBuffer()
+	errBuf := newTestBuffer()
 
 	originalSkip := _callerSkip
 	_callerSkip = 1e3
@@ -53,7 +52,7 @@ func TestHookAddCallerFail(t *testing.T) {
 }
 
 func TestHookAddStacks(t *testing.T) {
-	buf := &bytes.Buffer{}
+	buf := newTestBuffer()
 	logger := NewJSON(All, Output(buf), AddStacks(Info))
 
 	logger.Info("Stacks.")

logger.go

@@ -22,15 +22,11 @@ package zap
 
 import (
 	"fmt"
-	"io"
 	"os"
 	"sync/atomic"
 	"time"
 )
 
-// For stubbing in tests.
-var _defaultErrSink io.Writer = os.Stderr
-
 // A Logger enables leveled, structured logging. All methods are safe for
 // concurrent use.
 type Logger interface {
@@ -63,8 +59,8 @@ type jsonLogger struct {
 	level       *int32 // atomic
 	enc         encoder
 	hooks       []hook
-	errW        io.Writer
-	w           io.Writer
+	errW        WriteSyncer
+	w           WriteSyncer
 	alwaysEpoch bool
 }
 
@@ -81,7 +77,7 @@ func NewJSON(options ...Option) Logger {
 	jl := &jsonLogger{
 		enc:   newJSONEncoder(),
 		level: &defaultLevel,
-		errW:  _defaultErrSink,
+		errW:  os.Stderr,
 		w:     os.Stdout,
 	}
 
@@ -176,10 +172,18 @@ func (jl *jsonLogger) log(lvl Level, msg string, fields []Field) {
 	if jl.alwaysEpoch {
 		now = time.Unix(0, 0)
 	}
-	temp.WriteMessage(jl.w, lvl.String(), msg, now)
+	if err := temp.WriteMessage(jl.w, lvl.String(), msg, now); err != nil {
+		jl.internalError(err.Error())
+	}
 	temp.Free()
+
+	if lvl > Error {
+		// Sync on Panic and Fatal, since they may crash the program.
+		jl.w.Sync()
+	}
 }
 
 func (jl *jsonLogger) internalError(msg string) {
 	fmt.Fprintln(jl.errW, msg)
+	jl.errW.Sync()
 }

logger_bench_test.go

@@ -22,7 +22,6 @@ package zap_test
 
 import (
 	"errors"
-	"io/ioutil"
 	"testing"
 	"time"
 
@@ -49,7 +48,7 @@ var _jane = user{
 }
 
 func withBenchedLogger(b *testing.B, f func(zap.Logger)) {
-	logger := zap.NewJSON(zap.All, zap.Output(ioutil.Discard))
+	logger := zap.NewJSON(zap.All, zap.Output(zap.Discard))
 	b.ResetTimer()
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
@@ -141,7 +140,7 @@ func BenchmarkObjectField(b *testing.B) {
 
 func BenchmarkAddCallerHook(b *testing.B) {
 	logger := zap.NewJSON(
-		zap.Output(ioutil.Discard),
+		zap.Output(zap.Discard),
 		zap.AddCaller(),
 	)
 	b.ResetTimer()
@@ -171,7 +170,7 @@ func Benchmark10Fields(b *testing.B) {
 
 func Benchmark100Fields(b *testing.B) {
 	const batchSize = 50
-	logger := zap.NewJSON(zap.All, zap.Output(ioutil.Discard))
+	logger := zap.NewJSON(zap.All, zap.Output(zap.Discard))
 
 	// Don't include allocating these helper slices in the benchmark. Since
 	// access to them isn't synchronized, we can't run the benchmark in

logger_test.go

@@ -23,20 +23,21 @@ package zap
 import (
 	"bytes"
 	"fmt"
-	"os"
+	"io/ioutil"
 	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/uber-common/zap/spy"
 )
 
 func opts(opts ...Option) []Option {
 	return opts
 }
 
 func withJSONLogger(t testing.TB, opts []Option, f func(*jsonLogger, func() []string)) {
-	sink := &bytes.Buffer{}
-	errSink := &bytes.Buffer{}
+	sink := newTestBuffer()
+	errSink := newTestBuffer()
 
 	allOpts := make([]Option, 0, 3+len(opts))
 	allOpts = append(allOpts, All, Output(sink), ErrorOutput(errSink))
@@ -169,14 +170,11 @@ func TestJSONLoggerNoOpsDisabledLevels(t *testing.T) {
 	})
 }
 
-func TestJSONLoggerInternalErrorHandlingNoSink(t *testing.T) {
-	errBuf := bytes.NewBuffer(nil)
-	_defaultErrSink = errBuf
-	defer func() { _defaultErrSink = os.Stderr }()
+func TestJSONLoggerInternalErrorHandling(t *testing.T) {
+	buf := newTestBuffer()
+	errBuf := newTestBuffer()
 
-	buf := &bytes.Buffer{}
-
-	jl := NewJSON(All, Output(buf), Fields(Object("user", fakeUser{"fail"})))
+	jl := NewJSON(All, Output(buf), ErrorOutput(errBuf), Fields(Object("user", fakeUser{"fail"})))
 	jl.StubTime()
 	output := func() []string { return strings.Split(buf.String(), "\n") }
 
@@ -187,19 +185,15 @@ func TestJSONLoggerInternalErrorHandlingNoSink(t *testing.T) {
 	assert.Equal(t, "fail\n", errBuf.String(), "Expected internal errors to print to stderr.")
 }
 
-func TestJSONLoggerInternalErrorHandlingWithSink(t *testing.T) {
-	buf := &bytes.Buffer{}
+func TestJSONLoggerWriteMessageFailure(t *testing.T) {
 	errBuf := &bytes.Buffer{}
+	errSink := &spy.WriteSyncer{Writer: errBuf}
+	logger := NewJSON(All, Output(AddSync(spy.FailWriter{})), ErrorOutput(errSink))
 
-	jl := NewJSON(All, Output(buf), ErrorOutput(errBuf), Fields(Object("user", fakeUser{"fail"})))
-	jl.StubTime()
-	output := func() []string { return strings.Split(buf.String(), "\n") }
-
-	// Expect partial output, even if there's an error serializing
-	// user-defined types.
-	assertFields(t, jl, output, `{"user":{}}`)
-	// Internal errors go to stderr.
-	assert.Equal(t, "fail\n", errBuf.String(), "Expected internal errors to print to stderr.")
+	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) {
@@ -219,3 +213,14 @@ func TestJSONLoggerRuntimeLevelChange(t *testing.T) {
 		assert.Equal(t, Debug, logger.Level(), "Expected all loggers to switch to Debug level.")
 	}
 }
+
+func TestJSONLoggerSyncsOutput(t *testing.T) {
+	sink := &spy.WriteSyncer{Writer: ioutil.Discard}
+	logger := NewJSON(All, 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.")
+}

options.go

@@ -20,8 +20,6 @@
 
 package zap
 
-import "io"
-
 // Option is used to set options for the logger.
 type Option interface {
 	apply(*jsonLogger) error
@@ -48,15 +46,15 @@ func Fields(fields ...Field) Option {
 }
 
 // Output sets the destination for the logger's output.
-func Output(w io.Writer) Option {
+func Output(w WriteSyncer) Option {
 	return optionFunc(func(jl *jsonLogger) error {
 		jl.w = w
 		return nil
 	})
 }
 
 // ErrorOutput sets the destination for errors generated by the logger.
-func ErrorOutput(w io.Writer) Option {
+func ErrorOutput(w WriteSyncer) Option {
 	return optionFunc(func(jl *jsonLogger) error {
 		jl.errW = w
 		return nil

spy/writer.go

@@ -20,7 +20,10 @@
 
 package spy
 
-import "errors"
+import (
+	"errors"
+	"io"
+)
 
 // FailWriter is an io.Writer that always returns an error.
 type FailWriter struct{}
@@ -38,3 +41,68 @@ type ShortWriter struct{}
 func (w ShortWriter) Write(b []byte) (int, error) {
 	return len(b) - 1, nil
 }
+
+// A Syncer is a spy for the Sync portion of zap.WriteSyncer.
+type Syncer struct {
+	err    error
+	called bool
+}
+
+// SetError sets the error that the Sync method will return.
+func (s *Syncer) SetError(err error) {
+	s.err = err
+}
+
+// Sync records that it was called, then returns the user-supplied error (if
+// any).
+func (s *Syncer) Sync() error {
+	s.called = true
+	return s.err
+}
+
+// Called reports whether the Sync method was called.
+func (s *Syncer) Called() bool {
+	return s.called
+}
+
+// A Flusher is a spy for the Flush portion of zap.WriteFlusher.
+type Flusher struct {
+	err    error
+	called bool
+}
+
+// SetError sets the error that the Flush method will return.
+func (f *Flusher) SetError(err error) {
+	f.err = err
+}
+
+// Flush records that it was called, then returns the user-supplied error (if
+// any).
+func (f *Flusher) Flush() error {
+	f.called = true
+	return f.err
+}
+
+// Called reports whether the Flush method was called.
+func (f *Flusher) Called() bool {
+	return f.called
+}
+
+// WriteSyncer is a concrete type that implements zap.WriteSyncer.
+type WriteSyncer struct {
+	io.Writer
+	Syncer
+}
+
+// WriteFlusher is a concrete type that implements zap.WriteFlusher.
+type WriteFlusher struct {
+	io.Writer
+	Flusher
+}
+
+// A WriteFlushSyncer implements both zap.WriteFlusher and zap.WriteSyncer.
+type WriteFlushSyncer struct {
+	io.Writer
+	Syncer
+	Flusher
+}