Logging std::error::Errors

[theduke]

It would be really nice to have a specialized way of logging errors that implement std::error::Error.

This would allow automatically capturing detailed information about an error, including the Display and Debug representations, and especially backtraces via the new Error::backtrace, which has an open PR.

The main purpose is to give the backend implementation the option to extract all desired information about an error and use it as appropriate for the output.

Not sure how this could fit into the current design, but I'd imagine an additional method on Log and a macro.

trait Log {
  ...
  // The record serves the purpose of providing the location, and optionally an additional error message / metadata.
  // Question: Should the record be optional or required?
  fn error(&self, error: &dyn std::error::Error,  record: Option<&Record>);
}

Plus a macro.

Naming for that macro would of course be somewhat awkward, considering error! exists. Maybe with_error!(). Also there could be a variant of error! that allows specifying an error value.

One could of course ask if this is really necessary, since you could already write a custom macro or method that captures the required information as a Record. But I'd like to see a standardized way of doing this that gives the logger implementation the power to do what it wants, without forcing the user to make a decision here up-front.

[KodrAus]

Personally, I think treating errors as first-class concepts in logs is a worthwhile thing to do. It looks like we might not have given this too much thought in the past, but now that the std::error::Error type is more useful and backtrace support is in the works it could be a good time to consider it.

We could add something like a fn source(&self) -> Option<&(dyn Error + 'static)> method to Record along with macro support similar to how target was added:

error!(source: err, "Something didn't work {}", err);

Alternatively we could design support into the key-values API and leave it up to convention to capture an error with a common key name. That would probably be my preferred approach, because it would avoid creating too many parallel syntaxes in the log! macros.

[theduke]

I like the source: err syntax. Together with adding Record::source() this would also enable attaching an error to all the macros, and prevent clutter.

The ability to log an error without providing an additional message would also be nice though.

[sfackler]

Yep, I definitely agree that it makes sense to allow Errors to be tacked onto log records - it will be a field that's only available with the std feature, but that should be fine.

[theduke]

I thought a missing Send bound on the Error could be a problem for async loggers that ship the record to a different thread. But then I noticed that Record already is not Send.

How is that dealt with in, eg, slog? (cc @dpc)

[dpc]

I've explicitly mentioned that Send and Sync is something to consider for the future, but I don't think anyone followed up on that. In slog there are these explicitly built contexts that are Arced so they can be sent cheaply. The idea is that they are more permanent, so they take an upfront cost during creation to be cheaper during normal operations. The immediate key-values and stuff in Records are borrowed, but slog requires them to be Send and just clones/copies/kind-of-serializes them. The idea here is that they are more ad-hoc and should be generally smaller, so cost of the clone is OK.

I think it is worthwhile to investigate and built an async logger for log to iron out the async story. If Record had an explicit field for errors, then it could require them to be sync and avoid copying. Similiarily if log had more general way to group borrowed ad-hoc vs owned and Arced more persistent data, then some optimizations around these would be possible.

For reference: https://github.com/slog-rs/async/blob/e33823ceb8e7af9e0874262e1e57845bd5f30249/lib.rs#L448

[yoshuawuyts]

Alternatively we could design support into the key-values API and leave it up to convention to capture an error with a common key name.

This seems reasonable approach that could be done without additional support from the log crate (pending #353). I've been exploring some other conventions in log-types, and this seems like it would work as part of that.

[KodrAus]

We're on board with adding specific support for std::error::Error to log. There's a PR open at #378 with some initial support that allows you to attach an error to a Record.

For Send, since log already makes no direct concessions to allowing Records to be passed across thread boundaries it isn't going to be required here. You can, however, downcast a std::error::Error, so if your application needed to capture a sendable structured representation of the record then you could downcast it to the kind of error you expect to see at that point.

There is some space to explore about macro support though. I think all log levels should support accepting an error, because not every error you encounter is necessarily an error-worthy log. You might want to log them as warnings or debug if they're non-critical. We could follow the same approach as target, by allowing another kind of optional special field before the format arguments:

if let Err(e) = fallible() {
    debug!(error: e, "it didn't work, but that's ok");
    debug!(target: "something", error: e, "it didn't work, but that's ok");

    error!(error: e, "it didn't work");
    error!(target: "something", error: e, "it didn't work");

    // Could use `err` instead of `error`
    error!(err: e, "it didn't work");

    // Would we also want this to work?
    error!(err: e);
}

[rimutaka]

We are looking at adding error logging inside AWS Lambda Runtime for Rust (awslabs/aws-lambda-rust-runtime#241). The plan was to use Display trait, but that means the user would have to implement it, potentially more than once. Having a standard way of logging std::error::Error would make it easier for our users.

Looks like the work on this issue stalled.
Is there something I can help with to get it released?

[softprops]

Could some of this now be handled with log's builtin structured logging interfaces?

[KodrAus]

Hey @rimutaka 👋

The blocker for log’s stable API is macro support. To fit in with the existing syntax it would probably look something like:

error!(source: e, “Oh no!”);

we could cobble that in with some liberal duplication to the macros, but would be better off converting log! to a tt muncher that could handle any combination of target, source and level. In the past we’ve found changing the macros to be tricky, but the scope of this should be reasonably small.

There’s nothing blocking support in the unstable structured API, like @softprops mentioned. We could add Value::from_error and Value::as_error methods at any time.

[softprops]

The latter seems to keep the surface area small.

error!("whoops", { error: e }) you get the reuse the same syntax for the same semantic purpose, annotating a log message with additional information. You get to pick the name for that information, log serializes it

[KodrAus]

@softprops That would be much nicer, but we've had trouble in the past attempting to wrangle new syntax into the macros, especially after the message string, because currently that whole lot is shelled straight off to format_args as a bag of tokens. Things break in strange ways.

Until we can come up with entirely new macros (I've been prototyping some stuff in this repo) I think we'll have to attach the error at the front, before the message.

[Kixunil]

Heads up: I've recently contributed std::error::Error implementation into slog unaware of this issue here. I hope log can be interoperable with that and I didn't cause some catastrophic incompatibility.

[KodrAus]

@Kixunil No sweat! It looks like the &dyn (std::error::Error + 'static) type you've used in slog should be compatible with both log and tracing, which also use &dyn (Error + 'static).

[Kixunil]

That's great! I don't follow slog/log interop efforts closely, which one will be responsible for connecting them together?