Hi again,
To discard a particular issue with the destination endpoint used, I have tried
to send a similar request from this server to another server within the same
network. The result is similar, this time is able to read 92313 bytes of 101011
in just 0,26ms and then a wait of 14,75s until reaching the response timeout:
consumeResponse :: entityDetails =
org.apache.hc.core5.http.impl.IncomingEntityDetails@54dc9d56
consumeResponse :: headers = Content-Length = 101011, Content-Type =
application/xml, Date = Thu, 04 Apr 2019 15:35:40 GMT,
consume called :: iteration 0 :: block size read: 3985 bytes, total size read =
3985, total time spent = 46152 nanos.
consume called :: iteration 1 :: block size read: 8192 bytes, total size read =
12177, total time spent = 65443 nanos.
consume called :: iteration 2 :: block size read: 8192 bytes, total size read =
20369, total time spent = 80566 nanos.
consume called :: iteration 3 :: block size read: 8192 bytes, total size read =
28561, total time spent = 95823 nanos.
consume called :: iteration 4 :: block size read: 8192 bytes, total size read =
36753, total time spent = 110210 nanos.
consume called :: iteration 5 :: block size read: 3432 bytes, total size read =
40185, total time spent = 122873 nanos.
consume called :: iteration 6 :: block size read: 2896 bytes, total size read =
43081, total time spent = 138658 nanos.
consume called :: iteration 7 :: block size read: 8192 bytes, total size read =
51273, total time spent = 157141 nanos.
consume called :: iteration 8 :: block size read: 6288 bytes, total size read =
57561, total time spent = 171490 nanos.
consume called :: iteration 9 :: block size read: 8192 bytes, total size read =
65753, total time spent = 188350 nanos.
consume called :: iteration 10 :: block size read: 8192 bytes, total size read
= 73945, total time spent = 217534 nanos.
consume called :: iteration 11 :: block size read: 8192 bytes, total size read
= 82137, total time spent = 234016 nanos.
consume called :: iteration 12 :: block size read: 8192 bytes, total size read
= 90329, total time spent = 249907 nanos.
consume called :: iteration 13 :: block size read: 1984 bytes, total size read
= 92313, total time spent = 263477 nanos.
Finish 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)
The same execution with a curl or using HttpAsync 4.1.3 works fine.
Thanks,
Joan.
-----Original Message-----
From: [email protected] [mailto:[email protected]]
Sent: Thursday, April 4, 2019 4:21 PM
To: [email protected]
Subject: Socket timeout exception with HttpClient5
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: [email protected]
For additional commands, e-mail: [email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
