Bad chunk header mystery

Recently, I encounter an interesting issue in my project at work. I’m working on many Springboot-based microservices, and sometimes, an exception is thrown after using RestTemplate exchange() method:

org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.web.client.ResourceAccessException: I/O error on POST request for “...": Bad chunk header: {...}; nested exception is org.apache.http.MalformedChunkCodingException: Bad chunk header: {...} at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909) at javax.servlet.http.HttpServlet.service(HttpServlet.java:660) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

Below is the simplified sequence diagram:

After investigating, here is what I found about this issue:

• The exception is thrown after service A received the response from service B.
• The issue only happens when I run some performance test cases that flood service A with requests.
• The issue is pretty consistent, although not at an exact time, but happens most of the times I run test case.
• The interesting thing here is the log from service B & C didn’t show anything wrong when this issue happened, indicated that request is succeeded and response is returned. But is it true???
• The exception message is short but still left an important hint: header. Did service A receive an inappropriate header, or more correctly, service B sent an unwanted header? How can we know what header is wrong?

Further investigating, I found that service B just forwards request to service C, then forwards the response from service C to service A. Something like this:

public ResponseEntity<?> forwardRequest(@RequestBody Request request) {
    return restTemplate.exchange(url, HttpMethod.POST, request, ...)
}

If so, did the inappropriate header not come from service B, but from service C instead?

Luckily, we can insert code to log all the headers of service C response. After adding and re-running test case, here is what I get when the exception occurs:

Header: [Connection] > [close]
Header: [Content-Type] > [application/json;charset=UTF-8]
Header: [Date] > [DD/mm/yyyy]
Header: [Transfer-Encoding] > [chunked]

For easier, here is normal response’s headers:

Header: [Content-Type] > [application/json;charset=UTF-8]
Header: [Date] > [DD/mm/yyyy]
Header: [Transfer-Encoding] > [chunked]

Finally, we can see the culprit. It is the header Connection: close that service C returned and service B blindly returned to service A.

But what does Connection: close mean? And how it is included in the service C response?

From RFC 2616, Section 14.10 , Connection: close is included to signal that the connection will be closed after completion of the response. Normally, connection with keepAlive property will not be closed by the server so the client can keep using it for another request. But tomcat has a max-keepalive-timeout setting, that will close connection that reaches a certain keepAlive time. And that is when the server will include Connection: close header.

Conclusion

Now we know that blindly forwarding responses without filtering out headers is a bad practice. In case you don’t care about the header, just extract and return only the response body is enough.

Originally published at rey5137.com