[
https://issues.apache.org/jira/browse/HTTPCLIENT-2330?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17853739#comment-17853739
]
John Woodward commented on HTTPCLIENT-2330:
-------------------------------------------
I understand that the socket timeout is not a deadline, and so in most cases,
we probably would like something like HTTPCLIENT-1074.
However, seeing a socket timeout happen at the configured time (5 seconds) and
then a further 5 seconds taken to flush & close the stream, means control to my
application is always taking 2x the socket timeout in this case. In production,
we're actually using a 15 second timeout (the system we are connecting to can
take 5-10 seconds to process our request before sending a response), but this
means control isn't returned to our application for 30+ seconds, when _roughly_
15 seconds was the expectation.
We are scratching our heads over why it appears the flush is also taking a
period of time equivalent to the socket timeout (of course, we could be
mistaken, but setting a break point on that line, and doing a step over as soon
as the break point hits seems to confirm it).
Not sure it's anything httpclient has control over, if it's an operation on the
socket, and it's timing out with another socket timeout, but it's really
strange to happen against this particular site. We've tried setting up unit
tests connecting to hand-coded servers that do what httpstat.us does, but to no
avail — something we're not able to replicate is producing what seems to be a
second socket timeout (though we don't actually see a socket timeout being
thrown – just the equivalent time to a socket timeout).
> 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
> Priority: Major
>
> 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: dev-unsubscr...@hc.apache.org
For additional commands, e-mail: dev-h...@hc.apache.org
