Hello Oleg,
I've come across with the following issue. Our application is contacting
with a webservice that returns information about the requested hotels.
More hotels in the request, bigger the response size. This issue happens
using both https or http.
Below the results of the test using curl, httpAsync 4.1.3 and
httpclient5-5.0-beta3 with httpcore5-5.0-beta6 (all tests executed on
the same server):
1) Using curl:
1 hotel -> 200 OK : 37K : 1.2s
2 hotels --> 200 OK : 74K : 1.4s
3 hotels --> 200 OK : 102K : 1.5s
2) Using HttpAsync 4.1.3:
1 hotel -> 200 OK : 37K : 1.2s
2 hotels --> 200 OK : 74K : 1.4s
3 hotels --> 200 OK : 102K : 1.5s
3) Using HttpClient5:
1 hotel -> 200 OK : 37K : 1.3s
2 hotels --> Socket Timeout
3 hotels --> Socket Timeout
The socket timeout error trace is:
java.net.SocketTimeoutException: 15,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:404)
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)
Traces within our 'AsyncResponseConsumer' show the following for the
third case (3 hotels, 102K response size):
consumeResponse :: entityDetails =
org.apache.hc.core5.http.impl.IncomingEntityDetails@4ed28646
consumeResponse :: headers = Date = Thu, 04 Apr 2019 13:41:33 GMT,
Server = Apache, Keep-Alive = timeout=15, max=100, Connection =
Keep-Alive, Transfer-Encoding = chunked, Content-Type = text/xml;
charset=utf-8,
consume called :: iteration 0 :: block size read: 4072 bytes, total size
read = 4072, total time spent = 57635 nanos.
consume called :: iteration 1 :: block size read: 8144 bytes, total size
read = 12216, total time spent = 107300 nanos.
consume called :: iteration 2 :: block size read: 4126 bytes, total size
read = 16342, total time spent = 136496 nanos.
consume called :: iteration 3 :: block size read: 5512 bytes, total size
read = 21854, total time spent = 198755 nanos.
consume called :: iteration 4 :: block size read: 8192 bytes, total size
read = 30046, total time spent = 229160 nanos.
consume called :: iteration 5 :: block size read: 5994 bytes, total size
read = 36040, total time spent = 289098 nanos.
consume called :: iteration 6 :: block size read: 5094 bytes, total size
read = 41134, total time spent = 311649 nanos.
consume called :: iteration 7 :: block size read: 3050 bytes, total size
read = 44184, total time spent = 368913 nanos.
consume called :: iteration 8 :: block size read: 5126 bytes, total size
read = 49310, total time spent = 427755 nanos.
consume called :: iteration 9 :: block size read: 8192 bytes, total size
read = 57502, total time spent = 452800 nanos.
consume called :: iteration 10 :: block size read: 7044 bytes, total
size read = 64546, total time spent = 474367 nanos.
consume called :: iteration 11 :: block size read: 4088 bytes, total
size read = 68634, total time spent = 544338 nanos.
failed called :: java.net.SocketTimeoutException: 15,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:404)
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)
I'm trying to debug, but I'm not able to log anything into the http
client log. The log file is created but nothing is logged. I'm using
log4j2 in this way:
<!-- HTTP log for debug purposes -->
<File name="HTTP_LOG" fileName="${sys:log.dir}httpClient5.log"
append="true" immediateFlush="true">
<PatternLayout>
<Pattern>%m%n</Pattern>
</PatternLayout>
</File>
<!-- HTTP enable logging -->
<Logger name="org.apache.hc" level="debug" includeLocation="false"
additivity="false">
<AppenderRef ref="HTTP_LOG"/>
</Logger>
I'm logging correctly into another log files using identical
configuration ... What's wrong in this log4j2 configuration?
I have executed this test several times (request with 3 hotels) ... it
seems to always stop after reading more than (or around) 64K of data.
If I could debug I would be able to give more information.
Thanks,
Joan.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
