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: [email protected]
For additional commands, e-mail: [email protected]
