Here is the log I forgot to attach on my previous mail. Thomas
2014-01-29 Thomas Boniface <tho...@stickyads.tv> > 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 <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 >> >> >
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: httpclient-users-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org