Better interceptor chain on errors

[davidsteinsland]

In case of any errors, either a faulty route which throws an exception or requests to a non-existing route, the interceptor chain behaves differently than on requests to routes which responds properly.

In a normal situation the ApplicationSendPipeline is executed during the execution of the ApplicationCallPipeline, which enables us to trace an entire request/response situation using e.g. the Monitoring phase:

intercept(ApplicationCallPipeline.Monitoring) {
     try {
         log.info("incoming request ${call.request.httpMethod.value} ${call.request.uri}")
         proceed()
     } catch (err: Throwable) {
         log.info(err.message, err)
         throw err
     } finally {
         log.info("responding with ${call.response.status()}")
     }
}

Because we are executing within the ApplicationCallPipeline we get the added bonus that our log messages gets enriched with stuff like CallId.

However, when an error occurs (because the route does not exist, or the handler threw an exception) the ApplicationCallPipeline gets interrupted. Then some error handling is done by the DefaultEnginePipeline which tries to set a reasonable status code (404 in case of a non-existing route, 500 in case of exceptions) and logs the exception (no CallId here!).
But because the ApplicationCallPipeline got interrupted, the Monitoring interceptor from above has already exited, so it did never get a chance to act on the response code set by DefaultEnginePipeline.

After DefaultEnginePipeline has done its thing, the ApplicationSendPipeline is executed with the new response. And because ApplicationSendPipeline does not share any attributes with the ApplicationCallPipeline, we do not get the bonus of having things like CallId.

In short, it's hard to properly log a request with the resulting status code, with things like CallId. Because if we want to handle the quirks I've just mentioned, we have to do something like:

intercept(ApplicationCallPipeline.Monitoring) {
     try {
         log.info("incoming request ${call.request.httpMethod.value} ${call.request.uri}")
         proceed()
     } catch (err: Throwable) {
         log.info(err.message, err)
         throw err
     }
}

// ensure that the callId is present during the whole ApplicationSendPipeline execution
sendPipeline.intercept(ApplicationSendPipeline.Before) {
    try {
        MDC.put("call_id", call.callId)
        proceed()
    } finally {
        MDC.remove("call_id")
    }
}

sendPipeline.intercept(ApplicationSendPipeline.After) { message ->
    (when (message) {
        is OutgoingContent -> message.status
        is HttpStatusCode -> message
        else -> null
    } ?: context.response.status())?.let { status ->
        log.info("responding with ${status.value}")
    } ?: log.info("sending unknown response code")
}

[oleg-larshin]

Please check the following ticket on YouTrack for follow-ups to this issue. GitHub issues will be closed in the coming weeks.

[Stexxe]

Cannot reproduce using Ktor 1.6.1.