Add option to pass Errors to log functions

[samuelmurray]

Add option to pass Errors to log functions

Motivation:

Addresses #291

Modifications:

Add new API to Logger, that allows the caller to pass an Error object to any log function. Extend LogHandler to allow an implementation to access the error, in order to format the log appropriately. Provide default implementations to preserve backwards compatibility.

Result:

By providing default implementations, the change should be compatible between old and new code, both from the API and implementation side. I.e. a client can use the new API and it will still work with 'old' implementations, and vice versa.

[0xTim]

Why are we deprecating this and making error a standardised parameter in all log messages?

[samuelmurray]

My reasoning was that a LogHandler should not have to implement two separate methods - one with errors and one without. But still the error parameter is optional, so it’s not expected to be included in all log post, just that a LogHandler should decide how to include the error in the resulting log post, if passed to the log method.
Of course this is dependent on the other discussion in this PR, whether or not we want the argument to be passed to the handler at all.

[czechboy0]

I think we could add a convenience to pass an error to a Logger without forwarding it all the way to the LogHandler - just add it as a metadata field. I'm not sure what the LogHandler can realistically do with the error value other than stringify it - so we might as well do it in the Logger, and avoid having to change LogHandler at all.

[Gucky]

... I'm not sure what the LogHandler can realistically do with the error value other than stringify it ...

Maybe that is ultimately the case. The big but is: API of logging services, telemetry services, and others have their API for warning and error cases very often modeled to accept an error alongside the message. You simply can't just provide an error representing a string instead. I tried that with the tools we use. It failed and then I opened #291 to eventually solve it.
And I would argue that changing data types just to fit them with a current system is, after all, a loss of information. An error is more valuable than a raw string no one knows how to analyze. Just one example: Errors may still be NSErrors with domain and error codes, and having access to that is helpful for efficient grouping. You can't do that with anonymous strings that contain, e.g. the URL that failed to load - which might often be different and therefore is not suitable for error grouping.

[czechboy0]

Errors may still be NSErrors with domain and error codes, and having access to that is helpful for efficient grouping

Right, but that is starting to sound like wanting to "see" through the abstraction layer, because you know what's happening on both sides of the LogHandler - you have a specific LogHandler, one that manages errors the way you need, plus you also have your own code that emits errors directly into the Logger, instead of adding them as metadata.

Maybe the right question we should ask ourselves to help figure out if this should be a convenience on Logger, or actually something that propagates through the LogHandler: are errors more than just metadata? Or are they just a common piece of metadata, same as an HTTP response code, HTTP headers, raw data, a "cause" error string, and so on? My current lean is the latter, which is why I just suggested a method on Logger, but I'm open to having my mind changed if we find how an error attached to a log line is fundamentally different to any other piece of metadata attached to a log line.

[Gucky]

Right, but that is starting to sound like wanting to "see" through the abstraction layer, because you know what's happening on both sides of the LogHandler - you have a specific LogHandler, one that manages errors the way you need, plus you also have your own code that emits errors directly into the Logger, instead of adding them as metadata.

Maybe the right question we should ask ourselves to help figure out if this should be a convenience on Logger, or actually something that propagates through the LogHandler: are errors more than just metadata? Or are they just a common piece of metadata, same as an HTTP response code, HTTP headers, raw data, a "cause" error string, and so on? My current lean is the latter, which is why I just suggested a method on Logger, but I'm open to having my mind changed if we find how an error attached to a log line is fundamentally different to any other piece of metadata attached to a log line.

We are talking about .warning and .error cases. So we are literally talking about events that start with an error or not ideal behavior. The message in that case is just a short description of the error - for humans to read. Sure sometimes it's just a message and we don't have an error... but that's in my experience more laziness.

It has nothing to do with seeing through or controlling both sides. We come from an error and reducing that to just a human readable message and some selected values squeezed into Metadata is even more "see through" as you need to know what will be needed on the other side. An error is the original value.

As of today Metadata can only host Strings. Direct, dict, array, nested,... all "leaf" elements have to be some sort of String or StringConvertible. We can't add an Error to Metadata just like that. And in case an Error is actually needed on the other side of the Logger we would have to rebuild the error from the Metadata... way to complex and unnecessary.

We could change the definition of Metadata to also allow an Error. That will also allow to transport an error through the logger layer. To me that doesn't feel right. Like piggybacking essential information among noise as - again - for .error and .warning logs an error is the source of the event and not just metadata.

[samuelmurray]

We could change the definition of Metadata to also allow an Error. That will also allow to transport an error through the logger layer. To me that doesn't feel right. Like piggybacking essential information among noise as - again - for .error and .warning logs an error is the source of the event and not just metadata.

I agree that this doesn’t feel right. Also it would be hard to agree on a common key in which to pass the error. I suspect there are already consumers of the api that pass stringified errors under “error” or “err”, and so then the log handlers would still have to do pattern matching to see if a value is an Error.

For me a big reasong for adding this is to allow LogHandlers to do structured logging, e.g. if you want a handler to output ECS-formatted logs. Then you want to pass the error message to “error.message”, and perhaps the type name to “error.type”. You might also want to do pattern matching to extract an error code (from an NSError) to “error.code” and so on. Simply passing the stringified error to the handler prevents all of this, or forces the caller of the log API to do all the extraction (passing the message, code, and type to separate metadata fields) which then couples the code that generates the logs with the desired log format.
The same argument could be said about other metadata as well, but I guess to me, as @Gucky is arguing, an Error is not just “any other metadata” but rather could be related to the cause of the log post in the first place.

[czechboy0]

Can you describe what a LogHandler would do with an Error, other than turn it into a string, without knowing what concrete types of error your code is sending to the Logger? Maybe I'm missing something here, but Error alone gives you very little when it comes to programmatic handling. Are you saying every LogHandler should try to cast every incoming Error into several common concrete error types, like DecodingError, etc? Or how can you go from an Error back to the structured error you describe above, without coupling it with the emission code?

[Gucky]

Can you describe what a LogHandler would do with an Error, other than turn it into a string, [...] Are you saying every LogHandler should try to cast every incoming Error into several common concrete error types, like DecodingError, etc? [...]

The Error protocol is not alone.
Using cast checks to CustomNSError, NSError or LocalizedError we can tap into more structured information about an error. Using an errors userInfo we can get access to underlying errors - e.g. when a network error is wrapped into a more generic "loginFailed" error. Errors can have a nested hierarchy.
We get access to the errors own description, not just the message from the log statement itself.
And all that is convenience we lose. And complexity added on caller site when trying to squeeze all that into metadata.

And let's look beyond our own code. Sure in my own code I could encode into metadata all that I need.
The big benefit of swift-log is that everyone implementing it automatically contributes to my logging system and log handlers.
But I can't tell e.g. Alamofire, Kingfisher, GRDB, ... how to encode their errors into metadata so that I can do more with it than just printing. Metadata is entirely "unstructured" and just good for printing.
If 3rd party libraries could just contribute their error directly I would have it type safe, can work with it, ultimately provide it to log handlers that try to squeeze data from an error for clustering.

[czechboy0]

Gotcha. Yeah this basically requires LogHandlers to "guess" various error types, and dynamically cast them. I'm not sure if this is the way this API package is meant to be used, since it still couples emission code on Logger with processing code in LogHandler. I worry about what this would mean for eg an out-of-process LogHandlers, since suddenly what's being passed through isn't all simple serializable data, but custom objects that can't be transparently transferred over process boundaries without losing meaning.

I still think the emission code is in a better position to turn an error it's emitting into good metadata fields than the LogHandler, but I'll let others chime in. @FranzBusch @0xTim @weissi @ktoso

[FranzBusch]

Overall, I am open to changing both LogHandler and Logger to accept errors since this often carry a lot of additional information as pointed out here. However, I would like to see this change be motivated with a formal lightweight proposal similar to how we did it with other changes. In particular, this should call out some of the intended usage here and it should also address the source stability concerns of introducing a new method on Logger and the LogHandler protocol.

[samuelmurray]

Can you describe what a LogHandler would do with an Error, other than turn it into a string, without knowing what concrete types of error your code is sending to the Logger? […]

Ignoring the possibilities that casting/pattern matching the error gives you, one thing you could extract is the name of the underlying type.

let message = “\(error)”
let type = String(describing: type(of: error))

This would help grouping/categorizing logs arising from the same underlying error, especially if the message is not a static text (e.g. includes a timestamp or some other dynamic data).

Imagine the following example:

enum NetworkError: Error {
  case hostNotFound
  case httpCode(Int)
}

The stringified error would give something like “hostNotFound” and “httpCode(400)”, giving no indication that these are of the same type, whereas getting the type name (“NetworkError”) could help track overall occurrences of this error.
I would also argue it helps searching for the error in code, and can provide helpful context that the error message does not contain.

A stringified LocalizedError such as

enum NetworkError: Error, LocalizedError {
  case httpCode(Int)
  // …
  var errorDescription: String? {
    switch self {
    case .httpCode(let code):
      “Received http status \(code) in network request”
    }
  }
}

would simply give “Received http status 400 in network request”, making it even harder to search for, since it’s not apparent what parts of the message are static and not. So, getting the type name can be of huge help.

[samuelmurray]

Overall, I am open to changing both LogHandler and Logger to accept errors since this often carry a lot of additional information as pointed out here. However, I would like to see this change be motivated with a formal lightweight proposal similar to how we did it with other changes. In particular, this should call out some of the intended usage here and it should also address the source stability concerns of introducing a new method on Logger and the LogHandler protocol.

This sounds reasonable. @Gucky would you be able to help produce such a proposal?

[0xTim]

Imagine the following example:

enum NetworkError: Error {
  case hostNotFound
  case httpCode(Int)
}

I think the point that was @czechboy0 was making was that if you have an error like that in your application you also need the log handler you're using to know about that error as well so it knows how to handle the error. At which point, why not do that logic in the application anyway (not saying I completely disagree with the premise of the PR, but we are going to have to make sure that log handlers decide what to do with an error)

[samuelmurray]

I think the point that was @czechboy0 was making was that if you have an error like that in your application you also need the log handler you're using to know about that error as well so it knows how to handle the error.

I disagree with this. The error can come from a third party library that your application uses, and so you might not know what error type you caught. My example was just to show that there is more information that the LogHandler might want to extract, other than the stringified version of the error. (Of course, the application code could also extract this, and pass as metadata, but the idea of this PR is to shift the responsibility to the LogHandler on what to extract and not, and how to format the final log post, and provide a unified API for how we log Errors.)

[czechboy0]

What I think would be very reasonable is an extension like this, in Swift Log:

extension Logger {
    public func log(
        level: Logger.Level,
        _ message: @autoclosure () -> Logger.Message,
        error: any Error,
        metadata: @autoclosure () -> Logger.Metadata? = nil,
        source: @autoclosure () -> String? = nil,
        file: String = #fileID,
        function: String = #function,
        line: UInt = #line
    ) {
        self.log(
            level: level, 
            message(), 
            metadata: { 
                var metadata = metadata()
                metadata["error.type"] = "\(type(of: error))"
                metadata["error.message"] = "\(error)"
                return metadata
            }(),
            source: source(), 
            file: file, 
            function: function, 
            line: line
        )
    }
}

And in your application code, you could implement additional similar extensions that work with the errors your app is throwing.

I'm just not sure what the LogHandler can do that a Logger extension can't do. And the upside of the above is that it'll work with every LogHandler, not just those that explicitly opt into the potential new override. Keep in mind that there are many LogHandlers in the ecosystem already, and ideally they all shouldn't have to be updated to take advantage of more ergonomic error logging.