Affects: \<6.0.6>
In one of the applications I was working on, we record audit entries once the http response is received by the client. For this purpose, we use the afterCompletion of HandlerInterceptor. We found latencies at times while recording audit entries. We noticed that these latencies are affecting the user experience as the response is received by client only after the audit entries are recorded.
During the initial troubleshooting, it was found that the response is fully written to the client when the response type is String, but not when the response type is anything other than String. As an immediate workaround, we modified the code to convert the pojo as JSON string in the controller method and return to client.
I did post the issue in stackoverflow.com, but did not get a solution yet. The post is available at : https://stackoverflow.com/questions/75109281/handlerinterceptor-interfaces-aftercompletion-method-gets-executed-before-the-r/76096291#76096291.
As we wanted a good solution, I tried to find the root cause of the issue. I found that the Content-Length header is not getting added when the message converter is not StringHttpMessageConverter as the size of Pojo can't be determined before conversion. To resolve the issue for my application, I added a custom Http message converter extending MappingJackson2HttpMessageConverter and overriding the method writeInternal(Object object, @Nullable Type type, HttpOutputMessage outputMessage). The code snippet is as below:
@Override
protected void writeInternal(Object object, @Nullable Type type, HttpOutputMessage outputMessage)
throws IOException, HttpMessageNotWritableException {
if( outputMessage.getHeaders().getContentLength() < 0 ) {
ByteArrayOutputStream byteArrayOutputStream = new ByteArrayOutputStream();
HttpOutputMessage newOutputMessage = new HttpOutputMessage() {
@Override
public OutputStream getBody() {
return byteArrayOutputStream;
}
@Override
public HttpHeaders getHeaders() {
return outputMessage.getHeaders();
}
};
super.writeInternal(object, type, newOutputMessage);
byteArrayOutputStream.flush();
byteArrayOutputStream.close();
HttpHeaders headers = outputMessage.getHeaders();
headers.setContentLength(byteArrayOutputStream.toByteArray().length);
StreamUtils.copy(byteArrayOutputStream.toByteArray(), outputMessage.getBody());
} else {
super.writeInternal(object, type, outputMessage);
}
}
The full demo code is available at: Before resolving: https://github.com/pkurianjohn/InterceptorAfterCompletion/tree/main After resolving with the custom converter solution: https://github.com/pkurianjohn/InterceptorAfterCompletion/tree/content-length-fix
As written in https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/web/servlet/HandlerInterceptor.html, I understand that the afterCompletion is invoked after rendering the view.
I am hoping to get a clarification whether this is the expected behaviour or not. If not, I would like to understand the right solution.
Comment From: pkurianjohn
Apologies for tagging. Could you please have a look at this issue when possible? Thank you. @jhoeller @sbrannen @bclozel @sdeleuze @poutsma @snicoll @cbeams @philwebb @aclement @izeye
Comment From: bclozel
Sorry we did not get to your issue sooner. You have successfully pinged a lot of people including former team members.
I think there is a misunderstanding on the handler interceptor contract. "After completion" means that the view has been rendered (in the sense of MVC), but this is completely independent from the actual writing of bytes to the response body and the response being sent over the network. Measuring times there only partially measured how long controllers take to process requests (in this case excluding the encoding of the response body to JSON for example).
This explains why clients can receive the response after the audit measurement has ended. In fact, Spring is operating at the Servlet level and only the container has full control over how bytes are sent over the network.
Introducing a blocking call in the handler interception contract (as you did in your StackOverflow question) means that this blocks further processing of the response (encoding and writing) until this is done, further delaying the response to the client.
I believe that content length headers here are irrelevant as they don't guarantee that the response will be sent faster. If the length value is missing chunked encoding will be used instead and this has no consequence on response time.
As a result I'm closing this issue.
Comment From: pkurianjohn
Thank you @bclozel for looking into the issue. As per the code in my demo branch https://github.com/pkurianjohn/InterceptorAfterCompletion/tree/content-length-fix , the after completion is invoked after the response is received by the client.
Comment From: bclozel
Yes this is because in your implementation the outputstream is flushed and closed manually. Our own converter doesn't close the stream for cases like #25987
Comment From: pkurianjohn
Hello @bclozel,
It was my mistake to flush and close the ByteArrayOutputStream, but the outstream returned from the method is a non-closeable outputstream.
I modified the code by removing flush and close methods of ByteArrayOutputStream (https://github.com/pkurianjohn/InterceptorAfterCompletion/tree/removed-flush-and-close). By adding the content length header, the response gets committed to client before the code in after completion is executed.
Could you please have a look at it when possible?
Comment From: bclozel
Hi, This doesn't change the fact that this contract is not meant to signal whether the response has been committed nor sent to the client. This is mostly up to the Servlet container. From an observability perspective, the best thing you can do on the server side is measure how long server processing took with a Servlet filter properly ordered. Writing operations to the network can be greatly affected by buffers and proxies. If the proposed change is a good tradeoff for your case then a custom implementation is fine, but we cannot guarantee what you're looking for.