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

prashantv · 2023-04-12T04:26:29Z

Callsites that receive an error should either log, or return an error.

However, if the callsite has additioanl context, the simplest option is to add it to the error, but it's then flattened into a string, losing the benefit of structured logging. This often results in callsites logging with additional fields, and returning an error that is likely to be logged again.

WrapError provides a way for callsites to return an error that includes fields to be logged, which will be added to an errorFields key.

prashantv · 2023-04-12T04:34:26Z

fields_error.go

+	return e.err.Error()
+}
+
+func (e errorWithFields) MarshalLogObject(oe zapcore.ObjectEncoder) error {


Using the same interface as ObjectMarshaler makes it easy to integrate in an efficient way. I'm open to using a separate interface, but then adding it as a nested object will require an additional allocation to wrap the custom interface into an ObjectMarshaler

I think it's fine to use implement ObjectMarshaler directly, yeah.

That said, I think it might be nicer to do

func WrappedError(err error, fields ...Field) Field { return zap.Error(&errorWithFields{ err: err, fields: fields, }) }

primarily for ergonomics, because (1) that's what you're going to be doing with it anyway and (2) it probably makes more sense as a Field func rather than as something you pass to a Field func (since the only practical candidate is Error).

(pedantry: I chose WrappedError because none of the other Field func names are/have verbs)

I think we want the return to be an error to match the general usage of this -- the method that is adding fields currently returns an error, and the signature shouldn't change, this just adds some fields to be logged as part of the error log.

I've added an example to show this that should showcase it a little more clearly.

codecov · 2023-04-12T04:34:36Z

Codecov Report

Merging #1271 (baf6027) into master (845ca51) will increase coverage by 0.02%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master    #1271      +/-   ##
==========================================
+ Coverage   98.08%   98.11%   +0.02%     
==========================================
  Files          50       51       +1     
  Lines        3240     3287      +47     
==========================================
+ Hits         3178     3225      +47     
  Misses         53       53              
  Partials        9        9

Impacted Files	Coverage Δ
wrap_error.go	`100.00% <100.00%> (ø)`
zapcore/error.go	`91.35% <100.00%> (+5.94%)`	⬆️

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

alxn · 2023-04-12T04:36:36Z

fields_error.go

@@ -0,0 +1,54 @@
+// Copyright (c) 2023 Uber Technologies, Inc.


nice assignment.

alxn · 2023-04-12T04:38:04Z

is the receiver able to unpack the args?

Related to uber-go/guide#179 Callsites that receive an error should either log, or return an error. However, if the callsite has additioanl context, the simplest option is to add it to the error, but it's then flattened into a string, losing the benefit of structured logging. This often results in callsites logging with additional fields, and returning an error that is likely to be logged again. `WrapError` provides a way for callsites to return an error that includes fields to be logged, which will be added to an `errorFields` key.

prashantv · 2023-04-12T04:58:13Z

is the receiver able to unpack the args?

I didn't have use-cases that required unpacking, but open to it if there's a strong use-case for it.

It's also something that can be added in the future if required, so I'd rather start without.

rabbbit · 2023-04-12T05:44:15Z

However, if the callsite has additioanl context, the simplest option is to add it to the error, but it's then flattened into a string, losing the benefit of structured logging. This often results in callsites logging with additional fields, and returning an error that is likely to be logged again.

These are frequently nested. Irrespective of whether it's supported or not, perhaps it's worth calling out in the documentation and adding a test?

I also wondered if a syntax like:

err := errors.New("file doesn't exist")
...
return zap.WrapError("load config: %w", err, zap.String("fileName": "config.yaml"))

wouldn't be more natural since you can both wrap and extend the error message? I do typically extend the error message in each layer.

prashantv · 2023-04-12T06:48:05Z

These are frequently nested. Irrespective of whether it's supported or not, perhaps it's worth calling out in the documentation and adding a test?

Good call on nesting, I've added nesting support -- supporting multiple zap.WrapError calls, and fmt.Errorf("...: %w", err) wrapping.

I also wondered if a syntax like:
err := errors.New("file doesn't exist")
...
return zap.WrapError("load config: %w", err, zap.String("fileName": "config.yaml"))
wouldn't be more natural since you can both wrap and extend the error message? I do typically extend the error message in each layer.

We end up with 2 varargs (args to the format string, and fields). Having a single varargs where a subset is format args, and others are field hides the expectations from the type system which doesn't seem worth it for saving a few characters.

rabbbit · 2023-04-12T19:22:06Z

fields_error_test.go

+	}, enc.Fields)
+
+	wrap3 := fmt.Errorf("wrap3: %w", wrap2)
+	wrap4 := WrapError(wrap3, Bool("wrap4", true))


what about a test case for when names overlap? It seems worthwhile capturing the behavior explicitly.

you probably considered creating a new namespace for each error, but dismissed it as too slow/complicated?
(and then, naturally, I started thinking if configuring the behavior is worth it, but it increases the verbosity a lot. I guess we can always add WrappErrorNamespaced if people really want it?)

Sure, added a test where names overlap. In the JSON encoder, this will have duplicate keys (same as logger.With, but the map encoder has last-write-wins. What's interesting though is that we add the fields in unwrap order, so the most recently added field is overwritten.

Re: nesting, yeah I don't like the verbosity or performance.

zapcore/error.go

rabbbit · 2023-04-12T19:31:24Z

We end up with 2 varargs (args to the format string, and fields). Having a single varargs where a subset is format args, and others are field hides the expectations from the type system which doesn't seem worth it for saving a few characters.

Oh fair, I imagined we'd only let people do a single string, without the "error vararg".

I guess return zap.WrapError(error.New("load config: %w", err), zap.String("fileName": "config.yaml")) is indeed very close (but potentially slightly slower, right? Guess we don't care about errors)

Two more comments (I apparently cannot comment on non-touched lines in github?). Wanna:

update the docstring on encodeError - it's out of date now
clarify the behavior with errorGroup - perhaps add a test to capture this too?

mway

Nice! LGTM modulo the actual function signature.

fields_error.go

fields_error_test.go

zapcore/error.go

mway · 2023-04-13T14:46:02Z

fields_error.go

+	return e.err.Error()
+}
+
+func (e errorWithFields) MarshalLogObject(oe zapcore.ObjectEncoder) error {


I think it's fine to use implement ObjectMarshaler directly, yeah.

That said, I think it might be nicer to do

func WrappedError(err error, fields ...Field) Field { return zap.Error(&errorWithFields{ err: err, fields: fields, }) }

primarily for ergonomics, because (1) that's what you're going to be doing with it anyway and (2) it probably makes more sense as a Field func rather than as something you pass to a Field func (since the only practical candidate is Error).

(pedantry: I chose WrappedError because none of the other Field func names are/have verbs)

prashantv

Updated, thanks for the reviews!

prashantv · 2023-04-19T06:51:06Z

fields_error_test.go

+	}, enc.Fields)
+
+	wrap3 := fmt.Errorf("wrap3: %w", wrap2)
+	wrap4 := WrapError(wrap3, Bool("wrap4", true))


Sure, added a test where names overlap. In the JSON encoder, this will have duplicate keys (same as logger.With, but the map encoder has last-write-wins. What's interesting though is that we add the fields in unwrap order, so the most recently added field is overwritten.

Re: nesting, yeah I don't like the verbosity or performance.

prashantv · 2023-04-19T06:54:33Z

fields_error.go

+	return e.err.Error()
+}
+
+func (e errorWithFields) MarshalLogObject(oe zapcore.ObjectEncoder) error {


I think we want the return to be an error to match the general usage of this -- the method that is adding fields currently returns an error, and the signature shouldn't change, this just adds some fields to be logged as part of the error log.

I've added an example to show this that should showcase it a little more clearly.

rabbbit

The code works as expected, the fields being silently dropped feel a bit weird though. I'd prefer if @abg or @mway came up with a nice solution for this.

rabbbit · 2023-04-19T08:51:43Z

wrap_error_test.go

+			// fields are added in Unwrap order, and last added field wins in the map encoder
+			// which is the first field added.


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.

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.

alxn · 2023-04-23T03:08:24Z

example_test.go

+
+	// 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"}}


LG:

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

abhinav

Cool. Mostly LGTM with minor comments, however I have one last minute thought about the API:

Under the current design, WrapError will not be able to include additional context to the error object itself. So users will either do the following, and add no context:

return WrapError(err, zap.String("user", user))

Or the following, where they always do a fmt.Errorf:

return WrapError(fmt.Errorf("load: %w", err), zap.String("user", user))

They may also accidentally duplicate information because the fmt.Errorf is already there:

return WrapError(fmt.Errorf("load user %q: %w", user, err), zap.String("user", user))

What do you think about modifying -- or in a future change, adding a variant that takes a positional static msg string?

func WrapError(desc string, err error, fields ...zap.Field) error

return WrapError("load user", err, zap.String("user", user))

// equivalent to fmt.Errorf with just one wrapped error:

return WrapError(fmt.Errorf("load user: %w", err), zap.String("user", user))

I'm happy to defer this to a later change, but I have a feeling that adding context to the error is going to be a more frequent use case than not.

(Apologies for not bringing this up sooner.)

abhinav · 2023-04-23T20:38:42Z

wrap_error.go

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


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

abhinav · 2023-04-25T12:17:58Z

example_test.go

+		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),


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.

abhinav · 2023-04-25T12:26:23Z

wrap_error.go

+// 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{


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.)

abhinav · 2023-04-25T12:27:33Z

wrap_error_test.go

+	assert.True(t, errors.Is(wrap2, rootErr), "errors.Is")
+	assert.True(t, errors.Is(wrap2, wrap1), "errors.Is")


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")

abhinav · 2023-04-25T12:35:49Z

wrap_error.go

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


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

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

mway · 2023-04-25T14:58:21Z

LGTM modulo returning nil if the input error is also nil.

I'm mixed on this change because I think it can:

violate function semantics (does the function that returns an error imply that that error will "log additional fields"?)
violate abstractions (is the user logging this error with knowledge of the logging behavior? how is this error different from other errors the user logs?)
cause surprise ("where did these unexpected fields come from?")

but I can appreciate the value of enabling errors to be annotated without requiring users to define discrete error types IFF all they need to do with error metadata is log it. The above concerns are why I had suggested producing a Field instead of an error, but that would restrict its viability.

My only practical concern right now is if this becomes "a common way to return errors from a function", that it might get expensive. Can you paste benchmark output (unless I missed it somewhere)?

prashantv mentioned this pull request Apr 12, 2023

Handle errors once uber-go/guide#179

Merged

prashantv force-pushed the err-fields branch 2 times, most recently from eb82ae4 to ec5af52 Compare April 12, 2023 04:33

prashantv commented Apr 12, 2023

View reviewed changes

prashantv force-pushed the err-fields branch from ec5af52 to fb24b4c Compare April 12, 2023 04:35

alxn reviewed Apr 12, 2023

View reviewed changes

fields_error.go Outdated

@@ -0,0 +1,54 @@

// Copyright (c) 2023 Uber Technologies, Inc.

Copy link

Member

alxn Apr 12, 2023

Choose a reason for hiding this comment

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

nice assignment.

prashantv force-pushed the err-fields branch from fb24b4c to 809e1a9 Compare April 12, 2023 04:53

prashantv force-pushed the err-fields branch from 809e1a9 to a99527f Compare April 12, 2023 04:55

prashantv force-pushed the err-fields branch 2 times, most recently from 29186ef to 8ce30df Compare April 12, 2023 06:45

rabbbit reviewed Apr 12, 2023

View reviewed changes

zapcore/error.go Outdated Show resolved Hide resolved

mway reviewed Apr 13, 2023

View reviewed changes

prashantv added 5 commits April 19, 2023 06:30

Support nesting of errors

2a88ec3

Rename fields_error to wrap_error to match func name

b71daf6

Add example to show WrapError usage

36183ab

nit: rename + inline + group

1122080

More tests

568f031

prashantv force-pushed the err-fields branch from 8ce30df to 568f031 Compare April 19, 2023 06:49

prashantv commented Apr 19, 2023

View reviewed changes

prashantv added 2 commits April 19, 2023 07:27

Test errorFields marshal failures

26b53cc

Add comment on special handling for single marshaler

c9125d3

prashantv force-pushed the err-fields branch from a81b924 to c9125d3 Compare April 19, 2023 07:28

Document errorFields in encodeError

2f96d3a

rabbbit approved these changes Apr 19, 2023

View reviewed changes

alxn reviewed Apr 23, 2023

View reviewed changes

alxn approved these changes Apr 24, 2023

View reviewed changes

Add benchmark and pool marshalers

baf6027

abhinav reviewed Apr 25, 2023

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

prashantv commented Apr 12, 2023

prashantv Apr 12, 2023

mway Apr 13, 2023

prashantv Apr 19, 2023

codecov bot commented Apr 12, 2023 •

edited

alxn Apr 12, 2023

alxn commented Apr 12, 2023

prashantv commented Apr 12, 2023

rabbbit commented Apr 12, 2023 •

edited

prashantv commented Apr 12, 2023

rabbbit Apr 12, 2023

prashantv Apr 19, 2023

rabbbit commented Apr 12, 2023

mway left a comment

mway Apr 13, 2023

prashantv left a comment

prashantv Apr 19, 2023

prashantv Apr 19, 2023

rabbbit left a comment

rabbbit Apr 19, 2023

prashantv Apr 19, 2023

alxn Apr 23, 2023

abhinav left a comment

abhinav Apr 23, 2023

abhinav Apr 25, 2023

abhinav Apr 25, 2023

abhinav Apr 25, 2023

abhinav Apr 25, 2023

mway Apr 25, 2023

mway commented Apr 25, 2023

		@@ -0,0 +1,54 @@
		// Copyright (c) 2023 Uber Technologies, Inc.

		// fields are added in Unwrap order, and last added field wins in the map encoder
		// which is the first field added.

-// 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{

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

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

Are you sure you want to change the base?

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

Conversation

prashantv commented Apr 12, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Apr 12, 2023 • edited

Codecov Report

Choose a reason for hiding this comment

alxn commented Apr 12, 2023

prashantv commented Apr 12, 2023

rabbbit commented Apr 12, 2023 • edited

prashantv commented Apr 12, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rabbbit commented Apr 12, 2023

mway left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rabbbit left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhinav left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mway commented Apr 25, 2023

codecov bot commented Apr 12, 2023 •

edited

rabbbit commented Apr 12, 2023 •

edited