5

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.

Improve this question
0

1 Answer 1

Reset to default
2

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.

Improve this answer
Sign up to request clarification or add additional context in comments.

7 Comments

Thanks for your reply. The response I've included is a successful one. (The unsuccessful ones time out before logging any inbound wire traffic). I had noticed the business with Content-Length: 2 as well, but in this case the request and response have succeeded, so it must be doing something right; if nothing else, the server and client agree on how to handle the response. The Connection: close is, I'm pretty sure, just the standard final line of an HTTP response, similar perhaps to "EOF" in a scripting language.
No, "Connection: close" means that after the response, the server is supposed to close the connection. Is it doing so? If you look at the server (or maybe netstat -an), do you still see the connection? See here: docs.oracle.com/javase/1.5.0/docs/guide/net/http-keepalive.html
It's both from the client and the server. The client can request that the server closes the connection after the response. If the server says "Connection: close" then it better close the connection. If the connection is not closed then something is wrong on the server side.
Thanks for that link, that's very interesting. I had no idea keep-alive was the default behavior. I certainly don't want to keep these connections alive - I want to start with a clean slate on each connection attempt. Your suggestion about checking the server for evidence that the connection is still open is a good one and I'll follow it up. If the connection remains open even after Tomcat has logged a "200" response, that will be worth pursuing.
Sure thing. Reminder to +1 for the work. If it eventually solves your problem (or helps with) be sure to accept.
|

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.