Encode errors under different keys (#93)

Currently, we don't handle encoding errors in a consistent way
- `AddObject` serializes the error into the log message, but
`AddMarshaler` logs the message to standard out. Even though very few
portions of the code can fail at runtime, we end up checking and
managing errors all over the place.

This PR allows the encoder to return an error for `AddObject` and
`AddMarshaler`, which are the only two methods that can fail. However,
the field handles that error by serializing it under a different key
(errors for the key `foo` are serialized under `fooError`).

This should make our APIs less cumbersome and our error handling more
consistent. It fixes #43.

encoder.go

@@ -29,7 +29,7 @@ import (
 // safe for concurrent use.
 type encoder interface {
 	KeyValue
-	AddFields([]Field) error
+	AddFields([]Field)
 	Clone() encoder
 	Free()
 	WriteMessage(io.Writer, string, string, time.Time) error

field.go

@@ -153,7 +153,9 @@ func Nest(key string, fields ...Field) Field {
 }
 
 // AddTo exports a field through the KeyValue interface.
-func (f Field) AddTo(kv KeyValue) error {
+func (f Field) AddTo(kv KeyValue) {
+	var err error
+
 	switch f.fieldType {
 	case boolType:
 		kv.AddBool(f.key, f.ival == 1)
@@ -168,32 +170,29 @@ func (f Field) AddTo(kv KeyValue) error {
 	case stringerType:
 		kv.AddString(f.key, f.obj.(fmt.Stringer).String())
 	case marshalerType:
-		return kv.AddMarshaler(f.key, f.obj.(LogMarshaler))
+		err = kv.AddMarshaler(f.key, f.obj.(LogMarshaler))
 	case objectType:
-		kv.AddObject(f.key, f.obj)
+		err = kv.AddObject(f.key, f.obj)
 	case skipType:
 		break
 	default:
 		panic(fmt.Sprintf("unknown field type found: %v", f))
 	}
-	return nil
+
+	if err != nil {
+		kv.AddString(fmt.Sprintf("%sError", f.key), err.Error())
+	}
 }
 
 type multiFields []Field
 
 func (fs multiFields) MarshalLog(kv KeyValue) error {
-	return addFields(kv, []Field(fs))
+	addFields(kv, []Field(fs))
+	return nil
 }
 
-func addFields(kv KeyValue, fields []Field) error {
-	var errs multiError
+func addFields(kv KeyValue, fields []Field) {
 	for _, f := range fields {
-		if err := f.AddTo(kv); err != nil {
-			errs = append(errs, err)
-		}
-	}
-	if len(errs) > 0 {
-		return errs
+		f.AddTo(kv)
 	}
-	return nil
 }

field_test.go

@@ -139,8 +139,9 @@ func TestDurationField(t *testing.T) {
 }
 
 func TestMarshalerField(t *testing.T) {
-	// Marshaling the user failed, so we expect an empty object.
-	assertFieldJSON(t, `"foo":{}`, Marshaler("foo", fakeUser{"fail"}))
+	// Marshaling the user failed, so we expect an empty object and an error
+	// message.
+	assertFieldJSON(t, `"foo":{},"fooError":"fail"`, Marshaler("foo", fakeUser{"fail"}))
 
 	assertFieldJSON(t, `"foo":{"name":"phil"}`, Marshaler("foo", fakeUser{"phil"}))
 	assertCanBeReused(t, Marshaler("foo", fakeUser{"phil"}))
@@ -155,8 +156,9 @@ func TestNestField(t *testing.T) {
 	assertFieldJSON(t, `"foo":{"name":"phil","age":42}`,
 		Nest("foo", String("name", "phil"), Int("age", 42)),
 	)
-	// Marshaling the user failed, so we expect an empty object.
-	assertFieldJSON(t, `"foo":{"user":{}}`,
+	// Marshaling the user failed, so we expect an empty object and an error
+	// message.
+	assertFieldJSON(t, `"foo":{"user":{},"userError":"fail"}`,
 		Nest("foo", Marshaler("user", fakeUser{"fail"})),
 	)
 

hook.go

@@ -37,9 +37,8 @@ var _callerSkip = 3
 type hook func(Level, string, KeyValue) (string, error)
 
 // apply implements the Option interface.
-func (h hook) apply(jl *jsonLogger) error {
+func (h hook) apply(jl *jsonLogger) {
 	jl.hooks = append(jl.hooks, h)
-	return nil
 }
 
 // AddCaller configures the Logger to annotate each message with the filename

json_encoder.go

@@ -129,14 +129,14 @@ func (enc *jsonEncoder) AddMarshaler(key string, obj LogMarshaler) error {
 }
 
 // AddObject uses reflection to add an arbitrary object to the logging context.
-func (enc *jsonEncoder) AddObject(key string, obj interface{}) {
+func (enc *jsonEncoder) AddObject(key string, obj interface{}) error {
 	marshaled, err := json.Marshal(obj)
 	if err != nil {
-		enc.AddString(key, err.Error())
-		return
+		return err
 	}
 	enc.addKey(key)
 	enc.bytes = append(enc.bytes, marshaled...)
+	return nil
 }
 
 // Clone copies the current encoder, including any data already encoded.
@@ -147,8 +147,8 @@ func (enc *jsonEncoder) Clone() encoder {
 }
 
 // AddFields applies the passed fields to this encoder.
-func (enc *jsonEncoder) AddFields(fields []Field) error {
-	return addFields(enc, fields)
+func (enc *jsonEncoder) AddFields(fields []Field) {
+	addFields(enc, fields)
 }
 
 // WriteMessage writes a complete log message to the supplied writer, including

json_encoder_test.go

@@ -170,13 +170,10 @@ func TestJSONAddObject(t *testing.T) {
 		assertJSON(t, `"foo":"bar","nested":{"loggable":"yes"}`, enc)
 	})
 
+	// Serialization errors are handled by the field.
 	withJSONEncoder(func(enc *jsonEncoder) {
-		enc.AddObject("nested", noJSON{})
-		assertJSON(
-			t,
-			`"foo":"bar","nested":"json: error calling MarshalJSON for type zap.noJSON: no"`,
-			enc,
-		)
+		require.Error(t, enc.AddObject("nested", noJSON{}), "Unexpected success encoding non-JSON-serializable object.")
+		assertJSON(t, `"foo":"bar"`, enc)
 	})
 }
 

keyvalue.go

@@ -33,6 +33,6 @@ type KeyValue interface {
 	AddMarshaler(key string, marshaler LogMarshaler) error
 	// AddObject uses reflection to serialize arbitrary objects, so it's slow and
 	// allocation-heavy. Consider implementing the LogMarshaler interface instead.
-	AddObject(key string, value interface{})
+	AddObject(key string, value interface{}) error
 	AddString(key, value string)
 }

logger.go

@@ -99,9 +99,7 @@ func NewJSON(options ...Option) Logger {
 	}
 
 	for _, opt := range options {
-		if err := opt.apply(jl); err != nil {
-			jl.internalError(err.Error())
-		}
+		opt.apply(jl)
 	}
 
 	return jl
@@ -125,9 +123,7 @@ func (jl *jsonLogger) With(fields ...Field) Logger {
 		alwaysEpoch: jl.alwaysEpoch,
 		development: jl.development,
 	}
-	if err := clone.enc.AddFields(fields); err != nil {
-		jl.internalError(err.Error())
-	}
+	clone.enc.AddFields(fields)
 	return clone
 }
 
@@ -192,9 +188,7 @@ func (jl *jsonLogger) log(lvl Level, msg string, fields []Field) {
 	}
 
 	temp := jl.enc.Clone()
-	if err := temp.AddFields(fields); err != nil {
-		jl.internalError(err.Error())
-	}
+	temp.AddFields(fields)
 
 	for _, hook := range jl.hooks {
 		newMsg, err := hook(lvl, msg, temp)

logger_test.go

@@ -235,21 +235,6 @@ func TestJSONLoggerNoOpsDisabledLevels(t *testing.T) {
 	})
 }
 
-func TestJSONLoggerInternalErrorHandling(t *testing.T) {
-	buf := newTestBuffer()
-	errBuf := newTestBuffer()
-
-	jl := NewJSON(DebugLevel, Output(buf), ErrorOutput(errBuf), Fields(Marshaler("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.")
-}
-
 func TestJSONLoggerWriteMessageFailure(t *testing.T) {
 	errBuf := &bytes.Buffer{}
 	errSink := &spywrite.WriteSyncer{Writer: errBuf}

options.go

@@ -22,50 +22,46 @@ package zap
 
 // Option is used to set options for the logger.
 type Option interface {
-	apply(*jsonLogger) error
+	apply(*jsonLogger)
 }
 
 // optionFunc wraps a func so it satisfies the Option interface.
-type optionFunc func(*jsonLogger) error
+type optionFunc func(*jsonLogger)
 
-func (f optionFunc) apply(jl *jsonLogger) error {
-	return f(jl)
+func (f optionFunc) apply(jl *jsonLogger) {
+	f(jl)
 }
 
 // This allows any Level to be used as an option.
-func (l Level) apply(jl *jsonLogger) error {
+func (l Level) apply(jl *jsonLogger) {
 	jl.SetLevel(l)
-	return nil
 }
 
 // Fields sets the initial fields for the logger.
 func Fields(fields ...Field) Option {
-	return optionFunc(func(jl *jsonLogger) error {
-		return jl.enc.AddFields(fields)
+	return optionFunc(func(jl *jsonLogger) {
+		jl.enc.AddFields(fields)
 	})
 }
 
 // Output sets the destination for the logger's output.
 func Output(w WriteSyncer) Option {
-	return optionFunc(func(jl *jsonLogger) error {
+	return optionFunc(func(jl *jsonLogger) {
 		jl.w = w
-		return nil
 	})
 }
 
 // ErrorOutput sets the destination for errors generated by the logger.
 func ErrorOutput(w WriteSyncer) Option {
-	return optionFunc(func(jl *jsonLogger) error {
+	return optionFunc(func(jl *jsonLogger) {
 		jl.errW = w
-		return nil
 	})
 }
 
 // Development puts the logger in development mode, which alters the behavior
 // of the DFatal method.
 func Development() Option {
-	return optionFunc(func(jl *jsonLogger) error {
+	return optionFunc(func(jl *jsonLogger) {
 		jl.development = true
-		return nil
 	})
 }

zbark/bark_test.go

@@ -112,11 +112,10 @@ func TestWithField(t *testing.T) {
 		{time.Unix(0, 0), "0"},
 		{time.Nanosecond, "1"},
 		// Interfaces.
-		{loggable("bar"), `{"foo":"bar"}`},                                          // zap.Marshaler
-		{errors.New("foo"), `"foo"`},                                                // error
-		{stringable("foo"), `"foo"`},                                                // fmt.Stringer
-		{user{"fred"}, `{"name":"fred"}`},                                           // json.Marshaler
-		{noJSON{}, `"json: error calling MarshalJSON for type zbark.noJSON: fail"`}, // json.Marshaler
+		{loggable("bar"), `{"foo":"bar"}`}, // zap.Marshaler
+		{errors.New("foo"), `"foo"`},       // error
+		{stringable("foo"), `"foo"`},       // fmt.Stringer
+		{user{"fred"}, `{"name":"fred"}`},  // json.Marshaler
 	}
 
 	for _, tt := range tests {
@@ -131,6 +130,17 @@ func TestWithField(t *testing.T) {
 	}
 }
 
+func TestWithFieldSerializationError(t *testing.T) {
+	b, out := newBark()
+	b.WithField("thing", noJSON{}).Debug("")
+	assert.Contains(
+		t,
+		out.String(),
+		`"fields":{"thingError":"json: error calling MarshalJSON for type zbark.noJSON: fail"}`,
+		"Expected JSON serialization errors to be logged.",
+	)
+}
+
 func TestWithFields(t *testing.T) {
 	b, out := newBark()
 	b.WithFields(bark.Fields{

zwrap/kvmap.go

@@ -38,7 +38,10 @@ func (m KeyValueMap) AddInt(k string, v int) { m[k] = v }
 func (m KeyValueMap) AddInt64(k string, v int64) { m[k] = v }
 
 // AddObject adds the value under the specified key to the map.
-func (m KeyValueMap) AddObject(k string, v interface{}) { m[k] = v }
+func (m KeyValueMap) AddObject(k string, v interface{}) error {
+	m[k] = v
+	return nil
+}
 
 // AddString adds the value under the specified key to the map.
 func (m KeyValueMap) AddString(k string, v string) { m[k] = v }