hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Oleg Kalnichevski <ol...@apache.org>
Subject Re: HttpAsyncClient - Connection forcibly closed by remote host
Date Sat, 25 Feb 2012 14:55:49 GMT
On Sat, 2012-02-25 at 12:49 +0100, Alexander Hjalmarsson wrote:
> 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.
> 

Here's the relevant snapshot of events

11:33:46:867 Connection request succeeded:
[id:37][route:{}->http://example.com][state:null]
11:33:46:868 http-outgoing-37 [ACTIVE][r:r]: Set attribute
http.nio.exchange-handler
11:33:46:868 http-outgoing-37 [ACTIVE][rw:r]: Event set [w]
11:33:46:868 http-outgoing-37 [ACTIVE] Timeout
11:33:46:868 http-outgoing-37 [ACTIVE][rw:r]: Close
11:33:46:868 http-outgoing-37 [CLOSED]: Disconnected

As you can see the connection times out pretty much immediately before
the request could be written out.

What is your socket timeout value? Can it be that it is too aggressive?

If you still think that HttpAsyncClient does not handle this situation
correctly please try to package relevant bits of your application as a
self-contained unit test or a test application, raise a JIRA and attach
the source code to it.

Oleg

> 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
> >
> >



---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Mime
View raw message