Here is the log I forgot to attach on my previous mail.
Thomas
2014-01-29 Thomas Boniface <[email protected]>
> 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
>
>
>
> 2014-01-29 Oleg Kalnichevski <[email protected]>
>
>> 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 <[email protected]>
>> >
>> > > 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: [email protected]
>> > > For additional commands, e-mail: [email protected]
>> > >
>> > >
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [email protected]
>> For additional commands, e-mail: [email protected]
>>
>>
>
2014-01-29 11:46:29,475 INFO http-nio-8080-exec-1 [Req_1] Starting an auction
2014-01-29 11:46:29,492 INFO http-nio-8080-exec-1 [Req_1] Sending bid request
2014-01-29 11:46:29,493 INFO http-nio-8080-exec-1 [Req_1] Starting async
context
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,605 DEBUG
http-nio-8080-exec-1 [Req_1] [exchange: 1] start execution
org.apache.http.client.protocol.RequestAddCookies: 2014-01-29 11:46:29,609
DEBUG http-nio-8080-exec-1 [Req_1] CookieSpec selected: best-match
org.apache.http.client.protocol.RequestAuthCache: 2014-01-29 11:46:29,617 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
11:46:29,617 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
11:46:29,619 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]
2014-01-29 11:46:29,754 INFO http-nio-8080-exec-2 [Req_1] Auction has timedout
2014-01-29 11:46:29,754 INFO http-nio-8080-exec-2 [Req_1] No response from
bidder #59: mark as unfinished
2014-01-29 11:46:29,760 INFO http-nio-8080-exec-2 [Req_1] Cancelling request
for bidder #59
2014-01-29 11:46:29,762 INFO http-nio-8080-exec-2 [Req_1] Async auction
complete
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-29
11:46:29,788 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
11:46:29,792 DEBUG I/O dispatcher 1 [ ] [exchange: 1] Connection allocated:
http-outgoing-0 [ACTIVE]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,793 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][r:]: Set attribute
http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,793 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][rw:]: Event set [w]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:29,793
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE]: Connected
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,794 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][rw:]: Set attribute
http.nio.http-exchange-state
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:29,794
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE] Request ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,795 DEBUG
I/O dispatcher 1 [ ] Start connection routing
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,796 DEBUG
I/O dispatcher 1 [ ] Connection route established
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,796 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Attempt 1 to execute request
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,796 DEBUG
I/O dispatcher 1 [ ] Target auth state: UNCHALLENGED
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,797 DEBUG
I/O dispatcher 1 [ ] Proxy auth state: UNCHALLENGED
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,797 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][rw:]: Set timeout 60000
org.apache.http.headers: 2014-01-29 11:46:29,797 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> POST /openrtb/slow.php HTTP/1.1
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Content-Type: application/json
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> x-openrtb-version: 2.0
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Content-Length: 614
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Host: test.server.com
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> Connection: Keep-Alive
org.apache.http.headers: 2014-01-29 11:46:29,798 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> User-Agent: Apache-HttpAsyncClient/4.0 (java 1.5)
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,800 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][rw:]: Event set [w]
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:29,801
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE] Output ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,801 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] produce content
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:29,801 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Request completed
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:29,802
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
11:46:29,802 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][rw:w]: 832 bytes written
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "POST /openrtb/slow.php HTTP/1.1[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Content-Type: application/json[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "x-openrtb-version: 2.0[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Content-Length: 614[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Host: test.server.com[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "User-Agent: Apache-HttpAsyncClient/4.0 (java 1.5)[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:29,802 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 >> "my request body"
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:29,802 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][r:w]: Event cleared [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:34,834 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][r:r]: 1839 bytes read
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Date: Wed, 29 Jan 2014 10:46:29 GMT[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Server: Apache/2.2.16 (Debian)[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Access-Control-Allow-Origin: *[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 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 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Access-Control-Allow-Credentials: true[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Cache-Control: no-cache[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Content-Length: 1506[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Keep-Alive: timeout=15, max=100[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Connection: Keep-Alive[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "Content-Type: application/json[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "[\r][\n]"
org.apache.http.wire: 2014-01-29 11:46:34,835 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "my response body[\n]"
org.apache.http.wire: 2014-01-29 11:46:34,836 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << "[\n]"
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << HTTP/1.1 200 OK
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Date: Wed, 29 Jan 2014 10:46:29 GMT
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Server: Apache/2.2.16 (Debian)
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Access-Control-Allow-Origin: *
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << X-Powered-By: PHP/5.3.3-7+squeeze14
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Access-Control-Allow-Credentials: true
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Cache-Control: no-cache
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Content-Length: 1506
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Keep-Alive: timeout=15, max=100
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Connection: Keep-Alive
org.apache.http.headers: 2014-01-29 11:46:34,840 DEBUG I/O dispatcher 1 [ ]
http-outgoing-0 << Content-Type: application/json
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:34,840
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE(1506)] Response received
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:34,841 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Response received HTTP/1.1 200 OK
org.apache.http.nio.protocol.HttpAsyncRequestExecutor: 2014-01-29 11:46:34,844
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [ACTIVE(1506)] Input ready
org.apache.http.impl.nio.client.MainClientExec: 2014-01-29 11:46:34,844 DEBUG
I/O dispatcher 1 [ ] [exchange: 1] Consume content
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
11:46:34,844 DEBUG I/O dispatcher 1 [ ] [exchange: 1] releasing connection
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:34,844 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][r:r]: Remove attribute
http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-29
11:46:34,844 DEBUG I/O dispatcher 1 [ ] http-outgoing-0
192.168.0.26:59785<->5.135.147.172:80[ACTIVE][r:r]: Close
org.apache.http.impl.nio.client.InternalHttpAsyncClient: 2014-01-29
11:46:34,844 DEBUG I/O dispatcher 1 [ ] [exchange: 1] connection discarded
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-29
11:46:34,844 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 11:46:34,844
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 11:46:34,845
DEBUG I/O dispatcher 1 [ ] http-outgoing-0 [CLOSED]: Disconnected
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
