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: dev-unsubscr...@hc.apache.org For additional commands, e-mail: dev-h...@hc.apache.org