Hi,
On Fri, Jun 18, 2021 at 3:00 AM Lu Tahmazyan via jetty-users
<jetty-users@xxxxxxxxxxx> wrote:
>
> Hello, good people of Jetty.
>
> I am looking for some guidance with this exception
>
> 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)
>
> 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.
That is weird.
Do you have a reproducible case?
Unfortunately, I don't have an easily reproducible case, I observe this exception for servers with high load (possibly giving more weight to the theory that the server is under-provisioned)
What OS and JVM version/vendor?
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
> Exception is thrwon from here (ManagedSelector:955)
> public void run()
> {
> if (_selectorManager.isConnectionPending(channel))
> {
> if (LOG.isDebugEnabled())
> LOG.debug("Channel {} timed out while connecting, closing it", channel);
> failed(new SocketTimeoutException("Connect Timeout"));
> }
> }
>
> One theory was that the proxied service was not responding fast enough, due to it being under-provisioned. In order to test that theory, we scaled the backend service 3x, and still, we are seeing these types of exceptions.
>
> Looking at the Jetty code, "SocketTimeoutException: Connect Timeout" is thrown if the connection on the channel is pending. I don't really understand how the connect timeout is related here. If it is how would one configure it. Basically what I am asking for there is there a configuration parameter for addressing the pending connection issue which leads to SocketTimeoutException.
The way it works is that we open the SocketChannel and register it for
OP_CONNECT.
When the connection is complete, the JVM NIO subsystem calls the Jetty
code above where we test whether the connection was actually
completed.
Obviously it is still pending even if the JVM called Jetty with the
OP_CONNECT event, so we throw.
My theory is that you have some bad/under-provisioned configuration on
the server/load balancer where opening many connections leads to them
being refused almost immediately.
What you see is not a "timeout" but the server rejecting the
connection attempt, which generates on the client an OP_CONNECT event
to which we react with the code above.
So perhaps we can improve the exception type and/or message, but I
think you have some other configuration problem on the server or load
balancer.
Can you please open an issue about improving the exception message?
If you can take a network dump, it should be clear what happens.
I would expect the client sending a SYN and the server replying
immediately with a FIN.
Alternatively, configure the client with blocking connects:
HttpClient httpClient = ...;
httpClient.setConnectBlocking(true);
In this way TCP connects are blocking and you should see (if my theory
is correct) "close"-type exceptions being thrown as the server refuses
connect attempts.
After enabling hc.setConnectBlocking(true) this is what was observed.
We stopped getting the previously reported exception of
java.net.SocketTimeoutException: Connect Timeout
at org.eclipse.jetty.io.ManagedSelector$Connect.run(ManagedSelector.java:955) ...
And started getting this exception involving the same server
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)
Looking at the connect method in SocketAdaptor, it is obvious it will use the entirety of connect timeout before throwing STE. However, our logs using our instrumentation show that calls timeout really quickly (sup 10 ms), thus most likely there might be an issue with our measurement of call duration.
I am working on getting a tcpdump of the traffic, once this is done and I have some results will report back.
-Lu
--
Simone Bordet
----
http://cometd.org
http://webtide.com
Developer advice, training, services and support
from the Jetty & CometD experts.
