我使用Apache HttpClient 4.1.2将压缩的二进制数据(序列化的Java对象)POST到服务器。
有时(20%的时间)客户端在接收响应时会超时,甚至在服务器正确响应并在其自己的日志记录中记录"200"响应之后。
事件顺序为:
- 客户端发送数据到服务器(T0)。
- 服务器记录接收数据(T2,即T + 2秒)。
- 服务器处理数据。
- 服务器记录处理成功完成(T45)。
- 服务器访问日志显示完成响应输出,状态为"200"(T46)。
- client block read response headers.
- 客户端超时(T1800,即post请求后30分钟,这是我使用的标准超时)
服务器返回的响应体是一个小的纯文本字符串,比如5个字节或更少。"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]"
谢谢。
我注意到响应说
Content-Length: 2
但我没有看到[r][n]
结束空白行后的任何内容,不应算作内容。我想那是你的问题。要么服务器应该说Content-Length: 0
,要么它没有适当地刷新缓冲区或其他东西。
同时,在报头中服务器说:
Connection: close
服务器已关闭连接或客户端仍在连接?如果服务器没有关闭,那么它就被卡住了。