Further error-logging improvements (#333)

* Support rich errors in Any and Errors

* Remove stray newline

* Add a test for arrays of rich errors

array.go

@@ -21,11 +21,16 @@
 package zap
 
 import (
+	"sync"
 	"time"
 
 	"go.uber.org/zap/zapcore"
 )
 
+var _errArrayElemPool = sync.Pool{New: func() interface{} {
+	return &errArrayElem{}
+}}
+
 // Array constructs a field with the given key and ArrayMarshaler. It provides
 // a flexible, but still type-safe and efficient, way to add array-like types
 // to the logging context. The struct's MarshalLogArray method is called lazily.
@@ -311,7 +316,25 @@ func (errs errArray) MarshalLogArray(arr zapcore.ArrayEncoder) error {
 		if errs[i] == nil {
 			continue
 		}
-		arr.AppendString(errs[i].Error())
+		// To represent each error as an object with an "error" attribute and
+		// potentially an "errorVerbose" attribute, we need to wrap it in a
+		// type that implements LogObjectMarshaler. To prevent this from
+		// allocating, pool the wrapper type.
+		elem := _errArrayElemPool.Get().(*errArrayElem)
+		elem.error = errs[i]
+		arr.AppendObject(elem)
+		elem.error = nil
+		_errArrayElemPool.Put(elem)
 	}
 	return nil
 }
+
+type errArrayElem struct {
+	error
+}
+
+func (e *errArrayElem) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	// Re-use the error field's logic, which supports non-standard error types.
+	Error(e.error).AddTo(enc)
+	return nil
+}

array_test.go

@@ -25,8 +25,11 @@ import (
 	"testing"
 	"time"
 
-	"github.com/stretchr/testify/assert"
 	"go.uber.org/zap/zapcore"
+
+	richErrors "github.com/pkg/errors"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func BenchmarkBoolsArrayMarshaler(b *testing.B) {
@@ -94,7 +97,11 @@ func TestArrayWrappers(t *testing.T) {
 		{"uint16s", Uint16s("", []uint16{1, 2}), []interface{}{uint16(1), uint16(2)}},
 		{"uint8s", Uint8s("", []uint8{1, 2}), []interface{}{uint8(1), uint8(2)}},
 		{"uintptrs", Uintptrs("", []uintptr{1, 2}), []interface{}{uintptr(1), uintptr(2)}},
-		{"errors", Errors("", []error{nil, errors.New("foo"), nil, errors.New("bar")}), []interface{}{"foo", "bar"}},
+		{
+			"errors",
+			Errors("", []error{nil, errors.New("foo"), nil, errors.New("bar")}),
+			[]interface{}{map[string]interface{}{"error": "foo"}, map[string]interface{}{"error": "bar"}},
+		},
 	}
 
 	for _, tt := range tests {
@@ -105,3 +112,23 @@ func TestArrayWrappers(t *testing.T) {
 		assert.Equal(t, 1, len(enc.Fields), "%s: found extra keys in map: %v", tt.desc, enc.Fields)
 	}
 }
+
+func TestErrorsArraysHandleRichErrors(t *testing.T) {
+	errs := []error{richErrors.New("egad")}
+
+	enc := zapcore.NewMapObjectEncoder()
+	Errors("k", errs).AddTo(enc)
+	assert.Equal(t, 1, len(enc.Fields), "Expected only top-level field.")
+
+	val := enc.Fields["k"]
+	arr, ok := val.([]interface{})
+	require.True(t, ok, "Expected top-level field to be an array.")
+	require.Equal(t, 1, len(arr), "Expected only one error object in array.")
+
+	serialized := arr[0]
+	errMap, ok := serialized.(map[string]interface{})
+	require.True(t, ok, "Expected serialized error to be a map, got %T.", serialized)
+	assert.Equal(t, "egad", errMap["error"], "Unexpected standard error string.")
+	assert.Contains(t, errMap["errorVerbose"], "egad", "Verbose error string should be a superset of standard error.")
+	assert.Contains(t, errMap["errorVerbose"], "TestErrorsArraysHandleRichErrors", "Verbose error string should contain a stacktrace.")
+}

field.go

@@ -171,19 +171,23 @@ func Time(key string, val time.Time) zapcore.Field {
 	return zapcore.Field{Key: key, Type: zapcore.TimeType, Integer: val.UnixNano()}
 }
 
-// Error constructs a field that lazily stores err.Error() under the key
-// "error". If passed a nil error, the field is a no-op. This is purely a
-// convenience for a common error-logging idiom; use String("someFieldName",
-// err.Error()) to customize the key.
-//
-// Errors which also implement fmt.Formatter (like those produced by
-// github.com/pkg/errors) will also have their verbose representation stored
-// under "errorVerbose".
+// Error is shorthand for the common idiom NamedError("error", err).
 func Error(err error) zapcore.Field {
+	return NamedError("error", err)
+}
+
+// NamedError constructs a field that lazily stores err.Error() under the
+// provided key. Errors which also implement fmt.Formatter (like those produced
+// by github.com/pkg/errors) will also have their verbose representation stored
+// under key+"Verbose". If passed a nil error, the field is a no-op.
+//
+// For the common case in which the key is simply "error", the Error function
+// is shorter and less repetitive.
+func NamedError(key string, err error) zapcore.Field {
 	if err == nil {
 		return Skip()
 	}
-	return zapcore.Field{Key: "error", Type: zapcore.ErrorType, Interface: err}
+	return zapcore.Field{Key: key, Type: zapcore.ErrorType, Interface: err}
 }
 
 // Stack constructs a field that stores a stacktrace of the current goroutine
@@ -303,7 +307,7 @@ func Any(key string, value interface{}) zapcore.Field {
 	case []time.Duration:
 		return Durations(key, val)
 	case error:
-		return String(key, val.Error())
+		return NamedError(key, val)
 	case []error:
 		return Errors(key, val)
 	case fmt.Stringer:

field_test.go

@@ -100,12 +100,14 @@ func TestFieldConstructors(t *testing.T) {
 		{"Reflect", zapcore.Field{Key: "k", Type: zapcore.ReflectType, Interface: ints}, Reflect("k", ints)},
 		{"Error", Skip(), Error(nil)},
 		{"Error", zapcore.Field{Key: "error", Type: zapcore.ErrorType, Interface: fail}, Error(fail)},
+		{"NamedError", Skip(), NamedError("foo", nil)},
+		{"NamedError", zapcore.Field{Key: "foo", Type: zapcore.ErrorType, Interface: fail}, NamedError("foo", fail)},
 		{"Stringer", zapcore.Field{Key: "k", Type: zapcore.StringerType, Interface: addr}, Stringer("k", addr)},
 		{"Object", zapcore.Field{Key: "k", Type: zapcore.ObjectMarshalerType, Interface: name}, Object("k", name)},
 		{"Any:ObjectMarshaler", Any("k", name), Object("k", name)},
 		{"Any:ArrayMarshaler", Any("k", bools([]bool{true})), Array("k", bools([]bool{true}))},
 		{"Any:Stringer", Any("k", addr), Stringer("k", addr)},
-		{"Any:Error", Any("k", errors.New("v")), String("k", "v")},
+		{"Any:Error", Any("k", errors.New("v")), NamedError("k", errors.New("v"))},
 		{"Any:Errors", Any("k", []error{errors.New("v")}), Errors("k", []error{errors.New("v")})},
 		{"Any:Bool", Any("k", true), Bool("k", true)},
 		{"Any:Bools", Any("k", []bool{true}), Bools("k", []bool{true})},

logger_bench_test.go

@@ -125,6 +125,18 @@ func BenchmarkErrorField(b *testing.B) {
 	})
 }
 
+func BenchmarkErrorsField(b *testing.B) {
+	errs := []error{
+		errors.New("egad"),
+		errors.New("oh no"),
+		errors.New("dear me"),
+		errors.New("such fail"),
+	}
+	withBenchedLogger(b, func(log *Logger) {
+		log.Info("Errors.", Errors("errors", errs))
+	})
+}
+
 func BenchmarkStackField(b *testing.B) {
 	withBenchedLogger(b, func(log *Logger) {
 		log.Info("Error.", Stack("stacktrace"))