Clean up hooks and logger config (uber-go#102)

* Add a constructor for no-op fields

Add a constructor so that users can also create no-op fields. I
considered calling this `Nop`, but `zap.Nop()` looks like it should
return a logger instead of a Field.

* Clean up hooks and logger boilerplate

Reduce boilerplate by introducing an Entry struct and pulling common
logger elements into a Config struct (that can be shared between Logger
implementations). Along the way, start logging timestamps as
floating-point seconds since epoch.

* Address CR feedback

* Add tests, clarify comments

encoder.go

@@ -20,17 +20,15 @@
 
 package zap
 
-import (
-	"io"
-	"time"
-)
+import "io"
 
 // encoder is a format-agnostic interface for all log field encoders. It's not
 // safe for concurrent use.
 type encoder interface {
 	KeyValue
+
 	AddFields([]Field)
 	Clone() encoder
 	Free()
-	WriteMessage(io.Writer, string, string, time.Time) error
+	WriteEntry(io.Writer, *Entry) error
 }

entry.go

@@ -0,0 +1,62 @@
+// 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 (
+	"sync"
+	"time"
+)
+
+var (
+	_timeNow   = time.Now // for tests
+	_entryPool = sync.Pool{New: func() interface{} { return &Entry{} }}
+)
+
+// An Entry represents a complete log message. The entry's structured context
+// is already serialized, but the log level, time, and message are available
+// for inspection and modification.
+//
+// Entries are pooled, so any functions that accept them must be careful not to
+// retain references to them.
+type Entry struct {
+	Level   Level
+	Time    time.Time
+	Message string
+	enc     encoder
+}
+
+func newEntry(lvl Level, msg string, enc encoder) *Entry {
+	e := _entryPool.Get().(*Entry)
+	e.Level = lvl
+	e.Message = msg
+	e.Time = _timeNow().UTC()
+	e.enc = enc
+	return e
+}
+
+// Fields returns a mutable reference to the entry's accumulated context.
+func (e *Entry) Fields() KeyValue {
+	return e.enc
+}
+
+func (e *Entry) free() {
+	_entryPool.Put(e)
+}

entry_test.go

@@ -0,0 +1,23 @@
+package zap
+
+import (
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func stubNow(afterEpoch time.Duration) func() {
+	prev := _timeNow
+	t := time.Unix(0, int64(afterEpoch))
+	_timeNow = func() time.Time { return t }
+	return func() { _timeNow = prev }
+}
+
+func TestNewEntry(t *testing.T) {
+	defer stubNow(0)()
+	e := newEntry(DebugLevel, "hello", nil)
+	assert.Equal(t, DebugLevel, e.Level, "Unexpected log level.")
+	assert.Equal(t, time.Unix(0, 0).UTC(), e.Time, "Unexpected time.")
+	assert.Nil(t, e.Fields(), "Unexpected fields.")
+}

field.go

@@ -52,6 +52,11 @@ type Field struct {
 	obj       interface{}
 }
 
+// Skip constructs a no-op Field.
+func Skip() Field {
+	return Field{fieldType: skipType}
+}
+
 // Bool constructs a Field with the given key and value.
 func Bool(key string, val bool) Field {
 	var ival int64
@@ -91,17 +96,17 @@ func Stringer(key string, val fmt.Stringer) Field {
 }
 
 // Time constructs a Field with the given key and value. It represents a
-// time.Time as nanoseconds since epoch.
+// time.Time as a floating-point number of seconds since epoch.
 func Time(key string, val time.Time) Field {
-	return Int64(key, val.UnixNano())
+	return Float64(key, timeToSeconds(val))
 }
 
 // Error constructs a Field that stores err.Error() under the key "error". This is
 // just a convenient shortcut for a common pattern - apart from saving a few
 // keystrokes, it's no different from using zap.String.
 func Error(err error) Field {
 	if err == nil {
-		return Field{fieldType: skipType}
+		return Skip()
 	}
 	return String("error", err.Error())
 }

field_test.go

@@ -81,6 +81,11 @@ func assertCanBeReused(t testing.TB, field Field) {
 	wg.Wait()
 }
 
+func TestSkipField(t *testing.T) {
+	assertFieldJSON(t, ``, Skip())
+	assertCanBeReused(t, Skip())
+}
+
 func TestTrueBoolField(t *testing.T) {
 	assertFieldJSON(t, `"foo":true`, Bool("foo", true))
 	assertCanBeReused(t, Bool("foo", true))
@@ -124,6 +129,7 @@ func TestStringerField(t *testing.T) {
 
 func TestTimeField(t *testing.T) {
 	assertFieldJSON(t, `"foo":0`, Time("foo", time.Unix(0, 0)))
+	assertFieldJSON(t, `"foo":1.5`, Time("foo", time.Unix(1, int64(500*time.Millisecond))))
 	assertCanBeReused(t, Time("foo", time.Unix(0, 0)))
 }
 

hook.go

@@ -27,27 +27,34 @@ import (
 	"strconv"
 )
 
-// Skip Caller, Logger.log, and the leveled Logger method when using
-// runtime.Caller.
-var _callerSkip = 3
+var (
+	errHookNilEntry = errors.New("can't call a hook on a nil *Entry")
+	errCaller       = errors.New("failed to get caller")
+	// Skip Caller, Logger.log, and the leveled Logger method when using
+	// runtime.Caller.
+	_callerSkip = 3
+)
 
-// A hook is executed each time the Logger writes a message. It receives the
-// message's priority, the message itself, and the logging context, and it
-// returns a modified message and an error.
-type hook func(Level, string, KeyValue) (string, error)
+// A hook is executed each time the logger writes an Entry. It can modify the
+// entry, but must not retain references to the entry or any of its
+// contents. Returned errors are written to the logger's error output.
+type hook func(*Entry) error
 
 // apply implements the Option interface.
-func (h hook) apply(jl *jsonLogger) {
-	jl.hooks = append(jl.hooks, h)
+func (h hook) apply(m *Meta) {
+	m.Hooks = append(m.Hooks, h)
 }
 
 // AddCaller configures the Logger to annotate each message with the filename
 // and line number of zap's caller.
 func AddCaller() Option {
-	return hook(func(_ Level, msg string, _ KeyValue) (string, error) {
+	return hook(func(e *Entry) error {
+		if e == nil {
+			return errHookNilEntry
+		}
 		_, filename, line, ok := runtime.Caller(_callerSkip)
 		if !ok {
-			return msg, errors.New("failed to get caller")
+			return errCaller
 		}
 
 		// Re-use a buffer from the pool.
@@ -57,22 +64,26 @@ func AddCaller() Option {
 		buf = append(buf, ':')
 		buf = strconv.AppendInt(buf, int64(line), 10)
 		buf = append(buf, ':', ' ')
-		buf = append(buf, msg...)
+		buf = append(buf, e.Message...)
 
 		newMsg := string(buf)
 		enc.Free()
-		return newMsg, nil
+		e.Message = newMsg
+		return nil
 	})
 }
 
 // AddStacks configures the Logger to record a stack trace for all messages at
 // or above a given level. Keep in mind that this is (relatively speaking) quite
 // expensive.
 func AddStacks(lvl Level) Option {
-	return hook(func(msgLevel Level, msg string, kv KeyValue) (string, error) {
-		if msgLevel >= lvl {
-			Stack().AddTo(kv)
+	return hook(func(e *Entry) error {
+		if e == nil {
+			return errHookNilEntry
+		}
+		if e.Level >= lvl {
+			Stack().AddTo(e.Fields())
 		}
-		return msg, nil
+		return nil
 	})
 }

hook_test.go

@@ -68,3 +68,18 @@ func TestHookAddStacks(t *testing.T) {
 	logger.Debug("No stacks.")
 	assert.NotContains(t, buf.String(), "Unexpected stacktrace at Debug level.")
 }
+
+func TestHooksNilEntry(t *testing.T) {
+	tests := []struct {
+		name string
+		hook hook
+	}{
+		{"AddStacks", AddStacks(InfoLevel).(hook)},
+		{"AddCaller", AddCaller().(hook)},
+	}
+	for _, tt := range tests {
+		assert.NotPanics(t, func() {
+			assert.Equal(t, errHookNilEntry, tt.hook(nil), "Expected an error running hook %s on a nil message.", tt.name)
+		}, "Unexpected panic running hook %s on a nil message.", tt.name)
+	}
+}

json_encoder.go

@@ -22,12 +22,12 @@ package zap
 
 import (
 	"encoding/json"
+	"errors"
 	"fmt"
 	"io"
 	"math"
 	"strconv"
 	"sync"
-	"time"
 	"unicode/utf8"
 )
 
@@ -38,14 +38,19 @@ const (
 	_initialBufSize = 1024
 )
 
-var jsonPool = sync.Pool{
-	New: func() interface{} {
+var (
+	// errNilEntry signals that Encoder.WriteEntry was called with a nil *Entry.
+	errNilEntry = errors.New("can't encode a nil *Entry")
+	// errNilSink signals that Encoder.WriteEntry was called with a nil WriteSyncer.
+	errNilSink = errors.New("can't write encoded message a nil WriteSyncer")
+
+	jsonPool = sync.Pool{New: func() interface{} {
 		return &jsonEncoder{
 			// Pre-allocate a reasonably-sized buffer for each encoder.
 			bytes: make([]byte, 0, _initialBufSize),
 		}
-	},
-}
+	}}
+)
 
 // jsonEncoder is a logging-optimized JSON encoder.
 type jsonEncoder struct {
@@ -151,24 +156,32 @@ func (enc *jsonEncoder) AddFields(fields []Field) {
 	addFields(enc, fields)
 }
 
-// WriteMessage writes a complete log message to the supplied writer, including
+// WriteEntry writes a complete log message to the supplied writer, including
 // the encoder's accumulated fields. It doesn't modify or lock the encoder's
 // underlying byte slice. It's safe to call from multiple goroutines, but it's
-// not safe to call CreateMessage while adding fields.
-func (enc *jsonEncoder) WriteMessage(sink io.Writer, lvl string, msg string, ts time.Time) error {
+// not safe to call WriteEntry while adding fields.
+func (enc *jsonEncoder) WriteEntry(sink io.Writer, e *Entry) error {
+	if sink == nil {
+		return errNilSink
+	}
+	if e == nil {
+		return errNilEntry
+	}
 	// Grab an encoder from the pool so that we can re-use the underlying
 	// buffer.
 	final := newJSONEncoder()
 	defer final.Free()
 
 	final.bytes = append(final.bytes, `{"msg":"`...)
-	final.safeAddString(msg)
+	final.safeAddString(e.Message)
 	final.bytes = append(final.bytes, `","level":"`...)
-	final.bytes = append(final.bytes, lvl...)
+	final.bytes = append(final.bytes, e.Level.String()...)
 	final.bytes = append(final.bytes, `","ts":`...)
-	final.bytes = strconv.AppendInt(final.bytes, ts.UnixNano(), 10)
+	final.bytes = strconv.AppendFloat(final.bytes, timeToSeconds(e.Time), 'f', -1, 64)
 	final.bytes = append(final.bytes, `,"fields":{`...)
-	final.bytes = append(final.bytes, enc.bytes...)
+	if e.enc != nil {
+		final.bytes = append(final.bytes, e.enc.(*jsonEncoder).bytes...)
+	}
 	final.bytes = append(final.bytes, "}}\n"...)
 
 	n, err := sink.Write(final.bytes)

json_encoder_bench_test.go

@@ -53,6 +53,7 @@ func BenchmarkLogMarshalerFunc(b *testing.B) {
 }
 
 func BenchmarkZapJSON(b *testing.B) {
+	e := &Entry{Level: DebugLevel, Message: "fake", Time: time.Unix(0, 0)}
 	b.RunParallel(func(pb *testing.PB) {
 		for pb.Next() {
 			enc := newJSONEncoder()
@@ -65,7 +66,7 @@ func BenchmarkZapJSON(b *testing.B) {
 			enc.AddString("string3", "🤔")
 			enc.AddString("string4", "🙊")
 			enc.AddBool("bool", true)
-			enc.WriteMessage(ioutil.Discard, "debug", "fake", time.Unix(0, 0))
+			enc.WriteEntry(ioutil.Discard, e)
 			enc.Free()
 		}
 	})