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

Add support for stack trace extration of error fields #35

Merged
merged 5 commits into from
Jan 3, 2019
Merged

Conversation

rs
Copy link
Owner

@rs rs commented Feb 8, 2018

Proposal for #11.

@sean-: what do you think about this implementation?

I'm not super happy of the API. I'm not sure having Stack and Err separated is great design. What would you think about a new set of error-with-stack methods that would package the error message and the stack together.

For instance:

log.Log().ErrStack("error", err).Msg("")

would generate:

{"error": {"message": "error message", "stack": [{...}, {...}]}}

@soulne4ny
Copy link

.ErrStack() looks good for me. Definitely adding stack on every error is not a thing that everyone requires.

In the example for have a field name parameter like .ErrStack(name, error), however in the code there is no name parameter.
Here could be two ways for adding stack

  • error as an object, like in the code "error":{"message":"...", "stack":[...]"}.
  • or as two separate fields "error":"...", "stack":[...].

The first one makes sense if one wants to add more attributes to an error. While second one allows to keep log processing more simple and prevents from questions what should be inside the "error":{} object — "m" vs "message" for error text, etc...

@soulne4ny
Copy link

soulne4ny commented Feb 12, 2018

I see a way to configure root logger with an ErrorMarshaller implementation that could be like follows

type ErrorMarshaller func (buf []byte, err error, stack bool) []byte

or

type ErrorMarshaller func (e *Event, err error, stack bool) *Event

or

type ErrorMarshaller interface {
   func (e *Event) Err(err error) *Event
   func (e *Event) ErrStack(err error) *Event  
}

This would it make possible for a user to decide does he/she needs "error":{"message":"...", "stack":[...]"} or "error":"...", "stack":[...]". As well would provide a way to support third-party error wrapping libraries like pkg/errors without adding any dependency. And pkgerrors/stacktrace.go 3786fbf#diff-b36532f7d1ee3bc3766fb82447076e69
would be a good standard implementation for the zerolog's log stack trace object. :)

@soulne4ny
Copy link

@rs, please, take a look at a commit soulne4ny@863bbc6
There is a variant of ErrorMarshaler from the comment above.
However, a support for log.Context().Stack().Err() needed, as well as better handling for log.Info().AnErr("an_error", err) and log.Info().Errors(manyerrors...).

@rs
Copy link
Owner Author

rs commented Feb 16, 2018

@soulne4ny: one downside I see with your approach is that we have to pay for the cost of the interface, even for the default (current) mode with no stack support.

@soulne4ny
Copy link

Yes, it is the cost. It could be wrapped with if logger.defaultErr {} else { /*custom via interface*/ }.

However, this is only event.Err(). I suppose when there are a lot of log.Error().Err() calls it implies hard times, and the interface indirection for logging is just a minor detail.

On the other hand, this is not just support for error stacks, but for custom wrapped-error types. This requires either tight coupling with the library, or an interface, or a code generation.

Passing an error formatter as an interface or a function pointer, implies a cost for every event.Err() call. While it is a global setting, it introduces one and the very same indirection all though a compiled binary. So for every one who is not OK with default error formatting, will pay the cost.

Is there any other way to remove the indirection besides code generation?
Is the cost really that high comparing to handling errors itself?

@soulne4ny
Copy link

@rs Would you consider true the hypothesis that error messages should be rather infrequent during regular runs? It yes, then does the cost of indirection matter?

StackTrace() errors.StackTrace
}
var st errors.StackTrace
if err, ok := err.(stackTracer); ok {

Choose a reason for hiding this comment

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

You can remove this else by inverting the validation logic.

err, ok := err.(stackTracer)
if !ok {
    return nil
}
return appendJSONStack(make([]byte, 0, 500), err.StackTrace())

Just a different point of view on this block 😃

@rs
Copy link
Owner Author

rs commented Feb 19, 2018

We often use Err in access logs for instance, with err as nil most of the time. It is so skipped by the condition on nil which happen after the added code.

@soulne4ny
Copy link

soulne4ny commented Feb 24, 2018

Solving just stack reporting case, the following notation could be used

log.Error().Err(err).Stack(err).Msg("")

Then event.Stack(err) would be indirect call wrapped with if err != nil {...}. It looks affordable, doesn't it?

@rs
Copy link
Owner Author

rs commented Feb 24, 2018

Sounds reasonable.

@FarhadF
Copy link

FarhadF commented May 27, 2018

Any news on this? really looking forward to stacktraces

@rs
Copy link
Owner Author

rs commented May 29, 2018

@soulne4ny would you consider rebasing your work and implement the last discussed changes?

rs pushed a commit that referenced this pull request Jul 2, 2018
As per #9 and to offer a different approach from  #11 and #35 this PR introduces custom error serialization with sane defaults without breaking the existing APIs.

This is just a first draft and is missing tests. Also, a bit of code duplication which I feel could be reduced but it serves to get the idea across.

It provides global error marshalling by exposing a `var ErrorMarshalFunc func(error) interface{}` in zerolog package that by default is  a function that returns the passed argument. It should be overriden if you require custom error marshalling.

Then in every function that accept error or array of errors `ErrorMarshalFunc` is called on the error and then the result of it is processed like this:
- if it implements `LogObjectMarshaler`, serialize it as an object
- if it is a string serialize as a string
- if it is an error, serialize as a string with the result of `Error()`
- else serialize it as an interface

The side effect of this change is that the encoders don't need the `AppendError/s` methods anymore, as the errors are serialized directly to other types.
@mvrhov
Copy link

mvrhov commented Jul 24, 2018

@soulne4ny ping

@rs rs force-pushed the master branch 4 times, most recently from 1cea9c5 to 8479412 Compare September 17, 2018 17:28
@istomisgood
Copy link

Looking forward to this feature. Press the merge button already!

@krak3n
Copy link

krak3n commented Jan 2, 2019

Any chance we can get this merged? The rebase looks fairly easy, I had a go in a closed PR but ran into CI issues.

context.go Outdated
e.Stack()
}

var sh = callerHook{}
Copy link
Owner Author

Choose a reason for hiding this comment

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

Shouldn't this be var sh = stackTraceHook{}?

@rs
Copy link
Owner Author

rs commented Jan 2, 2019

@krak3n: I just tried to rebase, and it's not trivial. The pkgerrors package needs to access the encoder which is now "dynamic" and not easily accessible from outside the zerolog package. The MarshalStack should work on a zerolog.Event instead of trying to handle its own encoding IMHO.

@rs
Copy link
Owner Author

rs commented Jan 2, 2019

Here is a rebase with a change of API for the stack marshaler that work with the new encoding system. Please have a look before I merge.

Copy link

@sean- sean- left a comment

Choose a reason for hiding this comment

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

LGTM, thank you for chasing this to the end and incorporating this request.

out = append(out, map[string]string{
StackSourceFileName: fmt.Sprintf("%s", frame),
StackSourceLineName: fmt.Sprintf("%d", frame),
StackSourceFunctionName: fmt.Sprintf("%n", frame),
Copy link

Choose a reason for hiding this comment

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

Can we change this to be something like:

StackSourceFileName:     frame.String(),
StackSourceLineName:     strconv.FormatInt(frame, 10),

I'm not sure what the %n verb is for StackSourceFunctionName(), but finding something that isn't fmt.Sprintf() would be preferred if there's interest in reducing the overhead of this call.

Copy link
Owner Author

Choose a reason for hiding this comment

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

I think pkg/errors is using the fmt.Formatter interface to expose the different info. I'm not a big fan of this type of magic API, but that's the way it is.

Copy link
Owner Author

Choose a reason for hiding this comment

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

Check the last commit, I removed some allocs by calling the Format method directly. It's not a huge win though:

name        old time/op    new time/op    delta
LogStack-8    11.0µs ± 3%     8.9µs ± 1%  -18.97%  (p=0.008 n=5+5)

name        old alloc/op   new alloc/op   delta
LogStack-8    4.16kB ± 0%    4.24kB ± 0%   +2.12%  (p=0.008 n=5+5)

name        old allocs/op  new allocs/op  delta
LogStack-8      89.0 ± 0%      86.0 ± 0%   -3.37%  (p=0.008 n=5+5)

Copy link

Choose a reason for hiding this comment

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

:shipit:

@krak3n
Copy link

krak3n commented Jan 3, 2019

thanks guys, looking forward to this getting merged 😄

@rs rs merged commit aa55558 into master Jan 3, 2019
@mvrhov
Copy link

mvrhov commented Jan 4, 2019

🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

8 participants