You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Joan ventusproxy <jo...@ventusproxy.com> on 2019/05/27 17:33:48 UTC
Response timeout issue
Hello,
�
We are having an issue with HttpClient 5 beta4 / HttpCore 5 Beta7 and socket timeout after switching from asyncClient 1.3.
�
Our requests have a response timeout of 4 seconds. When a response timeout occurs we see this in our log:
2019-05-27 13:05:35 � � � � [62.73.191.161] GetAccomodationAvail � � � � Response timeout � � � � � � � java.net.SocketTimeoutException: 4,000 MILLISECONDS
� � � � � � � at org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTimeoutExceptionFactory.java:50)
� � � � � � � at org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeout(AbstractHttp1StreamDuplexer.java:378)
� � � � � � � at org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout(AbstractHttp1IOEventHandler.java:81)
� � � � � � � at org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(ClientHttp1IOEventHandler.java:39)
� � � � � � � at org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDataChannel.java:188)
� � � � � � � at org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChannel.java:67)
� � � � � � � at org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCoreIOReactor.java:232)
� � � � � � � at org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannels(SingleCoreIOReactor.java:165)
� � � � � � � at org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127)
� � � � � � � at org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:81)
� � � � � � � at org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44)
� � � � � � � at java.lang.Thread.run(Thread.java:748)
�
That’s ok, but when we check our statistics the average time in case of a response timeout is around 1s. For example the above request has been logged with response timeout:
13:05:35.423,748,http.responseTimeout,13:05:36.171
�
But the total time consumed by this request, since it enters to our app (at 13:05:35.423) until the response is returned (at 13:05:36.171), is just 748ms, not more than 4s.
�
After making a lot of tests, the solution came disabling keep alive. Our pool had keep alive enabled (with a value of 20s), disabling keep alive then everything works fine. Response timeouts almost disappear and when one occurs, the logged time is around 4s. If we enable keepalive, the issue occurs again.
�
Our KeepAliveStrategy is the same used in asyncClient (changing to the http5 cclasses). It’s set here:
HttpAsyncClientBuilder hcBuilder = HttpAsyncClients.custom().setKeepAliveStrategy(this.setKeepAliveStrategy(pool.getKeepAliveDuration())) …
�
And the class is:
�
( … )
public TimeValue getKeepAliveDuration(HttpResponse response, HttpContext context)
�
{
� // If we have set a keepalive in our pool, it’s used.
� if (this.keepAliveDuration > 0) return (TimeValue.ofMilliseconds(this.keepAliveDuration));
�
� �// Otherwise search for it in the client response.
� BasicHeaderElementIterator it = new BasicHeaderElementIterator(response.headerIterator(HTTP.CONN_KEEP_ALIVE));
�
� while (it.hasNext())
� �{
� � HeaderElement he = it.next();
� � String value � � � = he.getValue();
�
� � �if ( (value != null) && (he.getName().equalsIgnoreCase("timeout")) )
� � �{
� � � try { return (TimeValue.ofSeconds(Long.parseLong(value))); }
� � � �catch (NumberFormatException ignore) { break; }
� � }
� }
�
� // Otherwise return '100ms'
� return (TimeValue.ofMilliseconds(100L));
}
�
�
It will be difficult to put traces, we are already in production with this client. Just let me know what you need, and we will do our best to collect the info you need.
�
Thanks,
Joan,
�
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Great Oleg!
Issue raised: https://issues.apache.org/jira/browse/HTTPCLIENT-1998
Thanks,
Joan.
-----Original Message-----
From: Oleg Kalnichevski <ol...@apache.org>
Sent: Thursday, June 27, 2019 11:58 AM
To: httpclient-users@hc.apache.org
Subject: Re: Response timeout issue
On Wed, 2019-06-26 at 15:52 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> Regarding this pending issue about response timeout, I could finally
> get traces.
>
> Our response timeout is set to 2,000ms. This is a request that ended
> up with a response timeout:
> 62.xxx.xxx.xxx,23:59:47.606,A,1,A,5,A,4,B,,10.15.15.18:8081,,273,569,
> 0,776,http.responseTimeout,23:59:48.382
>
> If we log this error that means the 'failed' method of our
> AsyncResponseConsumer received an exception that is an instance of a
> 'java.net.SocketTimeoutException'.
>
> Here the trace in our error log:
> 2019-06-25 23:59:48 [62.xxx.xxx.xxx] ventusproxy : ToDi 2.1 :
> xxxxx : GetAccomodationAvail Response timeout
> java.net.SocketTimeoutException: 2,000 MILLISECONDS
> at
> org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTim
> eoutExceptionFactory.java:50)
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeo
> ut(AbstractHttp1StreamDuplexer.java:378)
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout
> (AbstractHttp1IOEventHandler.java:81)
> at
> org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(C
> lientHttp1IOEventHandler.java:39)
> at
> org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDat
> aChannel.java:188)
> at
> org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChan
> nel.java:67)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCo
> reIOReactor.java:232)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannel
> s(SingleCoreIOReactor.java:165)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreI
> OReactor.java:127)
> at
> org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(Abstr
> actSingleCoreIOReactor.java:81)
> at
> org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:
> 44)
> at java.lang.Thread.run(Thread.java:748)
>
> The point is that the total time consumed by the request/response is
> just 776ms (end = 23:59:48.382, start = 23:59:47.606).
>
Hi Juan
I found the culprit. Presently the internal data channel calculates the deadline of read operation based on the last read access. Naturally the last read operation timestamp on a persistent (kept-alive) HTTP connection usually points back at the previous message exchange
https://github.com/apache/httpcomponents-core/blob/master/httpcore5/src/main/java/org/apache/hc/core5/reactor/InternalChannel.java#L64
Please raise a JIRA for this defect.
Oleg
> Finally the http traces belonging to this request/response, where the
> start and end dates match perfectly:
> 23:59:47.606 ex-017E91C3: preparing request execution
> 23:59:47.606 ex-017E91C3: target auth state: UNCHALLENGED
> 23:59:47.606 ex-017E91C3: proxy auth state: UNCHALLENGED
> 23:59:47.606 ex-017E91C3: acquiring connection with route {}->
> http://10.15.15.18:8081
> 23:59:47.606 ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
> 23:59:47.606 ex-017E91C3: endpoint lease request (1,000
> MILLISECONDS) [route: {}->http://10.15.15.18:8081][total kept alive:
> 131; route allocated: 2 of 1500; total allocated: 208 of 1500]
> 23:59:47.606 ex-017E91C3: endpoint leased [route: {}->
> http://10.15.15.18:8081][total kept alive: 130; route allocated: 2 of
> 1500; total allocated: 208 of 1500]
> 23:59:47.606 ex-017E91C3: acquired ep-017E91C2
> 23:59:47.606 ex-017E91C3: acquired endpoint ep-017E91C2
> 23:59:47.606 ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
> 23:59:47.606 ep-017E91C2: start execution ex-017E91C3
> 23:59:47.606 ep-017E91C2: executing exchange ex-017E91C3 over i/o-
> 00970788
> 23:59:47.607 ex-017E91C3: send request POST /ApiServlet.Srv
> HTTP/1.1, entity len 810
> 23:59:47.607 ex-017E91C3: produce request data
> 23:59:47.607 ex-017E91C3: produce request data, len 810 bytes
> 23:59:47.607 ex-017E91C3: end of request data
> 23:59:48.382 ex-017E91C3: execution failed: 2,000 MILLISECONDS
> 23:59:48.382 ex-017E91C3: request failed: 2,000 MILLISECONDS
> 23:59:48.382 ep-017E91C2: close IMMEDIATE
> 23:59:48.382 ep-017E91C2: endpoint closed
> 23:59:48.382 ep-017E91C2: discarding endpoint
> 23:59:48.382 ep-017E91C2: releasing endpoint
> 23:59:48.382 ep-017E91C2: connection released [route: {}->
> http://10.15.15.18:8081][total kept alive: 106; route allocated: 1 of
> 1500; total allocated: 211 of 1500]
>
> Important: if we are not wrong, it seems this is only happening when
> keep alive connections are used. If we disable keep alive from the
> pool, all response timeouts disappear.
>
> Let me know if you need further information.
>
> Thanks,
> Joan.
>
>
>
>
> ---------------------------------------------------------------------
> 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
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2019-06-26 at 15:52 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> Regarding this pending issue about response timeout, I could finally
> get traces.
>
> Our response timeout is set to 2,000ms. This is a request that ended
> up with a response timeout:
> 62.xxx.xxx.xxx,23:59:47.606,A,1,A,5,A,4,B,,10.15.15.18:8081,,273,569,
> 0,776,http.responseTimeout,23:59:48.382
>
> If we log this error that means the 'failed' method of our
> AsyncResponseConsumer received an exception that is an instance of a
> 'java.net.SocketTimeoutException'.
>
> Here the trace in our error log:
> 2019-06-25 23:59:48 [62.xxx.xxx.xxx] ventusproxy : ToDi 2.1 :
> xxxxx : GetAccomodationAvail Response timeout
> java.net.SocketTimeoutException: 2,000 MILLISECONDS
> at
> org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTim
> eoutExceptionFactory.java:50)
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeo
> ut(AbstractHttp1StreamDuplexer.java:378)
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout
> (AbstractHttp1IOEventHandler.java:81)
> at
> org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(C
> lientHttp1IOEventHandler.java:39)
> at
> org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDat
> aChannel.java:188)
> at
> org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChan
> nel.java:67)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCo
> reIOReactor.java:232)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannel
> s(SingleCoreIOReactor.java:165)
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreI
> OReactor.java:127)
> at
> org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(Abstr
> actSingleCoreIOReactor.java:81)
> at
> org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:
> 44)
> at java.lang.Thread.run(Thread.java:748)
>
> The point is that the total time consumed by the request/response is
> just 776ms (end = 23:59:48.382, start = 23:59:47.606).
>
Hi Juan
I found the culprit. Presently the internal data channel calculates the
deadline of read operation based on the last read access. Naturally the
last read operation timestamp on a persistent (kept-alive) HTTP
connection usually points back at the previous message exchange
https://github.com/apache/httpcomponents-core/blob/master/httpcore5/src/main/java/org/apache/hc/core5/reactor/InternalChannel.java#L64
Please raise a JIRA for this defect.
Oleg
> Finally the http traces belonging to this request/response, where the
> start and end dates match perfectly:
> 23:59:47.606 ex-017E91C3: preparing request execution
> 23:59:47.606 ex-017E91C3: target auth state: UNCHALLENGED
> 23:59:47.606 ex-017E91C3: proxy auth state: UNCHALLENGED
> 23:59:47.606 ex-017E91C3: acquiring connection with route {}->
> http://10.15.15.18:8081
> 23:59:47.606 ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
> 23:59:47.606 ex-017E91C3: endpoint lease request (1,000
> MILLISECONDS) [route: {}->http://10.15.15.18:8081][total kept alive:
> 131; route allocated: 2 of 1500; total allocated: 208 of 1500]
> 23:59:47.606 ex-017E91C3: endpoint leased [route: {}->
> http://10.15.15.18:8081][total kept alive: 130; route allocated: 2 of
> 1500; total allocated: 208 of 1500]
> 23:59:47.606 ex-017E91C3: acquired ep-017E91C2
> 23:59:47.606 ex-017E91C3: acquired endpoint ep-017E91C2
> 23:59:47.606 ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
> 23:59:47.606 ep-017E91C2: start execution ex-017E91C3
> 23:59:47.606 ep-017E91C2: executing exchange ex-017E91C3 over i/o-
> 00970788
> 23:59:47.607 ex-017E91C3: send request POST /ApiServlet.Srv
> HTTP/1.1, entity len 810
> 23:59:47.607 ex-017E91C3: produce request data
> 23:59:47.607 ex-017E91C3: produce request data, len 810 bytes
> 23:59:47.607 ex-017E91C3: end of request data
> 23:59:48.382 ex-017E91C3: execution failed: 2,000 MILLISECONDS
> 23:59:48.382 ex-017E91C3: request failed: 2,000 MILLISECONDS
> 23:59:48.382 ep-017E91C2: close IMMEDIATE
> 23:59:48.382 ep-017E91C2: endpoint closed
> 23:59:48.382 ep-017E91C2: discarding endpoint
> 23:59:48.382 ep-017E91C2: releasing endpoint
> 23:59:48.382 ep-017E91C2: connection released [route: {}->
> http://10.15.15.18:8081][total kept alive: 106; route allocated: 1 of
> 1500; total allocated: 211 of 1500]
>
> Important: if we are not wrong, it seems this is only happening when
> keep alive connections are used. If we disable keep alive from the
> pool, all response timeouts disappear.
>
> Let me know if you need further information.
>
> Thanks,
> Joan.
>
>
>
>
> ---------------------------------------------------------------------
> 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
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Hi Oleg,
Regarding this pending issue about response timeout, I could finally get traces.
Our response timeout is set to 2,000ms. This is a request that ended up with a response timeout:
62.xxx.xxx.xxx,23:59:47.606,A,1,A,5,A,4,B,,10.15.15.18:8081,,273,569,0,776,http.responseTimeout,23:59:48.382
If we log this error that means the 'failed' method of our AsyncResponseConsumer received an exception that is an instance of a 'java.net.SocketTimeoutException'.
Here the trace in our error log:
2019-06-25 23:59:48 [62.xxx.xxx.xxx] ventusproxy : ToDi 2.1 : xxxxx : GetAccomodationAvail Response timeout
java.net.SocketTimeoutException: 2,000 MILLISECONDS
at org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTimeoutExceptionFactory.java:50)
at org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeout(AbstractHttp1StreamDuplexer.java:378)
at org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout(AbstractHttp1IOEventHandler.java:81)
at org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(ClientHttp1IOEventHandler.java:39)
at org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDataChannel.java:188)
at org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChannel.java:67)
at org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCoreIOReactor.java:232)
at org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannels(SingleCoreIOReactor.java:165)
at org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127)
at org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:81)
at org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44)
at java.lang.Thread.run(Thread.java:748)
The point is that the total time consumed by the request/response is just 776ms (end = 23:59:48.382, start = 23:59:47.606).
Finally the http traces belonging to this request/response, where the start and end dates match perfectly:
23:59:47.606 ex-017E91C3: preparing request execution
23:59:47.606 ex-017E91C3: target auth state: UNCHALLENGED
23:59:47.606 ex-017E91C3: proxy auth state: UNCHALLENGED
23:59:47.606 ex-017E91C3: acquiring connection with route {}->http://10.15.15.18:8081
23:59:47.606 ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
23:59:47.606 ex-017E91C3: endpoint lease request (1,000 MILLISECONDS) [route: {}->http://10.15.15.18:8081][total kept alive: 131; route allocated: 2 of 1500; total allocated: 208 of 1500]
23:59:47.606 ex-017E91C3: endpoint leased [route: {}->http://10.15.15.18:8081][total kept alive: 130; route allocated: 2 of 1500; total allocated: 208 of 1500]
23:59:47.606 ex-017E91C3: acquired ep-017E91C2
23:59:47.606 ex-017E91C3: acquired endpoint ep-017E91C2
23:59:47.606 ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
23:59:47.606 ep-017E91C2: start execution ex-017E91C3
23:59:47.606 ep-017E91C2: executing exchange ex-017E91C3 over i/o-00970788
23:59:47.607 ex-017E91C3: send request POST /ApiServlet.Srv HTTP/1.1, entity len 810
23:59:47.607 ex-017E91C3: produce request data
23:59:47.607 ex-017E91C3: produce request data, len 810 bytes
23:59:47.607 ex-017E91C3: end of request data
23:59:48.382 ex-017E91C3: execution failed: 2,000 MILLISECONDS
23:59:48.382 ex-017E91C3: request failed: 2,000 MILLISECONDS
23:59:48.382 ep-017E91C2: close IMMEDIATE
23:59:48.382 ep-017E91C2: endpoint closed
23:59:48.382 ep-017E91C2: discarding endpoint
23:59:48.382 ep-017E91C2: releasing endpoint
23:59:48.382 ep-017E91C2: connection released [route: {}->http://10.15.15.18:8081][total kept alive: 106; route allocated: 1 of 1500; total allocated: 211 of 1500]
Important: if we are not wrong, it seems this is only happening when keep alive connections are used. If we disable keep alive from the pool, all response timeouts disappear.
Let me know if you need further information.
Thanks,
Joan.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
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 <ol...@apache.org>
Sent: Thursday, June 6, 2019 3:15 PM
To: HttpClient User Discussion <ht...@hc.apache.org>
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 <ol...@apache.org>
> Sent: Thursday, June 6, 2019 2:27 PM
> To: HttpClient User Discussion <ht...@hc.apache.org>
> 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: 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
>
---------------------------------------------------------------------
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
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> Hi again,
>
> Not sure if we have seen something strange in the current test with
> the keep alive connections. It's just a GET method to get a gif (this
> pool has no keep-alive, that means a 100ms keep-alive). Here the
> complete http log: https://github.com/joanbalaguero/HttpClient.git
> (it's the "http_get.log")
> Previously to this test, this pool received 4 requests today
> 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> requests ended up with a 4xx status code.
>
> This is the first request we sent to this pool using this route.
> Should not keep-alive be 0 and total allocated 1 of 1000?
> -------------------------------------------------------------------
> ------------
> 17:23:02.692 ex-0105B9B8: preparing request execution
> 17:23:02.692 Target auth state: UNCHALLENGED
> 17:23:02.692 Proxy auth state: UNCHALLENGED
> 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692 ep-010526BF: acquired null
> 17:23:02.692 ex-0105B9B8: connection acquired
>
> This is the second:
> ------------------------
> 17:23:02.954 ex-0105B9B9: preparing request execution
> 17:23:02.955 Target auth state: UNCHALLENGED
> 17:23:02.955 Proxy auth state: UNCHALLENGED
> 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 ep-010526C0: acquired null
> 17:23:02.955 ex-0105B9B9: connection acquired
> 17:23:02.976 ep-010526C0: connected i/o-0000434A
> 17:23:02.976 Connected to target
> 17:23:02.976 Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -------------------------
> 17:27:29.996 Shutdown connection pool GRACEFUL
> 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> 17:27:29.996 Connection pool shut down
> 17:27:29.997 Shutdown GRACEFUL
>
> 1st. request after rebooting. Here keep-alive = 0 and total_allocated
> = 1
> -------------------------------------
> 17:27:53.585 ex-0105BA49: preparing request execution
> 17:27:53.585 Target auth state: UNCHALLENGED
> 17:27:53.585 Proxy auth state: UNCHALLENGED
> 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:27:53.585 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 0 of 1000; total allocated: 0 of 1000]
> 17:27:53.585 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 1 of 1000; total allocated: 1 of 1000]
> 17:27:53.585 ep-01052750: acquired null
> 17:27:53.585 ex-0105BA49: connection acquired
> 17:27:53.609 ep-01052750: connected i/o-000043B0
> 17:27:53.609 Connected to target
> 17:27:53.609 Route fully established
>
>
> Thanks,
> Joan.
>
I will study the logs tomorrow and see if I can find anything out
tomorrow.
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Fri, 2019-06-07 at 19:43 +0200, Joan grupoventus wrote:
> Hi,
>
> > Now the current issue. Something similar is happening. After
> > several
> > days of execution, requests start to throw an exception because
> > the
> > container asynchronous timeout is reached. Tracing http, we saw
> > the
> > pool exhausted ... so it's a behavior similar to issue nr. 1.
> > 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]
> >
>
> I could not find it anywhere in the logs that you have provided.
> --> It's here, https://github.com/joanbalaguero/HttpClient , in the
> http.log I uploaded.
>
But the pool is already been completely exhausted at the beginning of
the log
---
Connection request: [route: {}->http://10.15.15.22:8081][total kept
alive: 0; route allocated: 9 of 1500; total allocated: 1500 of 1500]
---
The log contains no information as to what has caused the pool
exhaustion in the first place. It is useless.
> >
> I need to see a log of such 'hanging' message exchnage.
> --> Ok, to do this I need to enable the http traces for days waiting
> the "hang" to happen. But with the log I have enabled now there is a
> significant increase in cpu and io (because the responses are usually
> quite big). Is there any way to enable a kind of logging useful for
> you but avoiding trace the request and response messages?
>
Try disabling I/O session and wire logging. That should massively
reduce the amount of chatter in the log.
---
<Configuration status="WARN" name="XMLConfigTest">
<Appenders>
<Console name="STDOUT">
<!--<PatternLayout pattern="%msg%n%xThrowable"/>-->
<PatternLayout pattern="%d %-5level [%t][%logger]%notEmpty{[%markerSimpleName]} %msg%n%xThrowable"/>
</Console>
</Appenders>
<Loggers>
<Root level="warn">
<AppenderRef ref="STDOUT"/>
</Root>
<Logger name="org.apache.hc.client5" level="debug"/>
<Logger name="org.apache.hc.client5.http.impl" level="debug"/>
<Logger name="org.apache.hc.client5.http.headers" level="debug"/>
<Logger name="org.apache.hc.client5.http.impl.io" level="debug"/>
<Logger name="org.apache.hc.client5.http.impl.nio" level="debug"/>
<Logger name="org.apache.hc.client5.http.impl.cache" level="debug"/>
<Logger name="org.apache.hc.client5.http.wire" level="error"/>
<Logger name="org.apache.hc.client5.http2" level="debug"/>
<Logger name="org.apache.hc.client5.http2.frame" level="debug"/>
<Logger name="org.apache.hc.client5.http2.frame.payload" level="error"/>
<Logger name="org.apache.hc.client5.http2.flow" level="debug"/>
</Loggers>
</Configuration>
---
Oleg
> Joan.
>
>
> > Thanks,
> >
> > Joan.
> >
> > -----Original Message-----
> > From: Oleg Kalnichevski <ol...@apache.org>
> > Sent: Friday, June 7, 2019 4:00 PM
> > To: HttpClient User Discussion <ht...@hc.apache.org>
> > Subject: Re: Response timeout issue
> >
> > On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> > > Hi again,
> > >
> > > Not sure if we have seen something strange in the current test
> > > with
> > > the keep alive connections. It's just a GET method to get a gif
> > > (this pool has no keep-alive, that means a 100ms keep-alive).
> > > Here
> > > the complete http log:
> > > https://github.com/joanbalaguero/HttpClient.git
> > > (it's the "http_get.log")
> >
> > Joan
> >
> > I am confused. I looked at http_get.log and I can see the exact
> > same
> > number of connection lease requests and that of released
> > connections.
> > There are two 253 message exchanges and the same number of
> > connection
> > lease / release operations.
> >
> > I am not seeing any evidence of connections being leaked. I am
> > lost
> > now. What is exactly the issue you are having?
> >
> > Oleg
> >
> >
> > > Previously to this test, this pool received 4 requests today
> > > 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> > > requests ended up with a 4xx status code.
> > >
> > > This is the first request we sent to this pool using this route.
> > > Should not keep-alive be 0 and total allocated 1 of 1000?
> > > ---------------------------------------------------------------
> > > ----
> > > ------------
> > > 17:23:02.692 ex-0105B9B8: preparing request execution
> > > 17:23:02.692 Target auth state: UNCHALLENGED
> > > 17:23:02.692 Proxy auth state: UNCHALLENGED
> > > 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> > > http://andalucia.viajesolympia.com:80
> > > 17:23:02.692 Connection request: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > > allocated: 0 of 1000; total allocated: 1 of 1000]
> > > 17:23:02.692 Connection leased: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > > allocated: 1 of 1000; total allocated: 2 of 1000]
> > > 17:23:02.692 ep-010526BF: acquired null
> > > 17:23:02.692 ex-0105B9B8: connection acquired
> > >
> > > This is the second:
> > > ------------------------
> > > 17:23:02.954 ex-0105B9B9: preparing request execution
> > > 17:23:02.955 Target auth state: UNCHALLENGED
> > > 17:23:02.955 Proxy auth state: UNCHALLENGED
> > > 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> > > http://andalucia.viajesolympia.com:80
> > > 17:23:02.955 Connection request: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> > > allocated: 1 of 1000; total allocated: 2 of 1000]
> > > 17:23:02.955 Connection leased: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > > allocated: 1 of 1000; total allocated: 2 of 1000]
> > > 17:23:02.955 ep-010526C0: acquired null
> > > 17:23:02.955 ex-0105B9B9: connection acquired
> > > 17:23:02.976 ep-010526C0: connected i/o-0000434A
> > > 17:23:02.976 Connected to target
> > > 17:23:02.976 Route fully established
> > >
> > > ( . . . )
> > >
> > > Now a pool reboot
> > > -------------------------
> > > 17:27:29.996 Shutdown connection pool GRACEFUL
> > > 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> > > 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> > > 17:27:29.996 Connection pool shut down
> > > 17:27:29.997 Shutdown GRACEFUL
> > >
> > > 1st. request after rebooting. Here keep-alive = 0 and
> > > total_allocated = 1
> > > -------------------------------------
> > > 17:27:53.585 ex-0105BA49: preparing request execution
> > > 17:27:53.585 Target auth state: UNCHALLENGED
> > > 17:27:53.585 Proxy auth state: UNCHALLENGED
> > > 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> > > http://andalucia.viajesolympia.com:80
> > > 17:27:53.585 Connection request: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > > allocated: 0 of 1000; total allocated: 0 of 1000]
> > > 17:27:53.585 Connection leased: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > > allocated: 1 of 1000; total allocated: 1 of 1000]
> > > 17:27:53.585 ep-01052750: acquired null
> > > 17:27:53.585 ex-0105BA49: connection acquired
> > > 17:27:53.609 ep-01052750: connected i/o-000043B0
> > > 17:27:53.609 Connected to target
> > > 17:27:53.609 Route fully established
> > >
> > >
> > > Thanks,
> > > Joan.
> > >
> > >
> > >
> > > -----------------------------------------------------------------
> > > ----
> > > 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
> >
> >
> >
> >
> > -----------------------------------------------------------------
> > ----
> > 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
>
>
>
>
> ---------------------------------------------------------------------
> 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
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Hi,
> Now the current issue. Something similar is happening. After several
> days of execution, requests start to throw an exception because the
> container asynchronous timeout is reached. Tracing http, we saw the
> pool exhausted ... so it's a behavior similar to issue nr. 1.
> 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]
>
I could not find it anywhere in the logs that you have provided.
--> It's here, https://github.com/joanbalaguero/HttpClient , in the http.log I uploaded.
> That's why I asked you if it's possible the 'updateCapacity' method to
> be called but without previously calling the 'consumeResponse'
> method with a non-null entity.
No, I do not think it is possible.
--> Ok.
> In this case the variable 'this.capacityToPerform' we use to extend
> the buffer will be 0 and we will be again in the first issue.
>
> So I think the pool exhausted is a consequence the thread that is
> managing the 'AsyncResponseConsumer' is not ending for some reason
> (like in the first issue).
>
Again, I need to see a _complete_ wire / context log of such message exchange.
Is there something else (like updating the capacity) I have to take
> into account in the ' AsyncResponseConsumer ' to avoid hanging the
> execution?
>
I need to see a log of such 'hanging' message exchnage.
--> Ok, to do this I need to enable the http traces for days waiting the "hang" to happen. But with the log I have enabled now there is a significant increase in cpu and io (because the responses are usually quite big). Is there any way to enable a kind of logging useful for you but avoiding trace the request and response messages?
Joan.
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Oleg Kalnichevski <ol...@apache.org>
> Sent: Friday, June 7, 2019 4:00 PM
> To: HttpClient User Discussion <ht...@hc.apache.org>
> Subject: Re: Response timeout issue
>
> On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> > Hi again,
> >
> > Not sure if we have seen something strange in the current test with
> > the keep alive connections. It's just a GET method to get a gif
> > (this pool has no keep-alive, that means a 100ms keep-alive). Here
> > the complete http log:
> > https://github.com/joanbalaguero/HttpClient.git
> > (it's the "http_get.log")
>
> Joan
>
> I am confused. I looked at http_get.log and I can see the exact same
> number of connection lease requests and that of released connections.
> There are two 253 message exchanges and the same number of connection
> lease / release operations.
>
> I am not seeing any evidence of connections being leaked. I am lost
> now. What is exactly the issue you are having?
>
> Oleg
>
>
> > Previously to this test, this pool received 4 requests today
> > 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> > requests ended up with a 4xx status code.
> >
> > This is the first request we sent to this pool using this route.
> > Should not keep-alive be 0 and total allocated 1 of 1000?
> > -------------------------------------------------------------------
> > ------------
> > 17:23:02.692 ex-0105B9B8: preparing request execution
> > 17:23:02.692 Target auth state: UNCHALLENGED
> > 17:23:02.692 Proxy auth state: UNCHALLENGED
> > 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.692 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 0 of 1000; total allocated: 1 of 1000]
> > 17:23:02.692 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.692 ep-010526BF: acquired null
> > 17:23:02.692 ex-0105B9B8: connection acquired
> >
> > This is the second:
> > ------------------------
> > 17:23:02.954 ex-0105B9B9: preparing request execution
> > 17:23:02.955 Target auth state: UNCHALLENGED
> > 17:23:02.955 Proxy auth state: UNCHALLENGED
> > 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.955 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.955 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.955 ep-010526C0: acquired null
> > 17:23:02.955 ex-0105B9B9: connection acquired
> > 17:23:02.976 ep-010526C0: connected i/o-0000434A
> > 17:23:02.976 Connected to target
> > 17:23:02.976 Route fully established
> >
> > ( . . . )
> >
> > Now a pool reboot
> > -------------------------
> > 17:27:29.996 Shutdown connection pool GRACEFUL
> > 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> > 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> > 17:27:29.996 Connection pool shut down
> > 17:27:29.997 Shutdown GRACEFUL
> >
> > 1st. request after rebooting. Here keep-alive = 0 and
> > total_allocated = 1
> > -------------------------------------
> > 17:27:53.585 ex-0105BA49: preparing request execution
> > 17:27:53.585 Target auth state: UNCHALLENGED
> > 17:27:53.585 Proxy auth state: UNCHALLENGED
> > 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:27:53.585 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > allocated: 0 of 1000; total allocated: 0 of 1000]
> > 17:27:53.585 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > allocated: 1 of 1000; total allocated: 1 of 1000]
> > 17:27:53.585 ep-01052750: acquired null
> > 17:27:53.585 ex-0105BA49: connection acquired
> > 17:27:53.609 ep-01052750: connected i/o-000043B0
> > 17:27:53.609 Connected to target
> > 17:27:53.609 Route fully established
> >
> >
> > Thanks,
> > Joan.
> >
> >
> >
> > -----------------------------------------------------------------
> > ----
> > 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
>
>
>
>
> ---------------------------------------------------------------------
> 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
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Fri, 2019-06-07 at 19:06 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> Ok, let me explain a bit more. This comes from a previous mistake in
> our AsyncResponseConsumer.
>
> Some weeks ago I wrote you an email because we were having an issue
> where threads got stuck, streamEnd and failed methods were never
> called, and the thread was released when the container asynchronous
> timeout was reached. As you notice, the issue was in our
> updateCapacity method because we were doing nothing on it, instead of
> extending the capacity of the buffer. This was fixed.
>
> Now the current issue. Something similar is happening. After several
> days of execution, requests start to throw an exception because the
> container asynchronous timeout is reached. Tracing http, we saw the
> pool exhausted ... so it's a behavior similar to issue nr. 1.
> 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]
>
I could not find it anywhere in the logs that you have provided.
> That's why I asked you if it's possible the 'updateCapacity' method
> to be called but without previously calling the 'consumeResponse'
> method with a non-null entity.
No, I do not think it is possible.
> In this case the variable 'this.capacityToPerform' we use to extend
> the buffer will be 0 and we will be again in the first issue.
>
> So I think the pool exhausted is a consequence the thread that is
> managing the 'AsyncResponseConsumer' is not ending for some reason
> (like in the first issue).
>
Again, I need to see a _complete_ wire / context log of such message
exchange.
Is there something else (like updating the capacity) I have to take
> into account in the ' AsyncResponseConsumer ' to avoid hanging the
> execution?
>
I need to see a log of such 'hanging' message exchnage.
Oleg
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Oleg Kalnichevski <ol...@apache.org>
> Sent: Friday, June 7, 2019 4:00 PM
> To: HttpClient User Discussion <ht...@hc.apache.org>
> Subject: Re: Response timeout issue
>
> On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> > Hi again,
> >
> > Not sure if we have seen something strange in the current test
> > with
> > the keep alive connections. It's just a GET method to get a gif
> > (this
> > pool has no keep-alive, that means a 100ms keep-alive). Here the
> > complete http log: https://github.com/joanbalaguero/HttpClient.git
> > (it's the "http_get.log")
>
> Joan
>
> I am confused. I looked at http_get.log and I can see the exact same
> number of connection lease requests and that of released connections.
> There are two 253 message exchanges and the same number of connection
> lease / release operations.
>
> I am not seeing any evidence of connections being leaked. I am lost
> now. What is exactly the issue you are having?
>
> Oleg
>
>
> > Previously to this test, this pool received 4 requests today
> > 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> > requests ended up with a 4xx status code.
> >
> > This is the first request we sent to this pool using this route.
> > Should not keep-alive be 0 and total allocated 1 of 1000?
> > -------------------------------------------------------------------
> > ------------
> > 17:23:02.692 ex-0105B9B8: preparing request execution
> > 17:23:02.692 Target auth state: UNCHALLENGED
> > 17:23:02.692 Proxy auth state: UNCHALLENGED
> > 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.692 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 0 of 1000; total allocated: 1 of 1000]
> > 17:23:02.692 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.692 ep-010526BF: acquired null
> > 17:23:02.692 ex-0105B9B8: connection acquired
> >
> > This is the second:
> > ------------------------
> > 17:23:02.954 ex-0105B9B9: preparing request execution
> > 17:23:02.955 Target auth state: UNCHALLENGED
> > 17:23:02.955 Proxy auth state: UNCHALLENGED
> > 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.955 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.955 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.955 ep-010526C0: acquired null
> > 17:23:02.955 ex-0105B9B9: connection acquired
> > 17:23:02.976 ep-010526C0: connected i/o-0000434A
> > 17:23:02.976 Connected to target
> > 17:23:02.976 Route fully established
> >
> > ( . . . )
> >
> > Now a pool reboot
> > -------------------------
> > 17:27:29.996 Shutdown connection pool GRACEFUL
> > 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> > 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> > 17:27:29.996 Connection pool shut down
> > 17:27:29.997 Shutdown GRACEFUL
> >
> > 1st. request after rebooting. Here keep-alive = 0 and
> > total_allocated
> > = 1
> > -------------------------------------
> > 17:27:53.585 ex-0105BA49: preparing request execution
> > 17:27:53.585 Target auth state: UNCHALLENGED
> > 17:27:53.585 Proxy auth state: UNCHALLENGED
> > 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:27:53.585 Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > allocated: 0 of 1000; total allocated: 0 of 1000]
> > 17:27:53.585 Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> > allocated: 1 of 1000; total allocated: 1 of 1000]
> > 17:27:53.585 ep-01052750: acquired null
> > 17:27:53.585 ex-0105BA49: connection acquired
> > 17:27:53.609 ep-01052750: connected i/o-000043B0
> > 17:27:53.609 Connected to target
> > 17:27:53.609 Route fully established
> >
> >
> > Thanks,
> > Joan.
> >
> >
> >
> > -----------------------------------------------------------------
> > ----
> > 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
>
>
>
>
> ---------------------------------------------------------------------
> 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
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Hi Oleg,
Ok, let me explain a bit more. This comes from a previous mistake in our AsyncResponseConsumer.
Some weeks ago I wrote you an email because we were having an issue where threads got stuck, streamEnd and failed methods were never called, and the thread was released when the container asynchronous timeout was reached. As you notice, the issue was in our updateCapacity method because we were doing nothing on it, instead of extending the capacity of the buffer. This was fixed.
Now the current issue. Something similar is happening. After several days of execution, requests start to throw an exception because the container asynchronous timeout is reached. Tracing http, we saw the pool exhausted ... so it's a behavior similar to issue nr. 1.
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]
That's why I asked you if it's possible the 'updateCapacity' method to be called but without previously calling the 'consumeResponse' method with a non-null entity. In this case the variable 'this.capacityToPerform' we use to extend the buffer will be 0 and we will be again in the first issue.
So I think the pool exhausted is a consequence the thread that is managing the 'AsyncResponseConsumer' is not ending for some reason (like in the first issue).
Is there something else (like updating the capacity) I have to take into account in the ' AsyncResponseConsumer ' to avoid hanging the execution?
Thanks,
Joan.
-----Original Message-----
From: Oleg Kalnichevski <ol...@apache.org>
Sent: Friday, June 7, 2019 4:00 PM
To: HttpClient User Discussion <ht...@hc.apache.org>
Subject: Re: Response timeout issue
On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> Hi again,
>
> Not sure if we have seen something strange in the current test with
> the keep alive connections. It's just a GET method to get a gif (this
> pool has no keep-alive, that means a 100ms keep-alive). Here the
> complete http log: https://github.com/joanbalaguero/HttpClient.git
> (it's the "http_get.log")
Joan
I am confused. I looked at http_get.log and I can see the exact same number of connection lease requests and that of released connections.
There are two 253 message exchanges and the same number of connection lease / release operations.
I am not seeing any evidence of connections being leaked. I am lost now. What is exactly the issue you are having?
Oleg
> Previously to this test, this pool received 4 requests today
> 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> requests ended up with a 4xx status code.
>
> This is the first request we sent to this pool using this route.
> Should not keep-alive be 0 and total allocated 1 of 1000?
> -------------------------------------------------------------------
> ------------
> 17:23:02.692 ex-0105B9B8: preparing request execution
> 17:23:02.692 Target auth state: UNCHALLENGED
> 17:23:02.692 Proxy auth state: UNCHALLENGED
> 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692 ep-010526BF: acquired null
> 17:23:02.692 ex-0105B9B8: connection acquired
>
> This is the second:
> ------------------------
> 17:23:02.954 ex-0105B9B9: preparing request execution
> 17:23:02.955 Target auth state: UNCHALLENGED
> 17:23:02.955 Proxy auth state: UNCHALLENGED
> 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 ep-010526C0: acquired null
> 17:23:02.955 ex-0105B9B9: connection acquired
> 17:23:02.976 ep-010526C0: connected i/o-0000434A
> 17:23:02.976 Connected to target
> 17:23:02.976 Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -------------------------
> 17:27:29.996 Shutdown connection pool GRACEFUL
> 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> 17:27:29.996 Connection pool shut down
> 17:27:29.997 Shutdown GRACEFUL
>
> 1st. request after rebooting. Here keep-alive = 0 and total_allocated
> = 1
> -------------------------------------
> 17:27:53.585 ex-0105BA49: preparing request execution
> 17:27:53.585 Target auth state: UNCHALLENGED
> 17:27:53.585 Proxy auth state: UNCHALLENGED
> 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:27:53.585 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 0 of 1000; total allocated: 0 of 1000]
> 17:27:53.585 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 1 of 1000; total allocated: 1 of 1000]
> 17:27:53.585 ep-01052750: acquired null
> 17:27:53.585 ex-0105BA49: connection acquired
> 17:27:53.609 ep-01052750: connected i/o-000043B0
> 17:27:53.609 Connected to target
> 17:27:53.609 Route fully established
>
>
> Thanks,
> Joan.
>
>
>
> ---------------------------------------------------------------------
> 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
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Thu, 2019-06-06 at 18:56 +0200, Joan grupoventus wrote:
> Hi again,
>
> Not sure if we have seen something strange in the current test with
> the keep alive connections. It's just a GET method to get a gif (this
> pool has no keep-alive, that means a 100ms keep-alive). Here the
> complete http log: https://github.com/joanbalaguero/HttpClient.git
> (it's the "http_get.log")
Joan
I am confused. I looked at http_get.log and I can see the exact same
number of connection lease requests and that of released connections.
There are two 253 message exchanges and the same number of connection
lease / release operations.
I am not seeing any evidence of connections being leaked. I am lost
now. What is exactly the issue you are having?
Oleg
> Previously to this test, this pool received 4 requests today
> 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4
> requests ended up with a 4xx status code.
>
> This is the first request we sent to this pool using this route.
> Should not keep-alive be 0 and total allocated 1 of 1000?
> -------------------------------------------------------------------
> ------------
> 17:23:02.692 ex-0105B9B8: preparing request execution
> 17:23:02.692 Target auth state: UNCHALLENGED
> 17:23:02.692 Proxy auth state: UNCHALLENGED
> 17:23:02.692 ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692 ep-010526BF: acquired null
> 17:23:02.692 ex-0105B9B8: connection acquired
>
> This is the second:
> ------------------------
> 17:23:02.954 ex-0105B9B9: preparing request execution
> 17:23:02.955 Target auth state: UNCHALLENGED
> 17:23:02.955 Proxy auth state: UNCHALLENGED
> 17:23:02.955 ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955 ep-010526C0: acquired null
> 17:23:02.955 ex-0105B9B9: connection acquired
> 17:23:02.976 ep-010526C0: connected i/o-0000434A
> 17:23:02.976 Connected to target
> 17:23:02.976 Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -------------------------
> 17:27:29.996 Shutdown connection pool GRACEFUL
> 17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
> 17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
> 17:27:29.996 Connection pool shut down
> 17:27:29.997 Shutdown GRACEFUL
>
> 1st. request after rebooting. Here keep-alive = 0 and total_allocated
> = 1
> -------------------------------------
> 17:27:53.585 ex-0105BA49: preparing request execution
> 17:27:53.585 Target auth state: UNCHALLENGED
> 17:27:53.585 Proxy auth state: UNCHALLENGED
> 17:27:53.585 ex-0105BA49: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:27:53.585 Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 0 of 1000; total allocated: 0 of 1000]
> 17:27:53.585 Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 1 of 1000; total allocated: 1 of 1000]
> 17:27:53.585 ep-01052750: acquired null
> 17:27:53.585 ex-0105BA49: connection acquired
> 17:27:53.609 ep-01052750: connected i/o-000043B0
> 17:27:53.609 Connected to target
> 17:27:53.609 Route fully established
>
>
> Thanks,
> Joan.
>
>
>
> ---------------------------------------------------------------------
> 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
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Hi again,
Not sure if we have seen something strange in the current test with the keep alive connections. It's just a GET method to get a gif (this pool has no keep-alive, that means a 100ms keep-alive). Here the complete http log: https://github.com/joanbalaguero/HttpClient.git (it's the "http_get.log")
Previously to this test, this pool received 4 requests today 06/06/2019 around 11:15:00 (so 6 hours before the test), these 4 requests ended up with a 4xx status code.
This is the first request we sent to this pool using this route. Should not keep-alive be 0 and total allocated 1 of 1000?
-------------------------------------------------------------------------------
17:23:02.692 ex-0105B9B8: preparing request execution
17:23:02.692 Target auth state: UNCHALLENGED
17:23:02.692 Proxy auth state: UNCHALLENGED
17:23:02.692 ex-0105B9B8: acquiring connection with route {}->http://andalucia.viajesolympia.com:80
17:23:02.692 Connection request: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route allocated: 0 of 1000; total allocated: 1 of 1000]
17:23:02.692 Connection leased: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.692 ep-010526BF: acquired null
17:23:02.692 ex-0105B9B8: connection acquired
This is the second:
------------------------
17:23:02.954 ex-0105B9B9: preparing request execution
17:23:02.955 Target auth state: UNCHALLENGED
17:23:02.955 Proxy auth state: UNCHALLENGED
17:23:02.955 ex-0105B9B9: acquiring connection with route {}->http://andalucia.viajesolympia.com:80
17:23:02.955 Connection request: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 2; route allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.955 Connection leased: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.955 ep-010526C0: acquired null
17:23:02.955 ex-0105B9B9: connection acquired
17:23:02.976 ep-010526C0: connected i/o-0000434A
17:23:02.976 Connected to target
17:23:02.976 Route fully established
( . . . )
Now a pool reboot
-------------------------
17:27:29.996 Shutdown connection pool GRACEFUL
17:27:29.996 i/o-000043AF: Shutdown connection GRACEFUL
17:27:29.996 i/o-00002D9A: Shutdown connection GRACEFUL
17:27:29.996 Connection pool shut down
17:27:29.997 Shutdown GRACEFUL
1st. request after rebooting. Here keep-alive = 0 and total_allocated = 1
-------------------------------------
17:27:53.585 ex-0105BA49: preparing request execution
17:27:53.585 Target auth state: UNCHALLENGED
17:27:53.585 Proxy auth state: UNCHALLENGED
17:27:53.585 ex-0105BA49: acquiring connection with route {}->http://andalucia.viajesolympia.com:80
17:27:53.585 Connection request: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 0; route allocated: 0 of 1000; total allocated: 0 of 1000]
17:27:53.585 Connection leased: [route: {}->http://andalucia.viajesolympia.com:80][total kept alive: 0; route allocated: 1 of 1000; total allocated: 1 of 1000]
17:27:53.585 ep-01052750: acquired null
17:27:53.585 ex-0105BA49: connection acquired
17:27:53.609 ep-01052750: connected i/o-000043B0
17:27:53.609 Connected to target
17:27:53.609 Route fully established
Thanks,
Joan.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
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 <ol...@apache.org>
> Sent: Thursday, June 6, 2019 2:27 PM
> To: HttpClient User Discussion <ht...@hc.apache.org>
> 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: 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
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
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?
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 <ol...@apache.org>
Sent: Thursday, June 6, 2019 2:27 PM
To: HttpClient User Discussion <ht...@hc.apache.org>
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.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: 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
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
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: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
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.internal.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.
Thanks,
Joan.
-----Original Message-----
From: Oleg Kalnichevski <ol...@apache.org>
Sent: Thursday, May 30, 2019 11:40 AM
To: HttpClient User Discussion <ht...@hc.apache.org>
Subject: Re: Response timeout issue
On Wed, 2019-05-29 at 18:56 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> I'm still trying to manage this with our client ... we are not able to
> reproduce it in our environment.
>
> In the meantime we have come across with another issue. I explain it
> just to know if you are aware that someone else has experienced
> something similar with HttpClient5. After 7 days working correctly,
> suddenly the http pool becomes exhausted and all the asynchronous
> tasks hang until the container asynchronous timeout is reached. What
> we see is the request is sent to the backend but no response is
> obtained, and finally the asynchronous task finishes due to the
> container timeout after 150s ... no response timeout is thrown (it's
> set at 90s).
>
Hi Joan
No, I am not aware of anyone else experiencing similar issues.
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2019-05-29 at 18:56 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> I'm still trying to manage this with our client ... we are not able
> to reproduce it in our environment.
>
> In the meantime we have come across with another issue. I explain it
> just to know if you are aware that someone else has experienced
> something similar with HttpClient5. After 7 days working correctly,
> suddenly the http pool becomes exhausted and all the asynchronous
> tasks hang until the container asynchronous timeout is reached. What
> we see is the request is sent to the backend but no response is
> obtained, and finally the asynchronous task finishes due to the
> container timeout after 150s ... no response timeout is thrown (it's
> set at 90s).
>
Hi Joan
No, I am not aware of anyone else experiencing similar issues.
Oleg
> Our client restarted Tomcat, we could only get a thread stack ... not
> sure if this can be of any utility but I could attach it ...
>
> Thanks,
>
> Joan.
>
>
> -----Original Message-----
> From: Oleg Kalnichevski <ol...@apache.org>
> Sent: Monday, May 27, 2019 11:10 PM
> To: HttpClient User Discussion <ht...@hc.apache.org>
> Subject: Re: Response timeout issue
>
> Joan
>
> Please raise a JIRA for this issue and attach a wire log with time
> stamps of a _complete_ message exchange demonstrating the incorrect
> behavior.
>
> I will review connection management code tomorrow.
>
> Oleg
>
>
> On Mon, 2019-05-27 at 19:33 +0200, Joan ventusproxy wrote:
> > Hello,
> >
> >
> >
> > We are having an issue with HttpClient 5 beta4 / HttpCore 5 Beta7
> > and
> > socket timeout after switching from asyncClient 1.3.
> >
> >
> >
> > Our requests have a response timeout of 4 seconds. When a response
> > timeout occurs we see this in our log:
> >
> > 2019-05-27 13:05:35 [62.73.191.161]
> > GetAccomodationAvail
> > Response timeout java.net.SocketTimeoutException:
> > 4,000 MILLISECONDS
> >
> > at
> > org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketT
> > im
> > eoutExceptionFactory.java:50)
> >
> > at
> > org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTim
> > eo
> > ut(AbstractHttp1StreamDuplexer.java:378)
> >
> > at
> > org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeo
> > ut
> > (AbstractHttp1IOEventHandler.java:81)
> >
> > at
> > org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout
> > (C
> > lientHttp1IOEventHandler.java:39)
> >
> > at
> > org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalD
> > at
> > aChannel.java:188)
> >
> > at
> > org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalCh
> > an
> > nel.java:67)
> >
> > at
> > org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(Single
> > Co
> > reIOReactor.java:232)
> >
> > at
> > org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChann
> > el
> > s(SingleCoreIOReactor.java:165)
> >
> > at
> > org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCor
> > eI
> > OReactor.java:127)
> >
> > at
> > org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(Abs
> > tr
> > actSingleCoreIOReactor.java:81)
> >
> > at
> > org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.jav
> > a:
> > 44)
> >
> > at java.lang.Thread.run(Thread.java:748)
> >
> >
> >
> > That’s ok, but when we check our statistics the average time in
> > case
> > of a response timeout is around 1s. For example the above request
> > has
> > been logged with response timeout:
> >
> > 13:05:35.423,748,http.responseTimeout,13:05:36.171
> >
> >
> >
> > But the total time consumed by this request, since it enters to
> > our
> > app (at 13:05:35.423) until the response is returned (at
> > 13:05:36.171), is just 748ms, not more than 4s.
> >
> >
> >
> > After making a lot of tests, the solution came disabling keep
> > alive.
> > Our pool had keep alive enabled (with a value of 20s), disabling
> > keep
> > alive then everything works fine. Response timeouts almost
> > disappear
> > and when one occurs, the logged time is around 4s. If we enable
> > keepalive, the issue occurs again.
> >
> >
> >
> > Our KeepAliveStrategy is the same used in asyncClient (changing to
> > the
> > http5 cclasses). It’s set here:
> >
> > HttpAsyncClientBuilder hcBuilder =
> > HttpAsyncClients.custom().setKeepAliveStrategy(this.setKeepAliveStr
> > at
> > egy(pool.getKeepAliveDuration())) …
> >
> >
> >
> > And the class is:
> >
> >
> >
> > ( … )
> >
> > public TimeValue getKeepAliveDuration(HttpResponse response,
> > HttpContext context)
> >
> >
> >
> > {
> >
> > // If we have set a keepalive in our pool, it’s used.
> >
> > if (this.keepAliveDuration > 0) return
> > (TimeValue.ofMilliseconds(this.keepAliveDuration));
> >
> >
> >
> > // Otherwise search for it in the client response.
> >
> > BasicHeaderElementIterator it = new
> > BasicHeaderElementIterator(response.headerIterator(HTTP.CONN_KEEP_A
> > LI
> > VE));
> >
> >
> >
> > while (it.hasNext())
> >
> > {
> >
> > HeaderElement he = it.next();
> >
> > String value = he.getValue();
> >
> >
> >
> > if ( (value != null) &&
> > (he.getName().equalsIgnoreCase("timeout")) )
> >
> > {
> >
> > try { return (TimeValue.ofSeconds(Long.parseLong(value))); }
> >
> > catch (NumberFormatException ignore) { break; }
> >
> > }
> >
> > }
> >
> >
> >
> > // Otherwise return '100ms'
> >
> > return (TimeValue.ofMilliseconds(100L));
> >
> > }
> >
> >
> >
> >
> >
> > It will be difficult to put traces, we are already in production
> > with
> > this client. Just let me know what you need, and we will do our
> > best
> > to collect the info you need.
> >
> >
> >
> > Thanks,
> >
> > Joan,
> >
> >
> >
>
>
> ---------------------------------------------------------------------
> 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
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
RE: Response timeout issue
Posted by Joan grupoventus <jo...@grupoventus.com>.
Hi Oleg,
I'm still trying to manage this with our client ... we are not able to reproduce it in our environment.
In the meantime we have come across with another issue. I explain it just to know if you are aware that someone else has experienced something similar with HttpClient5. After 7 days working correctly, suddenly the http pool becomes exhausted and all the asynchronous tasks hang until the container asynchronous timeout is reached. What we see is the request is sent to the backend but no response is obtained, and finally the asynchronous task finishes due to the container timeout after 150s ... no response timeout is thrown (it's set at 90s).
Our client restarted Tomcat, we could only get a thread stack ... not sure if this can be of any utility but I could attach it ...
Thanks,
Joan.
-----Original Message-----
From: Oleg Kalnichevski <ol...@apache.org>
Sent: Monday, May 27, 2019 11:10 PM
To: HttpClient User Discussion <ht...@hc.apache.org>
Subject: Re: Response timeout issue
Joan
Please raise a JIRA for this issue and attach a wire log with time stamps of a _complete_ message exchange demonstrating the incorrect behavior.
I will review connection management code tomorrow.
Oleg
On Mon, 2019-05-27 at 19:33 +0200, Joan ventusproxy wrote:
> Hello,
>
>
>
> We are having an issue with HttpClient 5 beta4 / HttpCore 5 Beta7 and
> socket timeout after switching from asyncClient 1.3.
>
>
>
> Our requests have a response timeout of 4 seconds. When a response
> timeout occurs we see this in our log:
>
> 2019-05-27 13:05:35 [62.73.191.161] GetAccomodationAvail
> Response timeout java.net.SocketTimeoutException:
> 4,000 MILLISECONDS
>
> at
> org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTim
> eoutExceptionFactory.java:50)
>
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeo
> ut(AbstractHttp1StreamDuplexer.java:378)
>
> at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout
> (AbstractHttp1IOEventHandler.java:81)
>
> at
> org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(C
> lientHttp1IOEventHandler.java:39)
>
> at
> org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDat
> aChannel.java:188)
>
> at
> org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChan
> nel.java:67)
>
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCo
> reIOReactor.java:232)
>
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannel
> s(SingleCoreIOReactor.java:165)
>
> at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreI
> OReactor.java:127)
>
> at
> org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(Abstr
> actSingleCoreIOReactor.java:81)
>
> at
> org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:
> 44)
>
> at java.lang.Thread.run(Thread.java:748)
>
>
>
> That’s ok, but when we check our statistics the average time in case
> of a response timeout is around 1s. For example the above request has
> been logged with response timeout:
>
> 13:05:35.423,748,http.responseTimeout,13:05:36.171
>
>
>
> But the total time consumed by this request, since it enters to our
> app (at 13:05:35.423) until the response is returned (at
> 13:05:36.171), is just 748ms, not more than 4s.
>
>
>
> After making a lot of tests, the solution came disabling keep alive.
> Our pool had keep alive enabled (with a value of 20s), disabling keep
> alive then everything works fine. Response timeouts almost disappear
> and when one occurs, the logged time is around 4s. If we enable
> keepalive, the issue occurs again.
>
>
>
> Our KeepAliveStrategy is the same used in asyncClient (changing to the
> http5 cclasses). It’s set here:
>
> HttpAsyncClientBuilder hcBuilder =
> HttpAsyncClients.custom().setKeepAliveStrategy(this.setKeepAliveStrat
> egy(pool.getKeepAliveDuration())) …
>
>
>
> And the class is:
>
>
>
> ( … )
>
> public TimeValue getKeepAliveDuration(HttpResponse response,
> HttpContext context)
>
>
>
> {
>
> // If we have set a keepalive in our pool, it’s used.
>
> if (this.keepAliveDuration > 0) return
> (TimeValue.ofMilliseconds(this.keepAliveDuration));
>
>
>
> // Otherwise search for it in the client response.
>
> BasicHeaderElementIterator it = new
> BasicHeaderElementIterator(response.headerIterator(HTTP.CONN_KEEP_ALI
> VE));
>
>
>
> while (it.hasNext())
>
> {
>
> HeaderElement he = it.next();
>
> String value = he.getValue();
>
>
>
> if ( (value != null) &&
> (he.getName().equalsIgnoreCase("timeout")) )
>
> {
>
> try { return (TimeValue.ofSeconds(Long.parseLong(value))); }
>
> catch (NumberFormatException ignore) { break; }
>
> }
>
> }
>
>
>
> // Otherwise return '100ms'
>
> return (TimeValue.ofMilliseconds(100L));
>
> }
>
>
>
>
>
> It will be difficult to put traces, we are already in production with
> this client. Just let me know what you need, and we will do our best
> to collect the info you need.
>
>
>
> Thanks,
>
> Joan,
>
>
>
---------------------------------------------------------------------
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
Re: Response timeout issue
Posted by Oleg Kalnichevski <ol...@apache.org>.
Joan
Please raise a JIRA for this issue and attach a wire log with time
stamps of a _complete_ message exchange demonstrating the incorrect
behavior.
I will review connection management code tomorrow.
Oleg
On Mon, 2019-05-27 at 19:33 +0200, Joan ventusproxy wrote:
> Hello,
>
> �
>
> We are having an issue with HttpClient 5 beta4 / HttpCore 5 Beta7 and
> socket timeout after switching from asyncClient 1.3.
>
> �
>
> Our requests have a response timeout of 4 seconds. When a response
> timeout occurs we see this in our log:
>
> 2019-05-27 13:05:35 � � � � [62.73.191.161] GetAccomodationAvail � �
> � � Response timeout � � � � � � � java.net.SocketTimeoutException:
> 4,000 MILLISECONDS
>
> � � � � � � � at
> org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTim
> eoutExceptionFactory.java:50)
>
> � � � � � � � at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeo
> ut(AbstractHttp1StreamDuplexer.java:378)
>
> � � � � � � � at
> org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout
> (AbstractHttp1IOEventHandler.java:81)
>
> � � � � � � � at
> org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler.timeout(C
> lientHttp1IOEventHandler.java:39)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDat
> aChannel.java:188)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChan
> nel.java:67)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCo
> reIOReactor.java:232)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannel
> s(SingleCoreIOReactor.java:165)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreI
> OReactor.java:127)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(Abstr
> actSingleCoreIOReactor.java:81)
>
> � � � � � � � at
> org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:
> 44)
>
> � � � � � � � at java.lang.Thread.run(Thread.java:748)
>
> �
>
> That’s ok, but when we check our statistics the average time in case
> of a response timeout is around 1s. For example the above request has
> been logged with response timeout:
>
> 13:05:35.423,748,http.responseTimeout,13:05:36.171
>
> �
>
> But the total time consumed by this request, since it enters to our
> app (at 13:05:35.423) until the response is returned (at
> 13:05:36.171), is just 748ms, not more than 4s.
>
> �
>
> After making a lot of tests, the solution came disabling keep alive.
> Our pool had keep alive enabled (with a value of 20s), disabling keep
> alive then everything works fine. Response timeouts almost disappear
> and when one occurs, the logged time is around 4s. If we enable
> keepalive, the issue occurs again.
>
> �
>
> Our KeepAliveStrategy is the same used in asyncClient (changing to
> the http5 cclasses). It’s set here:
>
> HttpAsyncClientBuilder hcBuilder =
> HttpAsyncClients.custom().setKeepAliveStrategy(this.setKeepAliveStrat
> egy(pool.getKeepAliveDuration())) …
>
> �
>
> And the class is:
>
> �
>
> ( … )
>
> public TimeValue getKeepAliveDuration(HttpResponse response,
> HttpContext context)
>
> �
>
> {
>
> � // If we have set a keepalive in our pool, it’s used.
>
> � if (this.keepAliveDuration > 0) return
> (TimeValue.ofMilliseconds(this.keepAliveDuration));
>
> �
>
> � �// Otherwise search for it in the client response.
>
> � BasicHeaderElementIterator it = new
> BasicHeaderElementIterator(response.headerIterator(HTTP.CONN_KEEP_ALI
> VE));
>
> �
>
> � while (it.hasNext())
>
> � �{
>
> � � HeaderElement he = it.next();
>
> � � String value � � � = he.getValue();
>
> �
>
> � � �if ( (value != null) &&
> (he.getName().equalsIgnoreCase("timeout")) )
>
> � � �{
>
> � � � try { return (TimeValue.ofSeconds(Long.parseLong(value))); }
>
> � � � �catch (NumberFormatException ignore) { break; }
>
> � � }
>
> � }
>
> �
>
> � // Otherwise return '100ms'
>
> � return (TimeValue.ofMilliseconds(100L));
>
> }
>
> �
>
> �
>
> It will be difficult to put traces, we are already in production with
> this client. Just let me know what you need, and we will do our best
> to collect the info you need.
>
> �
>
> Thanks,
>
> Joan,
>
> �
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org