jetty.project icon indicating copy to clipboard operation
jetty.project copied to clipboard

Client hangs despite setting timeout

Open garydgregory opened this issue 1 year ago • 3 comments
trafficstars

Jetty version(s) 12.0.10-SNAPSHOT

Jetty Environment ee9

Java version/vendor (use: java -version)

openjdk version "17.0.11" 2024-04-16
OpenJDK Runtime Environment Temurin-17.0.11+9 (build 17.0.11+9)
OpenJDK 64-Bit Server VM Temurin-17.0.11+9 (build 17.0.11+9, mixed mode, sharing)

OS type/version Microsoft Windows [Version 10.0.19045.4412]

Description To even give the test below a chance to run, I must apply PR https://github.com/jetty/jetty.project/pull/11891 to avoid NPEs on the server side. For me, the test hangs after between 90 and 400 iterations. If it does not, you can stress your CPU to 92%+ with CPU Stres.

Based on some println()s here and there (logging can affect timings): The hang is cause by CompletableFuture.get() never returning in listener.send().get() in HttpRequest.send():

    public ContentResponse send() throws InterruptedException, TimeoutException, ExecutionException
    {
        try
        {
            CompletableResponseListener listener = new CompletableResponseListener(this);
            return listener.send().get();
        }
    ...

get never returns because CompletableResponseListener.onComplete(Result) is never called, because ResponseListeners.notifyComplete(Response.CompleteListener, Result) is never called, because ResponseListeners.notifyComplete(Result) is never called.

How to reproduce?

diff --git a/jetty-ee9/jetty-ee9-proxy/src/test/java/org/eclipse/jetty/ee9/proxy/AsyncMiddleManServletTest.java b/jetty-ee9/jetty-ee9-proxy/src/test/java/org/eclipse/jetty/ee9/proxy/AsyncMiddleManServletTest.java
index 571b223307..1d171ffa17 100644
--- a/jetty-ee9/jetty-ee9-proxy/src/test/java/org/eclipse/jetty/ee9/proxy/AsyncMiddleManServletTest.java
+++ b/jetty-ee9/jetty-ee9-proxy/src/test/java/org/eclipse/jetty/ee9/proxy/AsyncMiddleManServletTest.java
@@ -41,6 +41,7 @@ import java.util.concurrent.ThreadLocalRandom;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.TimeoutException;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicInteger;
 import java.util.zip.GZIPInputStream;
 import java.util.zip.GZIPOutputStream;
 import java.util.zip.ZipEntry;
@@ -289,6 +290,72 @@ public class AsyncMiddleManServletTest
         }
     }

+    /**
+     * Tests that we do not hang processing sequenced client requests that are fast on the server-side;
+     * requires testServletOnContinueNullPointerException() to pass as a prerequisite.
+     * <p>
+     * Commenting out client EXPECT processing allows the test not to hang.
+     * </p>
+     * <p>
+     * It does not always happen, it may be related to how busy the CPU is; using "CPU Stres" from
+     * https://learn.microsoft.com/en-us/sysinternals/downloads/cpustres helps make the failure happen more often when
+     * I peg the CPU at 92% busy or above.
+     * </p>
+     * @throws Exception on a test failure.
+     */
+    @Test
+    public void testServletExpect100Hanging() throws Exception
+    {
+        startServer(new HttpServlet()
+        {
+            private AtomicInteger count = new AtomicInteger();
+
+            @Override
+            protected void service(HttpServletRequest request, HttpServletResponse response) throws IOException
+            {
+                // Adding logging may slow things down enough to not hang
+                // System.out.printf("Origin servicing %d%n", count.incrementAndGet());
+                // Send the 100 Continue.
+                ServletInputStream input = request.getInputStream();
+                // Echo the content.
+                IO.copy(input, response.getOutputStream());
+                // Slowing down the origin allows the test to not hang sometimes
+//                try {
+//                    Thread.sleep(50);
+//                } catch (InterruptedException e) {
+//                    e.printStackTrace();
+//                }
+            }
+        });
+        startProxy(new AsyncMiddleManServlet() {
+            private AtomicInteger count = new AtomicInteger();
+
+            @Override
+            protected void service(HttpServletRequest clientRequest, HttpServletResponse proxyResponse) throws ServletException, IOException {
+                // Adding logging may slow things down enough to not hang
+                // System.out.printf("Middle servicing %d%n", count.incrementAndGet());
+                super.service(clientRequest, proxyResponse);
+            }
+        });
+        startClient();
+
+        // loop to attempt increase odds of hanging
+        for (int i = 1; i <= 500; i++)
+        {
+            long start = System.currentTimeMillis();
+            System.out.printf("Sending %d", i);
+            ContentResponse response = client.newRequest("localhost", serverConnector.getLocalPort())
+                    .timeout(5, TimeUnit.SECONDS)
+                    // Commenting out EXPECT processing allows the test not to hang.
+                    .headers(headers -> headers.put(HttpHeader.EXPECT, HttpHeaderValue.CONTINUE))
+                    // Hangs with small payloads, 10k won't hang, so test smallest payload.
+                    .body(new BytesRequestContent("a"))
+                    .send();
+            assertEquals(200, response.getStatus());
+            System.out.printf(" %,d%n", System.currentTimeMillis() - start);
+        }
+    }
+
     @Test
     public void testClientRequestSmallContentKnownLengthGzipped() throws Exception
     {

garydgregory avatar Jun 09 '24 18:06 garydgregory

@lorban any insight on this one?

janbartel avatar Jul 10 '24 06:07 janbartel

We started investigating with @sbordet and it looks like there is a race condition in the proxy code. More work is needed to really understand what's going on and to come up with a fix.

Stay tuned.

lorban avatar Jul 12 '24 12:07 lorban

@lorban Thank you for the update! Looking forward to a solution.

garydgregory avatar Jul 12 '24 12:07 garydgregory

@garydgregory I think this issue has been fixed by #12542, where we reworked AsyncMiddleManServlet response writing.

The fix is incorporated in Jetty 12.0.16, which has recently been released.

Can you please test whether this issue is fixed for you? Thanks!

sbordet avatar Dec 12 '24 18:12 sbordet

@sbordet Thank you for the heads up. I will start testing... builds in progress...

garydgregory avatar Dec 12 '24 18:12 garydgregory

Hello @sbordet Our 3 builds are green, so this looks good 👍

garydgregory avatar Dec 13 '24 18:12 garydgregory

Thanks for the feedback, closing this issue.

sbordet avatar Dec 13 '24 19:12 sbordet