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-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
