[
https://issues.apache.org/jira/browse/HTTPCLIENT-2330?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17853753#comment-17853753
]
John Woodward commented on HTTPCLIENT-2330:
-------------------------------------------
Yeah; that's what I'm afraid of — that it's something in the underlying layer
is forcing an extra operation causing a secondary socket timeout delay. :( And
likely no way to avoid that.
> 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: [email protected]
For additional commands, e-mail: [email protected]
