Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WrapError: wrap an error with fields to be logged by zap.Error #1271

Open
wants to merge 10 commits into
base: master
Choose a base branch
from
46 changes: 46 additions & 0 deletions example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,9 +22,12 @@ package zap_test

import (
"encoding/json"
"errors"
"fmt"
"io"
"log"
"os"
"strings"
"time"

"go.uber.org/zap"
Expand Down Expand Up @@ -358,3 +361,46 @@ func ExampleWrapCore_wrap() {
// {"level":"info","msg":"doubled"}
// {"level":"info","msg":"doubled"}
}

type timeouts struct {
readTimeout time.Duration
writeTimeout time.Duration
}

func parseTimeouts(line string) (timeouts, error) {
parts := strings.Split(line, " ")
if len(parts) != 2 {
return timeouts{}, errors.New("line not in expected format")
}

read, err := time.ParseDuration(parts[0])
if err != nil {
return timeouts{}, zap.WrapError(fmt.Errorf("parse readTimeout: %w", err),
zap.String("readTimeout", parts[0]))
}

write, err := time.ParseDuration(parts[1])
if err != nil {
return timeouts{}, zap.WrapError(fmt.Errorf("parse writeTimeout: %w", err),
Comment on lines +378 to +384
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because the example will be used as reference, maybe we should reduce redundancy in the message here. The log message already says we're parsing a timeout, so maybe just the fields will be enough here.

Suggested change
return timeouts{}, zap.WrapError(fmt.Errorf("parse readTimeout: %w", err),
zap.String("readTimeout", parts[0]))
}
write, err := time.ParseDuration(parts[1])
if err != nil {
return timeouts{}, zap.WrapError(fmt.Errorf("parse writeTimeout: %w", err),
return timeouts{}, zap.WrapError(err, zap.String("readTimeout", parts[0]))
}
write, err := time.ParseDuration(parts[1])
if err != nil {
return timeouts{}, zap.WrapError(err,

Theoretically, if there was a caller to this function before the log, it would add the parseTimeouts: prefix, and that would also make it to the log.

zap.String("writeTimeout", parts[1]))
}

return timeouts{read, write}, nil
}

func ExampleWrapError() {
logger := zap.NewExample()
defer logger.Sync()

if _, err := parseTimeouts(""); err != nil {
logger.Error("parse empty", zap.Error(err))
}

if _, err := parseTimeouts("12ms 45"); err != nil {
logger.Error("parse invalid duration", zap.Error(err))
}

// Output:
// {"level":"error","msg":"parse empty","error":"line not in expected format"}
// {"level":"error","msg":"parse invalid duration","error":"parse writeTimeout: time: missing unit in duration \"45\"","errorFields":{"writeTimeout":"45"}}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LG:

{
  "level": "error",
  "msg": "parse invalid duration",
  "error": "parse writeTimeout: time: missing unit in duration \"45\"",
  "errorFields": {
    "writeTimeout": "45"
  }
}

}
8 changes: 8 additions & 0 deletions logger_bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -238,3 +238,11 @@ func Benchmark100Fields(b *testing.B) {
logger.With(first...).Info("Child loggers with lots of context.", second...)
}
}

func BenchmarkWrapError(b *testing.B) {
err := errors.New("err")
err = WrapError(err, String("errKey", "errVal"))
withBenchedLogger(b, func(log *Logger) {
log.Error("error", Error(err))
})
}
54 changes: 54 additions & 0 deletions wrap_error.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,54 @@
// Copyright (c) 2023 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 (
"go.uber.org/zap/zapcore"
)

type errorWithFields struct {
err error
fields []Field
}

// WrapError returns an error that will log the provided fields if the error
// is logged using `Error`.
func WrapError(err error, fields ...Field) error {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

optional: do we want to return nil if error is nil?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I think we should return nil in that case.

return &errorWithFields{
Comment on lines +32 to +35
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// WrapError returns an error that will log the provided fields if the error
// is logged using `Error`.
func WrapError(err error, fields ...Field) error {
return &errorWithFields{
// WrapError returns an error that, when logged with [Error] or [NamedError],
// will add the specified fields to the log entry.
//
// For example, given:
//
// func NewUser(uid string) (*User, error) {
// if !isValid(uid) {
// return nil, zap.WrapError(ErrInvalidUserID, zap.String("uid", uid))
// }
// // ...
// }
//
// The following will log the error message, as well as the 'uid' field.
//
// u, err := NewUser(uid)
// if err != nil {
// log.Warn("Unable to create user", zap.Error(err))
// }
func WrapError(err error, fields ...Field) error {
return &errorWithFields{

(I wanted to clarify that 'Error' refers to the field constructor, not the Logger.Error method and given that it's a new thing, more details on what it does and how to use it.)

err: err,
fields: fields,
}
}

func (e errorWithFields) Unwrap() error {
return e.err
}

func (e errorWithFields) Error() string {
return e.err.Error()
Comment on lines +41 to +46
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any reason to implement these receivers on the value instead of pointer, given that WrapError returns a pointer?

}

func (e errorWithFields) MarshalLogObject(enc zapcore.ObjectEncoder) error {
for _, f := range e.fields {
f.AddTo(enc)
}
return nil
}
98 changes: 98 additions & 0 deletions wrap_error_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
// Copyright (c) 2023 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 (
"errors"
"fmt"
"testing"

"github.com/stretchr/testify/assert"
"go.uber.org/zap/zapcore"
)

func TestWrapError(t *testing.T) {
var (
rootErr = errors.New("root err")
wrap1 = fmt.Errorf("wrap1: %w", rootErr)
wrap2 = WrapError(wrap1,
String("user", "foo"),
Int("count", 12),
)
)
assert.True(t, errors.Is(wrap2, rootErr), "errors.Is")
assert.True(t, errors.Is(wrap2, wrap1), "errors.Is")
Comment on lines +41 to +42
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

optional: assert.ErrorIs

Suggested change
assert.True(t, errors.Is(wrap2, rootErr), "errors.Is")
assert.True(t, errors.Is(wrap2, wrap1), "errors.Is")
assert.ErrorIs(t, wrap2, rootErr, "errors.Is")
assert.ErrorIs(t, wrap2, wrap1, "errors.Is")


enc := zapcore.NewMapObjectEncoder()
Error(wrap2).AddTo(enc)
assert.Equal(t, map[string]any{
"error": "wrap1: root err",
"errorFields": map[string]any{
"user": "foo",
"count": int64(12),
},
}, enc.Fields)

var (
wrap3 = fmt.Errorf("wrap3: %w", wrap2)
wrap4 = WrapError(wrap3, Bool("wrap4", true))
)
Error(wrap4).AddTo(enc)
assert.Equal(t, map[string]any{
"error": "wrap3: wrap1: root err",
"errorFields": map[string]any{
"user": "foo",
"count": int64(12),
"wrap4": true,
},
}, enc.Fields)

var (
wrap5 = fmt.Errorf("wrap5 no wrap: %v", wrap3)
wrap6 = WrapError(wrap5, Bool("wrap5", true))
)
Error(wrap6).AddTo(enc)
assert.Equal(t, map[string]any{
"error": "wrap5 no wrap: wrap3: wrap1: root err",
"errorFields": map[string]any{
"wrap5": true,
},
}, enc.Fields)
}

func TestWrapErrorDuplicateField(t *testing.T) {
var (
rootErr = errors.New("root err")
wrap1 = WrapError(rootErr, String("f1", "a"), String("f2", "b"))
wrap2 = WrapError(wrap1, String("f1", "c"))
)
enc := zapcore.NewMapObjectEncoder()
Error(wrap2).AddTo(enc)
assert.Equal(t, map[string]any{
"error": "root err",
"errorFields": map[string]any{
// fields are added in Unwrap order, and last added field wins in the map encoder
// which is the first field added.
Comment on lines +92 to +93
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just to do the sanity-check once again - are we sure this is okay? it feels weird.

one possibly crazy idea - I guess we cannot detect a conflict somehow make it visible? Hm.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The map encoder overwrites, the JSON encoder adds the duplicate fields. This is the behaviour of logger.With as well, see #622

This is one of the tradeoffs for performance, though there's some ideas in the issue for how we could detect this, which should apply to all cases of duplicated fields.

"f1": "a",
"f2": "b",
},
}, enc.Fields)
}
61 changes: 61 additions & 0 deletions zapcore/error.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,9 +21,11 @@
package zapcore

import (
"errors"
"fmt"
"reflect"

"go.uber.org/multierr"
"go.uber.org/zap/internal/pool"
)

Expand All @@ -33,6 +35,11 @@ import (
// If the error implements fmt.Formatter, a field with the name ${key}Verbose
// is also added with the full verbose error message.
//
// If the error implements `zapcore.ObjectMarshaler`, a field with the name
// ${key}Fields is added with the marshaled object. If the error can be unwrapped
// using `errors.Unwrap`, then unwrapped errors implementing `zapcore.Marshaler`
// are also marshaled to the same ${key}Fields.
//
// Finally, if the error implements errorGroup (from go.uber.org/multierr) or
// causer (from github.com/pkg/errors), a ${key}Causes field is added with an
// array of objects containing the errors this error was comprised of.
Expand Down Expand Up @@ -75,9 +82,63 @@ func encodeError(key string, err error, enc ObjectEncoder) (retErr error) {
enc.AddString(key+"Verbose", verbose)
}
}

// Only addMarshalers if we find an error implementing ObjectMarshaler.
for e := err; e != nil; e = errors.Unwrap(e) {
if _, ok := e.(ObjectMarshaler); ok {
if err := addMarshalers(enc, key, e); err != nil {
return err
}
break
}
}

return nil
}

// addMarshalers unwraps the error and marshals any ObjectMarshalers in the error chain.
func addMarshalers(enc ObjectEncoder, key string, err error) error {
marshalers := getMarshalers()
defer putMarshalers(marshalers)

for e := err; e != nil; e = errors.Unwrap(e) {
if errObj, ok := e.(ObjectMarshaler); ok {
*marshalers = append(*marshalers, errObj)
}
}

if err := enc.AddObject(key+"Fields", marshalers); err != nil {
return err
}

return nil
}

var _marshalersPool = pool.New(func() *mergedMarshalers {
mm := make(mergedMarshalers, 0, 3)
return &mm
})

func getMarshalers() *mergedMarshalers {
mm := _marshalersPool.Get()
*mm = (*mm)[:0]
return mm
}

func putMarshalers(mm *mergedMarshalers) {
_marshalersPool.Put(mm)
}

type mergedMarshalers []ObjectMarshaler

func (ms *mergedMarshalers) MarshalLogObject(enc ObjectEncoder) error {
var errs error
for _, m := range *ms {
errs = multierr.Append(errs, m.MarshalLogObject(enc))
}
return errs
}

type errorGroup interface {
// Provides read-only access to the underlying list of errors, preferably
// without causing any allocs.
Expand Down