Hi Oleg,
this is the log for the variant with STALE_CONNECTION_CHECK=TRUE. It can be
seen that the stale connection is detected, as no expect 100-continue is tried.
2011/05/24 11:43:12:391 CEST [DEBUG] ThreadSafeClientConnManager - Get
connection: HttpRoute[{}->http://empkl-lnx13:8030], timeout = 0
2011/05/24 11:43:12:393 CEST [DEBUG] ConnPoolByRoute -
[HttpRoute[{}->http://empkl-lnx13:8030]] total kept alive: 1, total issued: 0,
total allocated: 1 out of 100
2011/05/24 11:43:12:394 CEST [DEBUG] ConnPoolByRoute - No free connections
[HttpRoute[{}->http://empkl-lnx13:8030]][null]
2011/05/24 11:43:12:395 CEST [DEBUG] ConnPoolByRoute - Available capacity: 20
out of 20 [HttpRoute[{}->http://empkl-lnx13:8030]][null]
2011/05/24 11:43:12:396 CEST [DEBUG] ConnPoolByRoute - Creating new connection
[HttpRoute[{}->http://empkl-lnx13:8030]]
2011/05/24 11:43:12:400 CEST [DEBUG] DefaultClientConnectionOperator -
Connecting to empkl-lnx13/172.24.187.30:8030
2011/05/24 11:43:12:404 CEST [DEBUG] DefaultClientConnection - Connection closed
2011/05/24 11:43:12:405 CEST [DEBUG] DefaultClientConnection - Connection shut
down
2011/05/24 11:43:12:406 CEST [DEBUG] ThreadSafeClientConnManager - Released
connection is not reusable.
2011/05/24 11:43:12:408 CEST [DEBUG] ConnPoolByRoute - Releasing connection
[HttpRoute[{}->http://empkl-lnx13:8030]][null]
2011/05/24 11:43:12:409 CEST [DEBUG] ConnPoolByRoute - Notifying no-one, there
are no waiting threads
This is the log for the variant with STALE_CONNECTION_CHECK=FALSE
2011/05/24 11:53:01:679 CEST [DEBUG] ThreadSafeClientConnManager - Get
connection: HttpRoute[{}->http://empkl-lnx13:8030], timeout = 0
2011/05/24 11:53:01:681 CEST [DEBUG] ConnPoolByRoute -
[HttpRoute[{}->http://empkl-lnx13:8030]] total kept alive: 3, total issued: 0,
total allocated: 3 out of 100
2011/05/24 11:53:01:682 CEST [DEBUG] ConnPoolByRoute - Getting free connection
[HttpRoute[{}->http://empkl-lnx13:8030]][null]
2011/05/24 11:53:01:684 CEST [DEBUG] RequestAddCookies - CookieSpec selected:
best-match
2011/05/24 11:53:01:686 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute
request
2011/05/24 11:53:01:687 CEST [DEBUG] DefaultClientConnection - Sending request:
PUT /replicatedstore/obj1_1?token=9b7360dd-dc05-4b75-bd09-c95631c3c981 HTTP/1.1
2011/05/24 11:53:01:689 CEST [DEBUG] wire - >> "PUT
/replicatedstore/obj1_1?token=9b7360dd-dc05-4b75-bd09-c95631c3c981
HTTP/1.1[\r][\n]"
2011/05/24 11:53:01:690 CEST [DEBUG] wire - >> "Transfer-Encoding:
chunked[\r][\n]"
2011/05/24 11:53:01:691 CEST [DEBUG] wire - >> "Host: empkl-lnx13:8030[\r][\n]"
2011/05/24 11:53:01:692 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2011/05/24 11:53:01:693 CEST [DEBUG] wire - >> "User-Agent:
Apache-HttpClient/4.1 (java 1.5)[\r][\n]"
2011/05/24 11:53:01:695 CEST [DEBUG] wire - >> "Expect: 100-continue[\r][\n]"
2011/05/24 11:53:01:695 CEST [DEBUG] wire - >> "[\r][\n]"
2011/05/24 11:53:01:696 CEST [DEBUG] headers - >> PUT
/replicatedstore/obj1_1?token=9b7360dd-dc05-4b75-bd09-c95631c3c981 HTTP/1.1
2011/05/24 11:53:01:697 CEST [DEBUG] headers - >> Transfer-Encoding: chunked
2011/05/24 11:53:01:698 CEST [DEBUG] headers - >> Host: empkl-lnx13:8030
2011/05/24 11:53:01:699 CEST [DEBUG] headers - >> Connection: Keep-Alive
2011/05/24 11:53:01:700 CEST [DEBUG] headers - >> User-Agent:
Apache-HttpClient/4.1 (java 1.5)
2011/05/24 11:53:01:700 CEST [DEBUG] headers - >> Expect: 100-continue
Here I waited in the debugger for the WAIT_FOR_CONTINUE timeout of 5000 ms to
trigger.
Then some data is written on the InputStream which raises the exception.
2011/05/24 11:53:50:549 CEST [DEBUG] wire - >> "800[\r][\n]"
2011/05/24 11:53:50:551 CEST [DEBUG] DefaultClientConnection - I/O error
closing connection <java.net.SocketException: Broken
pipe>java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at
org.apache.http.impl.io.AbstractSessionOutputBuffer.flushBuffer(AbstractSessionOutputBuffer.java:131)
at
org.apache.http.impl.io.AbstractSessionOutputBuffer.flush(AbstractSessionOutputBuffer.java:138)
at
org.apache.http.impl.conn.LoggingSessionOutputBuffer.flush(LoggingSessionOutputBuffer.java:95)
at
org.apache.http.impl.AbstractHttpClientConnection.doFlush(AbstractHttpClientConnection.java:270)
at
org.apache.http.impl.SocketHttpClientConnection.close(SocketHttpClientConnection.java:245)
at
org.apache.http.impl.conn.DefaultClientConnection.close(DefaultClientConnection.java:164)
at
org.apache.http.impl.conn.AbstractPooledConnAdapter.close(AbstractPooledConnAdapter.java:152)
at
org.apache.http.protocol.HttpRequestExecutor.closeConnection(HttpRequestExecutor.java:142)
at
org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:129)
at
org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:622)
at
org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:454)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
at
com.empolis.ias.jdos.DosHttpExecutor.executeMethod(DosHttpExecutor.java:109)
at
com.empolis.ias.jdos.DosOutputStreamImpl$HttpWriter.executePut(DosOutputStreamImpl.java:337)
at
com.empolis.ias.jdos.DosOutputStreamImpl$HttpWriter.run(DosOutputStreamImpl.java:393)
at java.lang.Thread.run(Thread.java:662)
2011/05/24 11:53:50:559 CEST [DEBUG] DefaultHttpClient - Closing the connection.
2011/05/24 11:53:50:560 CEST [DEBUG] DefaultClientConnection - Connection closed
2011/05/24 11:53:50:561 CEST [DEBUG] DefaultClientConnection - Connection shut
down
2011/05/24 11:53:50:561 CEST [DEBUG] ThreadSafeClientConnManager - Released
connection is not reusable.
2011/05/24 11:53:50:562 CEST [DEBUG] ConnPoolByRoute - Releasing connection
[HttpRoute[{}->http://empkl-lnx13:8030]][null]
2011/05/24 11:53:50:563 CEST [DEBUG] ConnPoolByRoute - Notifying no-one, there
are no waiting threads
Bye,
Daniel
-----Ursprüngliche Nachricht-----
Von: Oleg Kalnichevski [mailto:[email protected]]
Gesendet: Dienstag, 24. Mai 2011 11:12
An: HttpClient User Discussion
Betreff: Re: Problems with stale connection check and expect 100-continue
On Tue, 2011-05-24 at 10:45 +0200, [email protected] wrote:
> Hi all,
>
>
>
> I have a scenario where I test error handling when streaming data to a
> http server that is not reachable (e.g. the server process is down).
>
>
>
> With the following settings
>
> client.getParams().setParameter(HttpConnectionParams.STALE_CONNECTION_CH
> ECK, true);
>
>
>
> InputStreamEntity entity = new InputStreamEntity(in, -1);
>
> entity.setChunked(true);
>
> putMethod = new HttpPut(effectiveUri);
>
> putMethod.setEntity(entity);
>
> putMethod.getParams().setParameter(CoreProtocolPNames.USE_EXPECT_CONTINU
> E, true);
>
> putMethod.getParams().setParameter(CoreProtocolPNames.WAIT_FOR_CONTINUE,
> 5000);
>
>
>
> I get a "org.apache.http.conn.HttpHostConnectException: Connection to
> serverXXX refused" before writing anything to the InputStream. This is
> just as expected.
>
>
>
>
>
> If I disable the stale connection check I don't get this exception.
> Instead it seems that either the HttpClient waits for a 100-continue
> response (and does not consider the set timeout of 5000 ms because the
> execute request blocks) or because of a bug http client thinks expect
> 100-continue was successful and waits for data to be written
>
Post a complete wire / context log of the session
http://hc.apache.org/httpcomponents-client-ga/logging.html
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
