Teach zerolog how to return errors, with and without stack traces

[sean-]

When zerolog logs an error message with an Error() finalizer, it returns a error. If the StackTrace() event has been called, the error will be a wrapped error using github.com/pkg/errors and will include the stack trace.

There are a few subtle differences introduced with this change:

1. It is possible to defeat this behavior using the Fields() method.
2. Only one error can be handled by an Event at a time.

Time was spent considering introducing an accumulator for errors that would be evaluated at finalizer-time, but this seemed unnecessary given errors should be wrapped and multiple calls to Err() seemed unlikely in practice.

The behavior of the Msg() finalizer was left in tact in order to avoid any performance penalty in non-error handling conditions. The deferral of error handling can best be observed by looking at the performance hit of an Err() Event with and without StackTrace():

BenchmarkErrorContextFields-8                  	20000000	        84.8 ns/op
BenchmarkErrorContextFields_WithStackTrace-8   	  500000	      2552 ns/op
BenchmarkLogContextFields-8                    	30000000	        47.6 ns/op
PASS
ok  	github.com/rs/zerolog	4.642s

Fixes: #9

[sean-]

@rs If this looks okay, I'll clean up the test for 1.7. The test is brittle for obvious reasons.

[rs]

Thank you for this contribution @sean-, the idea is very interesting.

I'm not comfortable with adding a dependency on github.com/pkg/errors though. I'm all for supporting wrapped errors with this library but I don't want to force a choice on a custom library to users of this lib.

I quickly looked at the exposed API, and we might be able to do that using the Format method. This would prevent us from expanding the stack trace as a JSON structure, but I am not sure it necessarily a good thing to do that anyway ; I am under the impression that storing the whole stack-trace as a string would be more relevant. At the end of the day, stack traces are computed by humans, and humans are better at reading plain stack traces rather than JSON structs. I don't see a use-case where the JSON exploded version would be useful. Perhaps you have some in mind?

Would you agree on trying to remove the dependency by checking for Format and use Format to output a string based stack trace? This would also mean we have to use stdlib for stack traces with non-wrapped errors.

[sean-]

@rs The dependency on pkg/errors fit our needs and ergonomics better than the alternative error handling/wrapping libraries, but I understand the desire to be package neutral. Use of Format() is probably sufficient.

Regarding humans consuming stack traces, I very much disagree with that. Humans reading stack traces is okay on the small scale, but that's exactly it: it doesn't scale well. Structured logging exists so tools can chew on the output. The same is true of exceptions and error management (e.g. ❤️ backtrace.io).

I'm happy to make the change but probably won't use this as a result. I actually want to go the other direction and more tightly couple @davecheney's pkg/errors with rs/zerolog in order to have more explicit control over the stack traces emitted (calling through the Formatter interface to extract information bothered me immensely).

I don't know if it's a fair characterization or not by my sense is that:

• rs/zerolog is interested in high-performance logging
• pkg/errors is interested in extending stdlib's error type to support wrapping

The two should be able to inter-operate tightly but their goals in life are slightly different. My goal is to have tight coupling between two systems because the structured logging of errors is important to us. I see unifying both as a good thing in that it reduces developer repetition and unifies logging and error management into the same post-processing system. This is why I left the Msg() method alone and created the Error() method for the cases where upon return of an error, you also want to log. Bundling zerolog's context and passing some of the collected values back in the Error() finalizer was the next thing I was going to ask about (e.g. EStr()).

If I can get away with not forking/repackaging, I want to do that where possible. :)

[rs]

I would arg that any automation on the stack trace could parse the stack trace format, as I guess the outputted JSON structure is no more standard than a string formatted stack trace. Structured logging is mainly for aggregation. I doubt you could efficiently index stack[0].file and make something useful with it. Most stack trace classifiers (like backtrace I guess) will certainly expect a stack as a []byte.

Instead of coupling the two library you could have an helper taking a pkg/errors and a zerolog.Event and add relevant fields to it. We are missing a way to have nested array of dicts, but I would be happy to add it.

You would have something like:

if ev := log.Error(); ev.Enabled() {
    errutil.StackTrace(ev, err).Msg("some message")
}

Does it make sense?

[sean-]

I hear what you're saying, yes.

To be clear, there isn't really an open standard regarding logging stack traces. Backtrace was just an example highlighting that stack traces aren't exclusively for humans to consume. Emitting something that's human-centric, then re-parsing it into something a machine can process is counter-intuitive given the point of structured logging is to optimize log ingest for computers (not necessarily aggregation, though that's a very common thing to do with logs).

The reason I initially coupled the two was to defer the cost of acquiring the stack trace until the last possible minute (e.g. in the Error() finalizer, not the Msg() finalizer). Introducing an event helper that unwinds the stack of an error message zerolog seems focused on the log emit action vs the retention of the information.

// Is this what you're suggesting?
log.Info().StackTrace(err).Msg("emit a log message with stack trace details, either from err or here at the call site")

// I was hoping to end up with something like:
var annotatedError error = log.Warm().Str("foo","bar").StackTrace(err).Error("emit a log message with stack trace details, either from err or here at the call site")

// or something like `EStr()` which passes along the annotated value to the error object returned from the Error() finalizer
var annotatedError error = log.Warm().EStr("foo","bar").StackTrace(err).Error("emit a log message with stack trace details, either from err or here at the call site")

?

[rs]

I'm not sure to understand. What annotatedError would be used for?

[sean-]

@rs returning an error object to the caller as the return parameter:

func foo() error {
  var annotatedError error = log.Warm().EStr("foo","bar").StackTrace(err).Error("emit a log message with stack trace details, either from err or here at the call site")
  return annotatedError
}

[rs]

Check last few commits. With object/array support you might be able to implement as an extension pretty easily. Check out the LogObjectMarshaler interface.

[sean-]

@rs This looks really good. I left a few small nits in a couple of those commits. I need to think about the accumulator and how this would work at finalizer-time and whether or not the log interface would be able to record the value and capture the desired values and return them up the stack as an error. Let me noodle on this and play around with it over the next few days.

[ghost]

Any updates on this pull request? This is the only missing piece for us to move from Zap to ZeroLog. I will be happy to help out with this PR.

[rs]

I would accept a PR that does add a dependency on pkg/errors or which would limit this dependency to a sub-package.

[sean-]

@rs so I looked through #24 and #25 but don't see how I'd immediately use those, however MarshalZerologObject is basically perfect and something I'd want to emulate. Given the frequency of errors, however, I don't want to use Object() to create a special error type that satisfies the MarshalZerologObject after chewing on a few examples below. To clarify, it sounds like you would accept a PR that:

• adds a dependency on github.com/pkg/errors
• adds an Error() finalizer that returns an error type (vs a string)

so we could unify logging and error handling? Here are the samples I was chewing on:

// #1 Okay.  My least favorite, but it'd work.
log.Warm().EStr("foo","bar").Object("err", errutil.StackTrace(err)).Error("emit a log message with stack trace details, either from err or here at the call site")

// #2 Better
log.Warm().EStr("foo","bar").StackTrace(err).Error("emit a log message with stack trace details, either from err or here at the call site")

// #3 Better
log.Warm().EStr("foo","bar").Stack(err).Error("emit a log message with stack trace details, either from err or here at the call site")

// #4 Best ?  Longer, but now there aren't two ways to set an error in a log message.
log.Warm().EStr("foo","bar").Err(err).Stack().Error("emit a log message with stack trace details, either from err or here at the call site")

// #5 Maybe?
log.Warm().EStr("foo","bar").EStack(err).Error("emit a log message with stack trace details, either from err or here at the call site")

Options 3 and 4 are close, and 5 is a convenience wrapper over 4. I like 4 (and 5) because it's more expressive. Pulling in a new package like option 1 is doable, but feels very clunky, especially given how frequently this would get used.

Do you have any thoughts on the following:

// #3
func (c Context) Stack(err error) Context {
  if s, ok := err.(LogStackMarshaler); ok {
    // ...
  }
}
# 4
func (c Context) Stack() Context { ... }
# 5
func (c Context) EStack(err error) Context { return c.Err(err).Stack() }

Where LogStackMarshaler is defined as:

type LogStackMarshaler interface {
	MarshalZerologStack(e *Event, err error)
}

? I think that'd be close to the interface (dry-coding in this issue). Basically Err() would continue to act as an accumulator and add the error, untouched, to Event as a pointer to an error (because error is an interface), but unexported by Event. MarshalZerologStack() would be pass the error from earlier in the event chain at the time Stack() is called and would type assert and call MarshalZerologStack(), otherwise it would return a "stack": "not supported" since someone did call Stack().

Thoughts?

[rs]

Another solution would be to expose a global zerolog.ErrorMarshaler that would be nil by default and would have the event and error passed whenever Err is called if non nil. In a separate package we could provide the github.com/pkg/errors implementation of that, so you would have to compose it only once for the whole app (i.e. in your main).

[sean-]

Ha! I actually really like that idea. It's clean and puts the control in the developers hands without changing any of the interface semantics.

What about the Error() finalizer so that the return object is an error not a string?

[rs]

@sean- I'm not sure to understand what you mean by "the Error() finalizer so that the return object is an error not a string".

[sean-]

Many (most?) functions return an error as their argument. When there is an error, it's not uncommon to log at the point of return from a function. Suppose the following:

func foo() error {
  if err := doSomething(); err != nil {
    return log.Debug().Err(err).Stack().Error("this emits a log entry with relevant stack details or other contextual information in foo()")
  }
}

I've annotated my error w/ relevant details and already level-guarded the log level. But as I increase the debugging verbosity, I get increasing amounts of detail. The rest of my stack, however, continues to get an error. As a developer, I'm not adding redundant context, once for logging, and once for error handling. Right now you'd do something like:

func foo() error {
  if err := doSomething(); err != nil {
    log.Debug().Err(err).Stack().Error("this emits a log entry with relevant stack details or other contextual information in foo()")
    return errors.Wrap(err, "this emits a log entry with relevant stack details or other contextual information in foo()")
  }
}

which is sub-optimal because idioms with the lowest friction tend to get used the most in daily practice. We have a bunch of context already in a custom error type, but sometimes we want to extend that error object:

https://github.com/joyent/triton-go/blob/master/errors/errors.go#L19-L29

I'm faltering slightly on the zerolog.ErrorMarshaler idea from earlier because stack traces can be expensive to get and I want control over that. Anyway, that's the gist.

[soulne4ny]

@sean- I totally support the point rs/zerolog and pkg/errors have different goals. More than that is I'm using a library that already uses pkg/errors it would be kind to have a way to log other information provided by the pkg/errors or any other error-wrapping library.

However this snippet looks strange for me

    log.Debug().Err(err).Stack().Error("this emits a log entry with relevant stack details or other contextual information in foo()")
    return errors.Wrap(err, "this emits a log entry with relevant stack details or other contextual information in foo()")

Most strange is log level for an error. I assume the point where the error is logged decides about log message level.
.Err(err) adds "error":... field and second .Error("...") is far from being obvious about that it will produce.

[sean-]

@soulne4ny Yeah, that example was contrived. After I submitted this PR I hashed out a better approach and where I'd like to ultimately go.

What I realized was that errors should be annotated with logging information but that logging shouldn't happen more than once for a given error. One handled error == one log entry.

To do this, additional logging information should accumulate in the error and then when it is logged, the details appear at the point where the error is handled and logged. Basically you want to log at the point that an error is handled, not emitted. But at the point that an error is emitted, you want to add information so that when it is logged, you have all of the necessary level-guarded detail, which may include the stack if the debug level is high enough. At the call site, however, you won't know.

import "errlog"

func emitError() error {
  return errlog.InfoMsg("info foo").DebugMsg("error number #123").DebugStr("key", "val").TraceStack()
}

func catchError() {
  if err := emitError(); err != nil {
    log.Err(err).Msg("emitError returned an error")
  }
}

Now when catchErr() is called, it has all of the necessary information to be sufficiently dynamic and useful. In this case the stack is only emitted when we're at TRACE-level (which doesn't exist in zerolog), but DEBUG level gets "key"` and some detailed error message. If you're at info level, you get the message, "info foo".

[rs]

Please see proposal in #35

[DusanKasan]

@rs @sean- I don't think that having direct or indirect dependency on any error library is a great fit here. I would go with any solution that doesn't introduce this coupling, like:

• adding a LogObjectMarshaler type check in all the Err methods and invoking MarshalZerologObject if the error implements it
• adding var ErrorMarshalFunc func(error, Level, Event) variable to zerolog package that user can override (as you've been discussing)

I personally like the first solution, since the Interface method behaves the same already.

Does this make sense?

[rs]

Fixed by #35