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.interna
> 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]
