Apache HttpClient timeout exception after server responds

Question

I use Apache HttpClient 4.1.2 to POST zipped binary data (serialized Java objects) to a server.

Sometimes (20% of the time) the client will time out while receiving the response, even after the server has responded correctly and logged a "200" response in its own logging.

The sequence of events is:

• client POSTs data to server (T0).
• server logs receipt of data (T2, i.e. T + 2 seconds).
• server processes data.
• server logs successful completion of processing (T45).
• server access log shows completed response going out with a "200" status (T46).
• client blocks reading response headers.
• client times out (T1800, i.e. 30 minutes after POSTing request, which is the standard timeout I use).

The response body the server returns is a small, like five bytes or less, plain text string, e.g. "OK".

What can be happening here? I could understand timing out if the server hasn't responded; but the server has responded, and has logged a correct response, in a timely way, long before the client times out. The client seems to be "trying" to read the response but blocks and eventually times out.

The client is running on a Windows XP machine; the server is Ubuntu. Both are running Java 6 (1.6.29 right now).

I'm creating a fresh DefaultHttpClient object on each request, and shutting it down (and releasing other resources appropriately) after each request.

The client consumes and disposes of the response entity body after the request successfully completes, but we haven't gotten to that point yet - the timeout is occurring in the context of the httpclient.execute (method) call.

Stack trace:

java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(Unknown Source)
    at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
    at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:110)
    at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
    at org.apache.http.impl.conn.LoggingSessionInputBuffer.readLine(LoggingSessionInputBuffer.java:115)
    at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
    at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
    at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:281)
    at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
    at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:219)
    at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
    at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
    at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:645)
    at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
    at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
    at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
    at foo.StreamerClient.sendRequest(StreamerClient.java:312)
    at foo.StreamerClient.compressAndPostBinaryDataToFooServer(StreamerClient.java:287)
    at foo.StreamerClient.compressAndPostObjectsToFooServer(StreamerClient.java:238)

Here's the wire level logging from a successful request. The only difference from the unsuccessful requests is that the unsuccessful ones stop after logging the binary data, and half an hour later pop up again and log the timeout.

[12-06 14:07:22.359][scheduler-3] D DefaultClientConnection   Sending request: POST /foo/bar HTTP/1.1 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "POST /foo/bar HTTP/1.1[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Accept-Encoding: gzip,deflate[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Content-Type: application/octet-stream[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Content-Length: 401[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Host: foo.com[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Connection: Keep-Alive[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "User-Agent: Apache-HttpClient/4.1.2 (java 1.5)[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "Authorization: Basic fobar[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "[\r][\n]" 
[12-06 14:07:22.359][scheduler-3] D wire                      >> "[several lines of binary data]" 
[12-06 14:07:24.265][scheduler-3] D wire                      << "HTTP/1.1 200 OK[\r][\n]" 
[12-06 14:07:24.265][scheduler-3] D wire                      << "Date: Tue, 06 Dec 2011 03:07:23 GMT[\r][\n]" 
[12-06 14:07:24.265][scheduler-3] D wire                      << "Content-Type: text/plain;charset=ISO-8859-1[\r][\n]" 
[12-06 14:07:24.265][scheduler-3] D wire                      << "Content-Length: 2[\r][\n]"
[12-06 14:07:24.265][scheduler-3] D wire                      << "Connection: close[\r][\n]"
[12-06 14:07:24.265][scheduler-3] D wire                      << "[\r][\n]" 

Thanks.

Answer 1

I noticed that the response says

Content-Length: 2

But I'm not seeing any content after the [\r][\n] closing blank line which should not be counted as content. I think that is your problem. Either the server should be saying Content-Length: 0 or it is not flushing its buffers appropriately or something.

Also, in the headers the server is saying:

Connection: close

Has the server closed the connection or is the client still attached? If the server hasn't closed then it is stuck somehow.

Hope this helps.