Hi Oleg,
One more information I forgot to provide, not sure if it can help.
>From the 08.13:00 to 08:13:59 the pool kept exhausted:
08:13:00.211 Connection request: [route: {}->http://10.15.15.41:8081][total
kept alive: 0; route allocated: 6 of 1500; total allocated: 1500 of 1500]
( . . . .)
08:13:59.893 Connection request: [route: {}->http://10.15.15.5:8083][total
kept alive: 0; route allocated: 108 of 1500; total allocated: 1500 of 1500]
But at any second within 08:13:xx we performed a "netstat -anp | grep
ESTABLISHED" and the result was 300. Should not it be 1500 at least?
Thanks,
Joan.
-----Original Message-----
From: Oleg Kalnichevski <[email protected]>
Sent: Thursday, June 6, 2019 3:15 PM
To: HttpClient User Discussion <[email protected]>
Subject: Re: Response timeout issue
On Thu, 2019-06-06 at 14:34 +0200, Joan grupoventus wrote:
> No .. that's the point ... we are trying any kind of tests ... no
> success. Did you see the 'ServerHttpResponse.java' code? Do you think
> the code is correct?
>
I cannot say 10% without seeing the complete code base.
Oleg
> We are thinking to replace the HttpClient5 by the AsyncClient1.3 and
> leave the rest of our code untouched and check again. So at least we
> will know in what side the issue is.
>
> We'll try to do this today ... I'll keep you informed.
>
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Oleg Kalnichevski <[email protected]>
> Sent: Thursday, June 6, 2019 2:27 PM
> To: HttpClient User Discussion <[email protected]>
> Subject: Re: Response timeout issue
>
> On Wed, 2019-06-05 at 16:19 +0200, Joan grupoventus wrote:
> > Hi Oleg,
> >
> > Still dealing with this stuck connections. I could get traces from
> > httpClient5 and we see all connections busy:
> > 08:12:56.031 ex-00E1DFB8: acquiring connection with route
> > {}->
> > http://10.15.15.14:8082
> > 08:12:56.087 Connection request: [route: {}->
> > http://10.15.15.14:8083][total kept alive: 0; route allocated: 108
> > of 1500; total allocated: 1500 of 1500]
> >
> > This happened previously because we were not expanding the capacity
> > of the buffer in the 'updateCapacity' method. After your
> > clarification this was fixed:
> > @Override
> > public void updateCapacity(CapacityChannel cc) {
> > try { cc.update(this.capacityToPerform); }
> > catch (Exception e) {
> > GlobalData.getInstance().getLoggerService().flushCluster("log.inter
> > na
> > l.error.server.http", new Object[] { this.objCall.getNombre(),
> > this.capacityToPerform, Utils.stackToString(e) }, true); } }
> >
> > But now, after several days working, the pool becomes full again.
> > And
> > the only way to solve the issue is restarting it (stopping the http
> > instance and starting it again from our app). This happens at
> > 08.14.03.225 in the http log we have on this repository:
> > https://github.com/joanbalaguero/HttpClient.git
> >
> > 08:14:03.054 Connection request: [route: {}->
> > http://10.15.15.53:8083][total kept alive: 0; route allocated: 107
> > of 1500; total allocated: 1500 of 1500]
> > 08:14:03.080 Connection request: [route: {}->
> > http://10.15.15.53:8080][total kept alive: 0; route allocated: 108
> > of 1500; total allocated: 1500 of 1500]
> > 08:14:03.107 Connection request: [route: {}->
> > http://10.15.15.53:8082][total kept alive: 0; route allocated: 107
> > of 1500; total allocated: 1500 of 1500]
> > 08:14:03.192 ex-00E1E1D1: preparing request execution
> > 08:14:03.192 Target auth state: UNCHALLENGED
> > 08:14:03.192 Proxy auth state: UNCHALLENGED
> > 08:14:03.192 ex-00E1E1D1: acquiring connection with route
> > {}->
> > http://10.15.15.24:8080
> > 08:14:03.197 Shutdown connection pool GRACEFUL
> > 08:14:03.224 Connection request: [route: {}->
> > http://10.15.15.24:8080][total kept alive: 0; route allocated: 10 of
> > 1500; total allocated: 1500 of 1500]
> > 08:14:03.225 i/o-0041DB56: Shutdown connection GRACEFUL
> > 08:14:03.226 i/o-0041DB37: Shutdown connection GRACEFUL
> > 08:14:03.226 i/o-0041DB19: Shutdown connection GRACEFUL
> > 08:14:03.242 Connection pool shut down
> > 08:14:03.242 Shutdown GRACEFUL
> > 08:14:03.276 ex-00E1E1D2: preparing request execution
> > 08:14:03.276 Target auth state: UNCHALLENGED
> > 08:14:03.276 Proxy auth state: UNCHALLENGED
> > 08:14:03.276 ex-00E1E1D2: acquiring connection with route
> > {}->
> > http://10.15.15.53:8081
> > 08:14:03.277 Connection request: [route: {}->
> > http://10.15.15.53:8081][total kept alive: 0; route allocated: 0 of
> > 1500; total allocated: 0 of 1500]
> > 08:14:03.277 Connection leased: [route: {}->
> > http://10.15.15.53:8081][total kept alive: 0; route allocated: 1 of
> > 1500; total allocated: 1 of 1500]
> > 08:14:03.277 ep-00DFEDB0: acquired null
> > 08:14:03.277 ex-00E1E1D2: connection acquired
> > 08:14:03.279 ep-00DFEDB0: connected i/o-00423C70
> > 08:14:03.279 Connected to target
> > 08:14:03.279 Route fully established
> >
> > The point is the variable 'this.capacityToPerform' we use to enlarge
> > the buffer is set in the 'consumeResponse' method when we have a
> > non-
> > null EntityDetails (you can see it in the ServerHttpResponse.java):
> > @Override
> > public void consumeResponse(HttpResponse response, EntityDetails
> > entityDetails, HttpContext context, FutureCallback<Void> fcback)
> > throws IOException, HttpException {
> > ( . . . .)
> > if (entityDetails != null)
> > {
> > this.capacityToPerform = entityDetails.getContentLength() > 0 ?
> > (int)entityDetails.getContentLength() :
> > GlobalData.getInstance().getHttpService().getBufferInInterface();
> > //
> > <--
> > GlobalData.getInstance().getHttpService().getBufferInInterface()
> > is 32768
> > this.vbaos = new
> > VentusByteArrayOutputStream(this.capacityToPerform);
> > }
> > else
> > {
> > fcback.completed(this.getResult());
> > this.submitTask(null);
> > }
> > }
> >
> > So our guess (maybe wrong) is:
> > - There is any case when the 'updateCapacity' method is being called
> > but without previously calling the 'consumeResponse' method with a
> > non-null entity, so this.capacityToPerform is always 0.
> > - we are still doing something wrong when the 'EntityDetails' is
> > null.
> > Before this we did nothing, so the control was not returning to our
> > app. Now we are calling to 'this.submitTask' and thus returning the
> > control to our app (not sure if completing the FutureCallback is
> > necessary).
> >
> > With the classic blocking model one must close the connection by
> > consuming the response, but in this asynchronous model we don't need
> > to explicitly close the http connections, so we are not able to see
> > where we are leaking these connections.
> >
> > We also uploaded a histogram just with the alive instances from
> > "org.apache.hc" when the pool was exhausted.
> >
> > Any help would be really appreciated.
> >
>
> Joan,
>
> Are you able to reproduce the issue outside PROD environment? I cannot
> glean anything useful from the log snippets you posted.
>
> 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]
>
---------------------------------------------------------------------
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]
