[Vapor 4] ErrorMiddleware should log the request path of a failed request

[natanrolnik]

When debugging requests that fail for some reason, it would be very helpful if ErrorMiddleware would print the path of the request. This was implemented in Vapor 3 a few days ago in #2170, and a similar approach would be enough to solve this in Vapor 4.

[tanner0101]

I started on implementing this fix, but I'm realizing it might not make sense to port the Vapor 3 change directly to 4. In Vapor 4, we have request-id metadata attached to each log. We also print out the incoming request method + path to the logs at .info level or lower.

With those two pieces of information, it's trivial to find the associated request method + path for a given error. Take the following example output from a test route I setup:

app.get("error") { req -> String in
    throw TestError()
}

[ INFO ] GET /error [request-id: CBB327BF-71E5-47C1-9067-5AB7B533EF5A] (Vapor/Responder/DefaultResponder.swift:35)
[ ERROR ] TestError 500: This is a test. [request-id: CBB327BF-71E5-47C1-9067-5AB7B533EF5A] (Development/routes.swift:167)

Given including the request method + path again in the error log would be redundant in certain cases, I'm wondering if we should include it. All errors logged to req.logger include the request-id. This includes error messages logged by other packages that might result not result in errors ErrorMiddleware will catch. In other words, linking the log message's request-id to the info log containing the request method and path is a more consistent way to find that information.

[0xTim]

Definitely like how this is going, one thing I would say is, is it possible to print the request ID in a fixed position for each request? Something like:

[Request ID: CBB327BF-71E5-47C1-9067-5AB7B533EF5A] [ INFO ] GET /error (Vapor/Responder/DefaultResponder.swift:35)
or
[ INFO - request-id: CBB327BF-71E5-47C1-9067-5AB7B533EF5A] GET /error (Vapor/Responder/DefaultResponder.swift:35)

Might make it easier to work with in logging backends (though if the whole thing is wrapped in [request-id: <ID>] that's actually not too bad

[natanrolnik]

Interesting, @tanner0101 - that is definitely way better than the default behavior in Vapor 3.
And I agree with @0xTim, having the request ID at the start of the line is easier to parse when looking for a specific ID.

[tanner0101]

What about if we had it on a new line? Maybe indented as well:

[ INFO ] GET /error (Vapor/Responder/DefaultResponder.swift:35)
    [request-id: CBB327BF-71E5-47C1-9067-5AB7B533EF5A]
[ ERROR ] TestError 500: This is a test. (Development/routes.swift:167)
    [request-id: CBB327BF-71E5-47C1-9067-5AB7B533EF5A]

The other thing to remember is that some pluggable logging backends will aggregate this metadata in a structured way and allow for filtering of results. (See https://github.com/apple/swift-log for backends currently supported). I haven't used these too much, but I imagine you can add a filter like request-id == CBB327BF-71E5-47C1-9067-5AB7B533EF5A and then only see log messages for that specific request with other metadata shown as a nice, nested tree.