hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alexander Hjalmarsson <hja...@sgh.se>
Subject Re: HttpAsyncClient - Connection forcibly closed by remote host
Date Sat, 25 Feb 2012 11:49:05 GMT
I can't reliably reproduce it, but it happens within < 100 requests. I
can't find what triggerrs it, and the same request can be completed in one
run and fail in another. Here is the log directly after the failing request
have been executed:


2012/02/25 11:33:46:867 CET [DEBUG] PoolingClientAsyncConnectionManager -
Connection request: [route: {}->http://example.com][total kept alive: 16;
route allocated: 1 of 2; total allocated: 16 of 400]
2012/02/25 11:33:46:867 CET [DEBUG] PoolingClientAsyncConnectionManager -
Connection leased: [id: 37][route: {}->http://example.com][total kept
alive: 15; route allocated: 1 of 2; total allocated: 16 of 400]
2012/02/25 11:33:46:867 CET [DEBUG] DefaultHttpAsyncClient - Connection
request suceeded: [id:37][route:{}->http://example.com][state:null]
2012/02/25 11:33:46:868 CET [DEBUG] IOSessionImpl - http-outgoing-37
85.226.146.192:16165<->134.25.4.140:80[ACTIVE][r:r]: Set attribute
http.nio.exchange-handler
2012/02/25 11:33:46:868 CET [DEBUG] IOSessionImpl - http-outgoing-37
85.226.146.192:16165<->134.25.4.140:80[ACTIVE][rw:r]: Event set [w]
2012/02/25 11:33:46:868 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-37 [ACTIVE] Timeout
2012/02/25 11:33:46:868 CET [DEBUG] IOSessionImpl - http-outgoing-37
85.226.146.192:16165<->134.25.4.140:80[ACTIVE][rw:r]: Close
2012/02/25 11:33:46:868 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-37 [CLOSED]: Disconnected
2012/02/25 11:33:47:782 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-40 [ACTIVE] Timeout
2012/02/25 11:33:47:782 CET [DEBUG] IOSessionImpl - http-outgoing-40
85.226.146.192:16168<->193.104.215.61:80[ACTIVE][r:r]: Close
2012/02/25 11:33:47:782 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-36 [ACTIVE] Timeout
2012/02/25 11:33:47:782 CET [DEBUG] IOSessionImpl - http-outgoing-36
85.226.146.192:16164<->134.25.4.140:80[ACTIVE][r:r]: Close
2012/02/25 11:33:47:782 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-38 [ACTIVE] Timeout
2012/02/25 11:33:47:783 CET [DEBUG] IOSessionImpl - http-outgoing-38
85.226.146.192:16166<->199.59.148.10:80[ACTIVE][r:r]: Close
2012/02/25 11:33:47:783 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-40 [CLOSED]: Disconnected
2012/02/25 11:33:47:783 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-36 [CLOSED]: Disconnected
2012/02/25 11:33:47:783 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-38 [CLOSED]: Disconnected
2012/02/25 11:33:47:868 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-39 [ACTIVE] Timeout
2012/02/25 11:33:47:868 CET [DEBUG] IOSessionImpl - http-outgoing-39
85.226.146.192:16167<->82.99.28.179:80[ACTIVE][r:r]: Close
2012/02/25 11:33:47:868 CET [DEBUG] HttpAsyncRequestExecutor -
http-outgoing-39 [CLOSED]: Disconnected

After this, nothing happens.

On Sat, Feb 25, 2012 at 10:50 AM, Oleg Kalnichevski <olegk@apache.org>wrote:

> On Sat, 2012-02-25 at 02:47 +0100, Alexander Hjalmarsson wrote:
> > Thank you for all your answers. I've now solved some of the problems I
> had,
> > but I got another question now.. I don't know if this this is a bug or if
> > I'm thinking about this in the wrong way:
> >
> > In this example Im sending ONE request to a server, and I'm blocked until
> > I've received a response from the callback (either fail or success). It
> > works most of the requests and when it do work, it looks something like
> > this:
> >
> > 2012/02/25 02:17:14:590 CET [DEBUG] DefaultHttpAsyncClient - Connection
> > request suceeded: [id:8][route:{}->http://example.com][state:null]
> > 2012/02/25 02:17:14:591 CET [DEBUG] DefaultHttpAsyncClient - Attempt 1 to
> > execute request
> > 2012/02/25 02:17:15:261 CET [DEBUG] DefaultHttpAsyncClient - Response:
> > HTTP/1.1 200 OK
> > 2012/02/25 02:17:15:316 CET [DEBUG] DefaultHttpAsyncClient - Response
> fully
> > read
> > 2012/02/25 02:17:15:316 CET [DEBUG] DefaultHttpAsyncClient - Connection
> can
> > be kept alive indefinitely
> > 2012/02/25 02:17:15:316 CET [DEBUG] DefaultHttpAsyncClient - Response
> > processed
> >
> > Then suddenly I can make a call that outputs only the first row:
> > 2012/02/25 02:17:15:466 CET [DEBUG] DefaultHttpAsyncClient - Connection
> > request suceeded: [id:1][route:{}->http://example.com][state:null]
> >
> > but it doesn't go any further than that and the request is neither failed
> > for any kind of timeout nor completed within many minutes. It seems like
> it
> > never gets the possibility to make the request. When I've let the request
> > run for some time (~10 minutes), I forcibly shutdown the
> connectionmanager
> > and receives
> >
> > 2012/02/25 02:30:50:897 CET [DEBUG] DefaultHttpAsyncClient - HTTP
> exchange
> > cancelled
> >
> > Which indicates that there was a request that was cancelled at least.
> Since
> > the requests never terminates, my program never gets out of the lock
> (since
> > the callback function is never executed). It might be a terrible way of
> > handling requests, but I can't see the explanation why it behaves like
> > this.
> >
> > And yeah, I'm using the 4.0-BETA1 :)
> >
> >
>
> Is this an intermittent problem or can it be reliably reproduced? Please
> also provide a complete wire / context log of the session.
>
> Oleg
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message