RE: Response timeout issue
Great Oleg!
Issue raised: https://issues.apache.org/jira/browse/HTTPCLIENT-1998
Thanks,
Joan.
-Original Message-
From: Oleg Kalnichevski
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 :
> x : 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.606ex-017E91C3: preparing request execution
> 23:59:47.606ex-017E91C3: target auth state: UNCHALLENGED
> 23:59:47.606ex-017E91C3: proxy auth state: UNCHALLENGED
> 23:59:47.606ex-017E91C3: acquiring connection with route {}->
> http://10.15.15.18:8081
> 23:59:47.606ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
> 23:59:47.606ex-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.606ex-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.606ex-017E91C3: acquired ep-017E91C2
> 23:59:47.606ex-017E91C3: acquired endpoint ep-017E91C2
> 23:59:47.606ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
> 23:59:47.606ep-017E91C2: start execution ex-017E91C3
> 23:59:47.606ep-017E91C2: executing exchange ex-017E91C3 over i/o-
> 00970788
> 23:59:47.607ex-017E91C3: send request POST /ApiServlet.Srv
> HTTP/1.1, entity len 810
> 23:59:47.607ex-017E91C3: produce request data
> 23:59:47.607ex-017E91C3: produce request data, len 810 bytes
> 23:59:47.607ex-017E91C3: end of request data
> 23:59:48.382ex-017E91C3: execution failed: 2,000 MILLISECONDS
> 23:59:48.382ex-017E91C3: request failed: 2,000 MILLISECONDS
> 23:59:48.382ep-017E91C2: close IMMEDIATE
> 23:59:48.382ep-017E91C2: endpoint closed
> 23:59:48.382ep-017E91C2: discarding endpoint
> 23:59:48.382ep-017E91C2: releasing endpoint
> 23:59:48.382ep-017E91C2: connection
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 :
> x : 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.606ex-017E91C3: preparing request execution
> 23:59:47.606ex-017E91C3: target auth state: UNCHALLENGED
> 23:59:47.606ex-017E91C3: proxy auth state: UNCHALLENGED
> 23:59:47.606ex-017E91C3: acquiring connection with route {}->
> http://10.15.15.18:8081
> 23:59:47.606ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
> 23:59:47.606ex-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.606ex-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.606ex-017E91C3: acquired ep-017E91C2
> 23:59:47.606ex-017E91C3: acquired endpoint ep-017E91C2
> 23:59:47.606ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
> 23:59:47.606ep-017E91C2: start execution ex-017E91C3
> 23:59:47.606ep-017E91C2: executing exchange ex-017E91C3 over i/o-
> 00970788
> 23:59:47.607ex-017E91C3: send request POST /ApiServlet.Srv
> HTTP/1.1, entity len 810
> 23:59:47.607ex-017E91C3: produce request data
> 23:59:47.607ex-017E91C3: produce request data, len 810 bytes
> 23:59:47.607ex-017E91C3: end of request data
> 23:59:48.382ex-017E91C3: execution failed: 2,000 MILLISECONDS
> 23:59:48.382ex-017E91C3: request failed: 2,000 MILLISECONDS
> 23:59:48.382ep-017E91C2: close IMMEDIATE
> 23:59:48.382ep-017E91C2: endpoint closed
> 23:59:48.382ep-017E91C2: discarding endpoint
> 23:59:48.382ep-017E91C2: releasing endpoint
> 23:59:48.382ep-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-unsubscr...@hc.apache.org
> For
RE: Response timeout issue
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 : x :
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.606ex-017E91C3: preparing request execution
23:59:47.606ex-017E91C3: target auth state: UNCHALLENGED
23:59:47.606ex-017E91C3: proxy auth state: UNCHALLENGED
23:59:47.606ex-017E91C3: acquiring connection with route
{}->http://10.15.15.18:8081
23:59:47.606ex-017E91C3: acquiring endpoint (1,000 MILLISECONDS)
23:59:47.606ex-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.606ex-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.606ex-017E91C3: acquired ep-017E91C2
23:59:47.606ex-017E91C3: acquired endpoint ep-017E91C2
23:59:47.606ex-017E91C3: executing POST /ApiServlet.Srv HTTP/1.1
23:59:47.606ep-017E91C2: start execution ex-017E91C3
23:59:47.606ep-017E91C2: executing exchange ex-017E91C3 over i/o-00970788
23:59:47.607ex-017E91C3: send request POST /ApiServlet.Srv HTTP/1.1, entity
len 810
23:59:47.607ex-017E91C3: produce request data
23:59:47.607ex-017E91C3: produce request data, len 810 bytes
23:59:47.607ex-017E91C3: end of request data
23:59:48.382ex-017E91C3: execution failed: 2,000 MILLISECONDS
23:59:48.382ex-017E91C3: request failed: 2,000 MILLISECONDS
23:59:48.382ep-017E91C2: close IMMEDIATE
23:59:48.382ep-017E91C2: endpoint closed
23:59:48.382ep-017E91C2: discarding endpoint
23:59:48.382ep-017E91C2: releasing endpoint
23:59:48.382ep-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-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
Re: Response timeout issue
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.054Connection 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.
---
---
Oleg
> Joan.
>
>
> > Thanks,
> >
> > Joan.
> >
> > -Original Message-
> > From: Oleg Kalnichevski
> > Sent: Friday, June 7, 2019 4:00 PM
> > To: HttpClient User Discussion
> > 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.692ex-0105B9B8: preparing request execution
> > > 17:23:02.692Target auth state: UNCHALLENGED
> > > 17:23:02.692Proxy auth state: UNCHALLENGED
> > > 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> > > http://andalucia.viajesolympia.com:80
> > > 17:23:02.692Connection request: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > > allocated: 0 of 1000; total allocated: 1 of 1000]
> > > 17:23:02.692Connection leased: [route: {}->
> > > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > > allocated: 1 of 1000; total allocated: 2 of 1000]
> > > 17:23:02.692ep-010526BF: acquired null
> > > 17:23:02.692ex-0105B9B8: connection acquired
> > >
> > > This is the second:
> > >
> > > 17:23:02.954ex-0105B9B9: preparing request execution
> > > 17:23:02.955Target auth state: UNCHALLENGED
> > > 17:23:02.955Proxy auth state: UNCHALLENGED
> > &
RE: Response timeout issue
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.054Connection 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
> Sent: Friday, June 7, 2019 4:00 PM
> To: HttpClient User Discussion
> 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.692ex-0105B9B8: preparing request execution
> > 17:23:02.692Target auth state: UNCHALLENGED
> > 17:23:02.692Proxy auth state: UNCHALLENGED
> > 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.692Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 0 of 1000; total allocated: 1 of 1000]
> > 17:23:02.692Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.692ep-010526BF: acquired null
> > 17:23:02.692ex-0105B9B8: connection acquired
> >
> > This is the second:
> >
> > 17:23:02.954ex-0105B9B9: preparing request execution
> > 17:23:02.955Target auth state: UNCHALLENGED
> > 17:23:02.955Proxy auth state: UNCHALLENGED
> > 17:23:02.955ex-0105B9B9: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.955Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.955Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > alloca
Re: Response timeout issue
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.054Connection 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
> Sent: Friday, June 7, 2019 4:00 PM
> To: HttpClient User Discussion
> 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.692ex-0105B9B8: preparing request execution
> > 17:23:02.692Target auth state: UNCHALLENGED
> > 17:23:02.692Proxy auth state: UNCHALLENGED
> > 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.692Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 0 of 1000; total allocated: 1 of 1000]
> > 17:23:02.692Connection leased: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> > 17:23:02.692ep-010526BF: acquired null
> > 17:23:02.692ex-0105B9B8: connection acquired
> >
> > This is the second:
> >
> > 17:23:02.954ex-0105B9B9: preparing request execution
> > 17:23:02.955Target auth state: UNCHALLENGED
> > 17:23:02.955Proxy auth state: UNCHALLENGED
> > 17:23:02.955ex-0105B9B9: acquiring connection with route {}->
> > http://andalucia.viajesolympia.com:80
> > 17:23:02.955Connection request: [route: {}->
> > http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> > allocated: 1 of 1000; total allocated: 2 of 1000]
> &
RE: Response timeout issue
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.054Connection 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
Sent: Friday, June 7, 2019 4:00 PM
To: HttpClient User Discussion
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.692ex-0105B9B8: preparing request execution
> 17:23:02.692Target auth state: UNCHALLENGED
> 17:23:02.692Proxy auth state: UNCHALLENGED
> 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692ep-010526BF: acquired null
> 17:23:02.692ex-0105B9B8: connection acquired
>
> This is the second:
>
> 17:23:02.954ex-0105B9B9: preparing request execution
> 17:23:02.955Target auth state: UNCHALLENGED
> 17:23:02.955Proxy auth state: UNCHALLENGED
> 17:23:02.955ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955ep-010526C0: acquired null
> 17:23:02.955ex-0105B9B9: connection acquired
> 17:23:02.976ep-010526C0: connected i/o-434A
> 17:23:02.976Connected to target
> 17:23:02.976Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -
> 17:27:29.996Shutdown connection pool GRACEFUL
> 17:27:29.996i/o-43AF: Shutdown connection GRACEFUL
> 17:27:29.996i/o-2D9A: Shutdown connection GRACEFUL
> 17:27:29.996Connection pool shut down
> 17:27:29.997Shutdown GRACEFUL
>
> 1st. request afte
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.692ex-0105B9B8: preparing request execution
> 17:23:02.692Target auth state: UNCHALLENGED
> 17:23:02.692Proxy auth state: UNCHALLENGED
> 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692ep-010526BF: acquired null
> 17:23:02.692ex-0105B9B8: connection acquired
>
> This is the second:
>
> 17:23:02.954ex-0105B9B9: preparing request execution
> 17:23:02.955Target auth state: UNCHALLENGED
> 17:23:02.955Proxy auth state: UNCHALLENGED
> 17:23:02.955ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955ep-010526C0: acquired null
> 17:23:02.955ex-0105B9B9: connection acquired
> 17:23:02.976ep-010526C0: connected i/o-434A
> 17:23:02.976Connected to target
> 17:23:02.976Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -
> 17:27:29.996Shutdown connection pool GRACEFUL
> 17:27:29.996i/o-43AF: Shutdown connection GRACEFUL
> 17:27:29.996i/o-2D9A: Shutdown connection GRACEFUL
> 17:27:29.996Connection pool shut down
> 17:27:29.997Shutdown GRACEFUL
>
> 1st. request after rebooting. Here keep-alive = 0 and total_allocated
> = 1
> -
> 17:27:53.585ex-0105BA49: preparing request execution
> 17:27:53.585Target auth state: UNCHALLENGED
> 17:27:53.585Proxy auth state: UNCHALLENGED
> 17:27:53.585ex-0105BA49: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:27:53.585Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 0 of 1000; total allocated: 0 of 1000]
> 17:27:53.585Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 1 of 1000; total allocated: 1 of 1000]
> 17:27:53.585ep-01052750: acquired null
> 17:27:53.585ex-0105BA49: connection acquired
> 17:27:53.609ep-01052750: connected i/o-43B0
> 17:27:53.609Connected to target
> 17:27:53.609Route fully established
>
>
> Thanks,
> Joan.
>
>
>
> -
> To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> For additional commands, e-mail: httpclient-users-h...@hc.apache.org
>
-
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
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")
> 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.692ex-0105B9B8: preparing request execution
> 17:23:02.692Target auth state: UNCHALLENGED
> 17:23:02.692Proxy auth state: UNCHALLENGED
> 17:23:02.692ex-0105B9B8: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.692Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 0 of 1000; total allocated: 1 of 1000]
> 17:23:02.692Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.692ep-010526BF: acquired null
> 17:23:02.692ex-0105B9B8: connection acquired
>
> This is the second:
>
> 17:23:02.954ex-0105B9B9: preparing request execution
> 17:23:02.955Target auth state: UNCHALLENGED
> 17:23:02.955Proxy auth state: UNCHALLENGED
> 17:23:02.955ex-0105B9B9: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:23:02.955Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 2; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 1; route
> allocated: 1 of 1000; total allocated: 2 of 1000]
> 17:23:02.955ep-010526C0: acquired null
> 17:23:02.955ex-0105B9B9: connection acquired
> 17:23:02.976ep-010526C0: connected i/o-434A
> 17:23:02.976Connected to target
> 17:23:02.976Route fully established
>
> ( . . . )
>
> Now a pool reboot
> -
> 17:27:29.996Shutdown connection pool GRACEFUL
> 17:27:29.996i/o-43AF: Shutdown connection GRACEFUL
> 17:27:29.996i/o-2D9A: Shutdown connection GRACEFUL
> 17:27:29.996Connection pool shut down
> 17:27:29.997Shutdown GRACEFUL
>
> 1st. request after rebooting. Here keep-alive = 0 and total_allocated
> = 1
> -
> 17:27:53.585ex-0105BA49: preparing request execution
> 17:27:53.585Target auth state: UNCHALLENGED
> 17:27:53.585Proxy auth state: UNCHALLENGED
> 17:27:53.585ex-0105BA49: acquiring connection with route {}->
> http://andalucia.viajesolympia.com:80
> 17:27:53.585Connection request: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 0 of 1000; total allocated: 0 of 1000]
> 17:27:53.585Connection leased: [route: {}->
> http://andalucia.viajesolympia.com:80][total kept alive: 0; route
> allocated: 1 of 1000; total allocated: 1 of 1000]
> 17:27:53.585ep-01052750: acquired null
> 17:27:53.585ex-0105BA49: connection acquired
> 17:27:53.609ep-01052750: connected i/o-43B0
> 17:27:53.609Connected to target
> 17:27:53.609Route 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-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
RE: Response timeout issue
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.692ex-0105B9B8: preparing request execution
17:23:02.692Target auth state: UNCHALLENGED
17:23:02.692Proxy auth state: UNCHALLENGED
17:23:02.692ex-0105B9B8: acquiring connection with route
{}->http://andalucia.viajesolympia.com:80
17:23:02.692Connection request: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route
allocated: 0 of 1000; total allocated: 1 of 1000]
17:23:02.692Connection leased: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route
allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.692ep-010526BF: acquired null
17:23:02.692ex-0105B9B8: connection acquired
This is the second:
17:23:02.954ex-0105B9B9: preparing request execution
17:23:02.955Target auth state: UNCHALLENGED
17:23:02.955Proxy auth state: UNCHALLENGED
17:23:02.955ex-0105B9B9: acquiring connection with route
{}->http://andalucia.viajesolympia.com:80
17:23:02.955Connection request: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 2; route
allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.955Connection leased: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 1; route
allocated: 1 of 1000; total allocated: 2 of 1000]
17:23:02.955ep-010526C0: acquired null
17:23:02.955ex-0105B9B9: connection acquired
17:23:02.976ep-010526C0: connected i/o-434A
17:23:02.976Connected to target
17:23:02.976Route fully established
( . . . )
Now a pool reboot
-
17:27:29.996Shutdown connection pool GRACEFUL
17:27:29.996i/o-43AF: Shutdown connection GRACEFUL
17:27:29.996i/o-2D9A: Shutdown connection GRACEFUL
17:27:29.996Connection pool shut down
17:27:29.997Shutdown GRACEFUL
1st. request after rebooting. Here keep-alive = 0 and total_allocated = 1
-
17:27:53.585ex-0105BA49: preparing request execution
17:27:53.585Target auth state: UNCHALLENGED
17:27:53.585Proxy auth state: UNCHALLENGED
17:27:53.585ex-0105BA49: acquiring connection with route
{}->http://andalucia.viajesolympia.com:80
17:27:53.585Connection request: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 0; route
allocated: 0 of 1000; total allocated: 0 of 1000]
17:27:53.585Connection leased: [route:
{}->http://andalucia.viajesolympia.com:80][total kept alive: 0; route
allocated: 1 of 1000; total allocated: 1 of 1000]
17:27:53.585ep-01052750: acquired null
17:27:53.585ex-0105BA49: connection acquired
17:27:53.609ep-01052750: connected i/o-43B0
17:27:53.609Connected to target
17:27:53.609Route fully established
Thanks,
Joan.
-
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
RE: Response timeout issue
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.211Connection 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.893Connection 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
Sent: Thursday, June 6, 2019 3:15 PM
To: HttpClient User Discussion
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
> Sent: Thursday, June 6, 2019 2:27 PM
> To: HttpClient User Discussion
> 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.031ex-00E1DFB8: acquiring connection with route
> > {}->
> > http://10.15.15.14:8082
> > 08:12:56.087Connection 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.054Connection 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.080Connection 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.107Connection 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.192ex-00E1E1D1: preparing request execution
> > 08:14:03.192Target auth state: UNCHALLENGED
> > 08:14:03.192Proxy auth state: UNCHALLENGED
> > 08:14:03.192ex-00E1E1D1: acquiring connection with route
> > {}->
> > http://10.15.15.24:8080
> > 08:14:03.197Shutdown connection pool GRACEFUL
> > 08:14:03.224Connection 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.225i/o-0041DB56: Shutdown connection GRACEFUL
> > 08:14:03.226i/o-0041DB37: Shutdown connection GRACEFUL
> > 08:14:03.226i/o-0041DB19: Shutdown connection GRACEFUL
> > 08:14:03.242Connection pool shut down
> > 08:14:03.242Shutdown GRACEFUL
> > 08:14:03.276ex-00E1E1D2: preparing request execution
> > 08:14:03.276Target auth state: UNCHALLENGED
> > 08:14:03.276Proxy auth state: UNCHALLENGED
> > 08:14:03.276ex-00E1E1D2: acquiring connection with route
> > {}->
> > http://10.15.15.53:8081
> > 08:14:03.277Connection re
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
> Sent: Thursday, June 6, 2019 2:27 PM
> To: HttpClient User Discussion
> 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.031ex-00E1DFB8: acquiring connection with route
> > {}->
> > http://10.15.15.14:8082
> > 08:12:56.087Connection 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.054Connection 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.080Connection 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.107Connection 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.192ex-00E1E1D1: preparing request execution
> > 08:14:03.192Target auth state: UNCHALLENGED
> > 08:14:03.192Proxy auth state: UNCHALLENGED
> > 08:14:03.192ex-00E1E1D1: acquiring connection with route
> > {}->
> > http://10.15.15.24:8080
> > 08:14:03.197Shutdown connection pool GRACEFUL
> > 08:14:03.224Connection 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.225i/o-0041DB56: Shutdown connection GRACEFUL
> > 08:14:03.226i/o-0041DB37: Shutdown connection GRACEFUL
> > 08:14:03.226i/o-0041DB19: Shutdown connection GRACEFUL
> > 08:14:03.242Connection pool shut down
> > 08:14:03.242Shutdown GRACEFUL
> > 08:14:03.276ex-00E1E1D2: preparing request execution
> > 08:14:03.276Target auth state: UNCHALLENGED
> > 08:14:03.276Proxy auth state: UNCHALLENGED
> > 08:14:03.276ex-00E1E1D2: acquiring connection with route
> > {}->
> > http://10.15.15.53:8081
> > 08:14:03.277Connection 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.277Connection 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.277ep-00DFEDB0: acquired null
> > 08:14:03.277ex-00E1E1D2: connection acquired
> > 08:14:03.279ep-00DFEDB0: connected i/o-00423C70
> > 08:14:03.279Connected to target
> > 08:14:03.279Route fully established
> >
> > The point is the variable 'this.capacityToPerform' we
RE: Response timeout issue
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
Sent: Thursday, June 6, 2019 2:27 PM
To: HttpClient User Discussion
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 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());
>
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 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
>
RE: Response timeout issue
ent: Thursday, May 30, 2019 11:40 AM To: HttpClient User Discussion 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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org
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 > 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 > Sent: Monday, May 27, 2019 11:10 PM > To: HttpClient User Discussion > 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 lo
RE: Response timeout issue
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
Sent: Monday, May 27, 2019 11:10 PM
To: HttpClient User Discussion
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.headerItera
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-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
