We see time-outs during some calls to external REST service from within a Spring Boot application. They do not seem to occur when we connect to the REST service directly. Debug logging on org.apache.http has given us a very peculiar aspect of the failing requests: it contains an inbound log entry '<< "[read] I/O error: Read timed out"' in the middle of sending headers - the same millisecond the first headers were sent.
How can we see an inbound 'Read timed out' a few milliseconds after sending the first headers? And why does it not immediately interrupt the request/connection with a time-out, but instead waits the full 4500ms until it times out with an exception?
Here is our production log for a failing request, redacted. Note the 4500ms delay between lines two and three. My question is about the occurrence of http-outgoing-104 << "[read] I/O error: Read timed out" at 16:55:08.258, not the first one on line 2.
16:55:12.764 Connection released: [id: 104][route: {s}-><<website-redacted>>:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
16:55:12.763 http-outgoing-104 << "[read] I/O error: Read timed out"
16:55:08.259 http-outgoing-104 >> "<<POST Body Redacted>>"
16:55:08.259 http-outgoing-104 >> "[\r][\n]"
16:55:08.258 http-outgoing-104: set socket timeout to 4500
16:55:08.258 Executing request POST <<Endpoint Redacted>> HTTP/1.1
16:55:08.258 Target auth state: UNCHALLENGED
16:55:08.258 Proxy auth state: UNCHALLENGED
16:55:08.258 Connection leased: [id: 104][route: {s}-><<website-redacted>>:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
....
16:55:08.258 http-outgoing-104 >> "POST <<Endpoint Redacted>> HTTP/1.1[\r][\n]"
16:55:08.258 http-outgoing-104 >> "Accept: text/plain, application/json, application/*+json, */*[\r][\n]"
16:55:08.258 http-outgoing-104 >> Cookie: <<Redacted>>
16:55:08.258 http-outgoing-104 >> "Content-Type: application/json[\r][\n]"
16:55:08.258 http-outgoing-104 >> "Connection: close[\r][\n]"
16:55:08.258 http-outgoing-104 >> "X-B3-SpanId: <<ID>>[\r][\n]"
16:55:08.258 http-outgoing-104 << "[read] I/O error: Read timed out"
16:55:08.258 http-outgoing-104 >> "X-Span-Name: https:<<Endpoint Redacted>>[\r][\n]"
16:55:08.258 http-outgoing-104 >> "X-B3-TraceId: <<ID>>[\r][\n]"
16:55:08.258 http-outgoing-104 >> "X-B3-ParentSpanId: <<ID>>[\r][\n]"
16:55:08.258 http-outgoing-104 >> "Content-Length: 90[\r][\n]"
16:55:08.258 http-outgoing-104 >> "User-Agent: Apache-HttpClient/4.5.3 (Java/1.8.0_172)[\r][\n]"
16:55:08.258 http-outgoing-104 >> "Cookie: <<Redacted>>"
16:55:08.258 http-outgoing-104 >> "Host: <<Host redacted>>[\r][\n]"
16:55:08.258 http-outgoing-104 >> "Accept-Encoding: gzip,deflate[\r][\n]"
16:55:08.258 http-outgoing-104 >> "X-B3-Sampled: 1[\r][\n
Update 1: a second occurrence: In another request that timed out the same behavior roughly occurs, but the timeout message is logged even before sending headers and eventually receiving the actual timeout. Note: this request is actually older, after it I have configured the request to include 'Connection: close' to circumvent a firewall dropping the connection under 'Keep Alive'.
19:28:08.102 http-outgoing-36 << "[read] I/O error: Read timed out"
19:28:08.102 http-outgoing-36: Shutdown connection
19:28:08.102 http-outgoing-36: Close connection
19:28:03.598 http-outgoing-36 >> "Connection: Keep-Alive[\r][\n]"
19:28:03.598 http-outgoing-36 >> "Content-Type: application/json;charset=UTF-8[\r][\n]"
...
19:28:03.598 http-outgoing-36 >> "Accept-Encoding: gzip,deflate[\r][\n]"
...
19:28:03.597 http-outgoing-36 >> Cookie: ....
19:28:03.597 http-outgoing-36 >> Accept-Encoding: gzip,deflate
19:28:03.597 http-outgoing-36 >> User-Agent: Apache-HttpClient/4.5.3 (Java/1.8.0_172)
19:28:03.596 Connection leased: [id: 36][route: {s}-><< Site redacted >>:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
19:28:03.596 http-outgoing-36: set socket timeout to 4500
19:28:03.596 Executing request POST HTTP/1.1
19:28:03.596 Target auth state: UNCHALLENGED
19:28:03.596 http-outgoing-36 << "[read] I/O error: Read timed out"
19:28:03.594 Connection request: [route: {s}-><< Site redacted >>:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]
19:28:03.594 Auth cache not set in the context
Update 2: added HttpClientBuilder configuration
RequestConfig.Builder requestBuilder = RequestConfig.custom()
.setSocketTimeout(socketTimeout)
.setConnectTimeout(connectTimeout);
CloseableHttpClient httpClient = HttpClientBuilder.create()
.setDefaultRequestConfig(requestBuilder.build())
.build();
HttpComponentsClientHttpRequestFactory rf = new HttpComponentsClientHttpRequestFactory(httpClient);
return new RestTemplate(rf);