Thanks for your help regarding the snapshot. Here is an updated log using
the 4.0.1-SNAPSHOT.
Regarding request cancel, it is done as follow:
if (futureHttpResponse != null && !futureHttpResponse.isCancelled()) {
futureHttpResponse.cancel(true);
}
where futureHttpResponse what the object return by the execute call.
Thomas
2014-01-29 Oleg Kalnichevski <ol...@apache.org>
> On Wed, 2014-01-29 at 16:36 +0100, Thomas Boniface wrote:
> > I can't get my hand on the snapshot can you give a pointer ?
> >
> > It doesn't appear to be available at:
> >
> https://repository.apache.org/content/repositories/snapshots/org/apache/httpcomponents/
> >
> > Nor I can download it using maven: mvn
> > org.apache.maven.plugins:maven-dependency-plugin:2.4:get
> > -DartifactId=httpcomponents-asyncclient
> -DgroupId=org.apache.httpcomponents
> > -Dversion=4.0.1-SNAPSHOT
> >
> > Thanks
> >
>
> Thomas
>
> It is generally preferred to build snapshots from source [1][2]. That
> way one can be sure to get the latest.
>
> If that makes your life easier though I just deployed the latest
> snapshot to the ASF snapshot repository [3]
>
> Oleg
>
> [1]
> http://svn.apache.org/repos/asf/httpcomponents/httpasyncclient/trunk/
> [2] https://github.com/apache/httpasyncclient
> [3]
>
> https://repository.apache.org/content/repositories/snapshots/org/apache/httpcomponents/httpasyncclient/4.0.1-SNAPSHOT/
>
> >
> >
> > 2014-01-29 Oleg Kalnichevski <ol...@apache.org>
> >
> > > On Wed, 2014-01-29 at 14:21 +0100, Thomas Boniface wrote:
> > > > Hi Oleg,
> > > >
> > > > Here is a log with the wire and context log for the behavior I
> described
> > > > before. I obfuscated business related details in the log but most
> of the
> > > > interesting things should be there.
> > > >
> > > > Thanks,
> > > > Thomas
> > > >
> > > >
> > >
> > > For some reason the client considers the connection to be an
> > > inconsistent state and drops it. I cannot figure out why just by
> looking
> > > at the log.
> > >
> > > Could you please do the following: upgrade to the latest
> 4.0.1-SNAPSHOT,
> > > re-run the test and re-post the log as well as let me know exactly how
> > > your application cancels the request?
> > >
> > > Oleg
> > >
> > > >
> > > > 2014-01-29 Oleg Kalnichevski <ol...@apache.org>
> > > >
> > > > > On Wed, 2014-01-29 at 10:42 +0100, Thomas Boniface wrote:
> > > > > > Hi,
> > > > > >
> > > > > > I am using the httpasyncclient 4.0.
> > > > > >
> > > > > > Thomas
> > > > > >
> > > > >
> > > > > Then, things do not quite add up. If one cancels the result future,
> > > this
> > > > > should have no impact on the ongoing request execution. The request
> > > > > still gets fully executed, the response gets fully processed and
> the
> > > > > underlying connection gets returned back to the pool (provided it
> can
> > > be
> > > > > kept alive). The future is simply considered done and will receive
> no
> > > > > result notification.
> > > > >
> > > > > Please note though that connections cannot be kept alive in some
> cases.
> > > > > So, it is perfectly normal that the socket may end up in the
> TIME_WAIT
> > > > > state after the response has been fully processed.
> > > > >
> > > > > Wire / context log should help find out why the connection needs
> to be
> > > > > closed.
> > > > >
> > > > > http://hc.apache.org/httpcomponents-client-4.3.x/logging.html
> > > > >
> > > > > Oleg
> > > > >
> > > > > >
> > > > > > 2014-01-29 Oleg Kalnichevski <ol...@apache.org>
> > > > > >
> > > > > > > On Tue, 2014-01-28 at 18:00 +0100, Thomas Boniface wrote:
> > > > > > > > Hi,
> > > > > > > >
> > > > > > > > I am using an http async client to contact several endpoints
> in
> > > a row
> > > > > > > with
> > > > > > > > the same process. In the context of my application I want to
> > > keep the
> > > > > > > > global process under a certain time. Sometimes it happens
> some
> > > of the
> > > > > > > > executes I triggered using the client did not respond before
> > > what I
> > > > > > > > consider to be a reasonable time.
> > > > > > > >
> > > > > > > > In such a case I used to call cancel on the Future object
> > > returned
> > > > > by the
> > > > > > > > execute in order to free the socket used by this execute as
> soon
> > > as
> > > > > > > > possible (as I don't need the response anymore). The thing
> is it
> > > > > appears
> > > > > > > > that the socket is closed instead of being put back in the
> pool
> > > when
> > > > > I
> > > > > > > call
> > > > > > > > the cancel (The socket appears in TIME_WAIT state when I use
> > > netstat
> > > > > > > > whereas when there is no timeout the socket appears as
> > > ESTABLISHED).
> > > > > > > >
> > > > > > > > Is this an expected behavior ?
> > > > > > > >
> > > > > > > > Thanks,
> > > > > > > > Thomas
> > > > > > >
> > > > > > > Thomas,
> > > > > > >
> > > > > > > What version of HttpAsyncClient are you using?
> > > > > > >
> > > > > > > Oleg
> > > > > > >
> > > > > > >
> > > > > > >
> > > ---------------------------------------------------------------------
> > > > > > > To unsubscribe, e-mail:
> httpclient-users-unsubscr...@hc.apache.org
> > > > > > > For additional commands, e-mail:
> > > httpclient-users-h...@hc.apache.org
> > > > > > >
> > > > > > >
> > > > >
> > > > >
> > > > >
> > > > >
> ---------------------------------------------------------------------
> > > > > To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> > > > > For additional commands, e-mail:
> httpclient-users-h...@hc.apache.org
> > > > >
> > > > >
> > >
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> > > For additional commands, e-mail: httpclient-users-h...@hc.apache.org
> > >
> > >
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> For additional commands, e-mail: httpclient-users-h...@hc.apache.org
>
>
2014-01-29 17:27:49,081 INFO http-nio-8080-exec-1 [Req_1] Starting an auction
2014-01-29 17:27:49,097 INFO http-nio-8080-exec-1 [Req_1] Sending bid request
2014-01-29 17:27:49,097 INFO http-nio-8080-exec-1 [Req_1] Starting async
context
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,209 DEBUG
http-nio-8080-exec-1 [Req_1] [exchange: 1] start execution
org.apache.http.client.protocol.RequestAddCookies: 2014-01-29 17:27:49,213
DEBUG http-nio-8080-exec-1 [Req_1] CookieSpec selected: best-match
org.apache.http.client.protocol.RequestAuthCache: 2014-01-29 17:27:49,220 DEBUG
http-nio-8080-exec-1 [Req_1] Auth cache not set in the context
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
17:27:49,220 DEBUG http-nio-8080-exec-1 [Req_1] [exchange: 1] Request
connection for {}->http://test.server.com:80
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-29
17:27:49,222 DEBUG http-nio-8080-exec-1 [Req_1] Connection request: [route:
{}->http://test.server.com:80][total kept alive: 0; route allocated: 0 of 10;
total allocated: 0 of 10]
networkComm.commands.HttpCommand: 2014-01-29 17:27:49,258 INFO
http-nio-8080-exec-1 [Req_1] command response:
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-29
17:27:49,297 DEBUG I/O dispatcher 1 [ ] Connection leased: [id:
http-outgoing-0][route: {}->http://test.server.com:80][total kept alive: 0;
route allocated: 1 of 10; total allocated: 1 of 10]
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
17:27:49,301 DEBUG I/O dispatcher 1 [ ] [exchange: 1] Connection allocated:
http-outgoing-0 [ACTIVE]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,302 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.172:80[ACTIVE][r:]: Set attribute
http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,302 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.172:80[ACTIVE][rw:]: Event set [w]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:49,302
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE]: Connected
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,303 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.172:80[ACTIVE][rw:]: Set attribute
http.nio.http-exchange-state
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:49,303
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE] Request ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,304 DEBUG
I/O dispatcher 1 [ ] Start connection routing
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,305 DEBUG
I/O dispatcher 1 [ ] Connection route established
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,305 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Attempt 1 to execute request
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,305 DEBUG
I/O dispatcher 1 [ ] Target auth state: UNCHALLENGED
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,306 DEBUG
I/O dispatcher 1 [ ] Proxy auth state: UNCHALLENGED
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,307 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.172:80[ACTIVE][rw:]: Set timeout 60000
org.apache.http.headers: 2014-01-29 17:27:49,307 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> POST /openrtb/slow.php HTTP/1.1
org.apache.http.headers: 2014-01-29 17:27:49,307 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Content-Type: application/json
org.apache.http.headers: 2014-01-29 17:27:49,308 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> x-openrtb-version: 2.0
org.apache.http.headers: 2014-01-29 17:27:49,308 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Content-Length: 614
org.apache.http.headers: 2014-01-29 17:27:49,308 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Host: test.server.com
org.apache.http.headers: 2014-01-29 17:27:49,308 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Connection: Keep-Alive
org.apache.http.headers: 2014-01-29 17:27:49,308 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> User-Agent: Apache-HttpAsyncClient/4.0.1-SNAPSHOT (java 1.5)
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,312 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.172:80[ACTIVE][rw:]: Event set [w]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:49,312
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE] Output ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,312 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] produce content
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:49,313 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Request completed
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:49,313
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE] [content length: 614;
pos: 614; completed: true]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,313 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.xxx:80[ACTIVE][rw:w]: 843 bytes written
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "POST /openrtb/slow.php HTTP/1.1[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Content-Type: application/json[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "x-openrtb-version: 2.0[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Content-Length: 614[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Host: test.server.com[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "User-Agent: Apache-HttpAsyncClient/4.0.1-SNAPSHOT (java
1.5)[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:49,314 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "my request body"
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:49,314 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.xxx:80[ACTIVE][r:w]: Event cleared [w]
2014-01-29 17:27:49,346 INFO http-nio-8080-exec-2 [Req_1] Auction has timedout
2014-01-29 17:27:49,346 INFO http-nio-8080-exec-2 [Req_1] No response from
bidder #59: mark as unfinished
2014-01-29 17:27:49,355 INFO http-nio-8080-exec-2 [Req_1] Cancelling request
for bidder #59
2014-01-29 17:27:49,357 INFO http-nio-8080-exec-2 [Req_1] Async auction
complete
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:54,352 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.xxx:80[ACTIVE][r:r]: 1839 bytes read
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Date: Wed, 29 Jan 2014 16:27:49 GMT[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Server: Apache/2.2.16 (Debian)[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Access-Control-Allow-Origin: *[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "X-Powered-By: PHP/5.3.3-7+squeeze14[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Access-Control-Allow-Credentials: true[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Cache-Control: no-cache[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Content-Length: 1506[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Keep-Alive: timeout=15, max=100[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,352 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Connection: Keep-Alive[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,353 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Content-Type: application/json[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,353 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "[\r][\n]"
org.apache.http.wire: 2014-01-29 17:27:54,353 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "my response body[\n]"
org.apache.http.wire: 2014-01-29 17:27:54,353 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "[\n]"
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << HTTP/1.1 200 OK
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Date: Wed, 29 Jan 2014 16:27:49 GMT
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Server: Apache/2.2.16 (Debian)
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Access-Control-Allow-Origin: *
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << X-Powered-By: PHP/5.3.3-7+squeeze14
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Access-Control-Allow-Credentials: true
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Cache-Control: no-cache
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Content-Length: 1506
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Keep-Alive: timeout=15, max=100
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Connection: Keep-Alive
org.apache.http.headers: 2014-01-29 17:27:54,357 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Content-Type: application/json
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:54,357
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE(1506)] Response received
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:54,357 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Response received HTTP/1.1 200 OK
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:54,361
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE(1506)] Input ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 17:27:54,361 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Consume content
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
17:27:54,361 DEBUG I/O dispatcher 1 [ ] [exchange: 1] releasing connection
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:54,361 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.xxx:80[ACTIVE][r:r]: Remove attribute
http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
17:27:54,361 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:35590<->5.135.147.xxx:80[ACTIVE][r:r]: Close
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
17:27:54,361 DEBUG I/O dispatcher 1 [ ] [exchange: 1] connection discarded
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-29
17:27:54,361 DEBUG I/O dispatcher 1 [ ] Connection released: [id:
http-outgoing-0][route: {}->http://test.server.com:80][total kept alive: 0;
route allocated: 0 of 10; total allocated: 0 of 10]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:54,362
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [CLOSED] [content length: 1506;
pos: 1506; completed: true]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 17:27:54,362
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [CLOSED]: Disconnected
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
