Socket timeout exception is thrown without utilizing allocated ConnectTimeout

[rushalias]

Jetty version(s) 9.4.42.v20210604

Java version/vendor (use: java -version) openjdk 11.0.11 2021-04-20 LTS OpenJDK Runtime Environment Corretto-11.0.11.9.1 (build 11.0.11+9-LTS) OpenJDK 64-Bit Server VM Corretto-11.0.11.9.1 (build 11.0.11+9-LTS, mixed mode)

OS type/version In Kubernetes Ubuntu 20 in userland container Ubuntu 18 in kernel

Description We have a subclass of AsyncMiddleManServlet which uses Jetty's HttpClient to proxy requests. HttpClient is configured with a connect-timeout of 1000 ms. What is interesting is that we see socket timeout exception is thrown without utilizing the full 1000 ms allocated for connect timeout, for example, we see calls getting timed out under 25 ms.

Thread is HTTP client scheduler thread: HttpClient@XXXXXXXX-scheduler-1

java.net.SocketTimeoutException: Connect Timeout
at org.eclipse.jetty.io.ManagedSelector$Connect.run(ManagedSelector.java:955)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)

Upon suggestion from Jetty maintainer we switched httpClient.setConnectBlocking(true) to help us debug. Here is the stack trace we get in that case.

Thread is main Jetty worker thread: default-pool-XX

java.net.SocketTimeoutException: null
at java.base/sun.nio.ch.SocketAdaptor.connect(SocketAdaptor.java:129)
at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.connect(AbstractConnectorHttpClientTransport.java:94)
at org.eclipse.jetty.client.HttpClient$1.connect(HttpClient.java:638)
at org.eclipse.jetty.client.HttpClient$1.succeeded(HttpClient.java:615)
at org.eclipse.jetty.client.HttpClient$1.succeeded(HttpClient.java:607)
at org.eclipse.jetty.util.SocketAddressResolver$Async.lambda$resolve$1(SocketAddressResolver.java:186)
at com.opentable.metrics.JettyServerMetricsConfiguration$OTQueuedThreadPool.runJob(JettyServerMetricsConfiguration.java:109)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036)
at java.base/java.lang.Thread.run(Thread.java:829)

Manage to take a network capture and look at it using Wire-shark. As predicted there is a reset happening, but it is not the server but Jetty-based proxy that is sending [RST]. Here is a screenshot of the failed stream: https://opentable.d.pr/m0KI1V

pseudo-code of network capture: proxy:58254 -> k8s service:8080 [SYN] k8s servic:8080 -> proxy:58254 [SYN, ACK] proxy:58254 -> k8s service:8080 [RST]

see https://www.eclipse.org/lists/jetty-users/msg09910.html for more details

How to reproduce? Sadly I don't have steps for reproduction, we see this exception in our production when proxying calls for "high traffic" servers, about 1.5 K requests / sec. This exception is not very frequent, when compared to successfully proxied calls it occurs less than 0.0001% of calls. We are still investigating on our side, will post additional details when available.

[github-actions[bot]]

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

[github-actions[bot]]

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.