服务器响应后Apache HttpClient超时异常

Question

我使用 Apache HttpClient 4.1.2 将压缩的二进制数据（序列化的 Java 对象）POST 到服务器。

有时（20% 的时间）客户端会在接收响应时超时，即使服务器正确响应并在其自己的日志记录中记录了“200”响应。

事件的顺序是：

• 客户端 POST 数据到服务器 (T0)。
• 服务器记录数据接收（T2，即T + 2 秒）。
• 服务器处理数据。
• 服务器记录处理的成功完成 (T45)。
• 服务器访问日志显示以“200”状态（T46）发出的已完成响应。
• 客户端阻止读取响应头。
• 客户端超时（T1800，即 POST 请求后 30 分钟，这是我使用的标准超时）。

服务器返回的响应主体是一个很小的纯文本字符串，例如五个字节或更少，例如“OK”。

这里会发生什么？如果服务器没有响应，我可以理解超时；但服务器已经响应，并及时记录了正确的响应，早在客户端超时之前。客户端似乎“试图”读取响应，但阻塞并最终超时。

客户端运行在 Windows XP 机器上；服务器是 Ubuntu。两者都在运行 Java 6（现在是 1.6.29）。

我DefaultHttpClient在每个请求上创建一个新对象，并在每个请求后关闭它（并适当地释放其他资源）。

客户端在请求成功完成后消费和处理响应实体主体，但我们还没有到那一步 - 超时发生在httpclient.execute（方法）调用的上下文中。

堆栈跟踪：

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)

这是来自成功请求的线路级别日志记录。与不成功的请求唯一不同的是，不成功的请求在记录二进制数据后停止，半小时后再次弹出并记录超时。

[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]" 

谢谢。

Answer 1

我注意到回复说

Content-Length: 2

但我在结束空白行之后没有看到任何内容，[\r][\n]这些内容不应被视为内容。我认为这是你的问题。服务器要么应该说Content-Length: 0，要么它没有适当地刷新其缓冲区或其他什么。

此外，服务器在标头中说：

Connection: close

服务器是否已关闭连接或者客户端是否仍处于连接状态？如果服务器没有关闭，那么它就会以某种方式卡住。

希望这可以帮助。