John Woodward created HTTPCLIENT-2330:
-----------------------------------------
Summary: Socket timeouts taking 2x time requested
Key: HTTPCLIENT-2330
URL: https://issues.apache.org/jira/browse/HTTPCLIENT-2330
Project: HttpComponents HttpClient
Issue Type: Bug
Components: HttpClient (classic)
Affects Versions: 5.3.1
Environment: Recreated on
Unbuntu 23.10
Java 17 and 21
Reporter: John Woodward
We are having an issue very similar to
https://issues.apache.org/jira/browse/HTTPCLIENT-2324. We've had issues
recreating this in a small unit test, however. We have traced through the
execution of the code carefully, with trace-level logging enabled, and see the
following:
We have a socket timeout (responseTimeout) set to 5000 ms.
We fire a request using RestTemplate to a point-of-sale endpoint using https
and basic auth (Aloha; using a site like httpstat.us does not seem to recreate
the issue, when using http or https).
We see the outbound event at a timestamp such as
{quote}2024-06-10T09:01:17.880-0500
{quote}
We see http.wire post the socket timeout at the expected time, 5 seconds after
the initial request:
{quote}2024-06-10T09:01:22.883-0500| DEBUG|
http-nio-8080-exec-2| org.apache.hc.client5.http.wire| http-outgoing-2
<< "[read] I/O error: Read timed out"
2024-06-10T09:01:22.883-0500| DEBUG| http-nio-8080-exec-2|
http-outgoing-2 Close connection
{quote}
We then see the connection wait for an additional 5 seconds (adjusting the
socket timeout, this time will be identical to the socket timeout), followed by:
{quote}2024-06-10T09:01:27.889-0500| DEBUG|
http-nio-8080-exec-2|nt5.http.impl.classic.InternalHttpClient| ep-0000000003
endpoint closed
2024-06-10T09:01:27.889-0500| DEBUG|
http-nio-8080-exec-2|nt5.http.impl.classic.InternalHttpClient| ep-0000000003
discarding endpoint
{quote}
Tracing with the debugger, the second delay appears to happen in
org.apache.hc.core5.http.impl.io.BHttpConnectionBase, on line 255:
{quote} this.outbuffer.flush(socketHolder.getOutputStream());
{quote}
Interestingly enough, if we are in the debugger we need to step over this line
quickly to see it hang here for the socket timeout period; if we wait on this
line, then the flush will happen quickly.
I certainly understand the comments made in HTTPCLIENT-2324, that the socket
timeout is just a timeout between events (so the connection cannot be idle
longer that time span without encountering the socket timeout), but this
appears to be clear that a socket timeout is being encountered, followed by a
delay equivalent to the socket timeout timespan (another socket timeout being
thrown?).
A better way to handle an overall timeout would be to use something other than
just a socket timeout — but this is very unexpected to have a socket timeout
taking 2x the configured time (as if 2 separate timeouts are occurring).
Btw, we have recreated this with the latest httpclient 4.x release, as well as
5.x, and we've used both java 17, and java 21.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
