Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8304701

Request with timeout aborts later in-flight request on HTTP/1.1 cxn

XMLWordPrintable

    • b26
    • generic
    • generic
    • Verified

      ADDITIONAL SYSTEM INFORMATION :
      macOS 12.6.3 (21G419)
      openjdk version "20" 2023-03-21
      OpenJDK Runtime Environment (build 20+36-2344)
      OpenJDK 64-Bit Server VM (build 20+36-2344, mixed mode, sharing)

      A DESCRIPTION OF THE PROBLEM :
      This was originally encountered and reported as https://github.com/SeleniumHQ/selenium/issues/11798, until it was determined to be a JDK issue.

      When an java.net.http.HttpRequest is sent with a specific timeout over a persistent HTTP/1.1 connection, the ResponseTimerEvent appears to be unconditionally handle()'d once its deadline elapses (regardless of whether
      the request has completed), forcing the connection to be promptly and unnecessarily closed. If there is another request in-flight on the connection at this moment, then it will fail with a "java.io.IOException: connection closed locally" error.

      This issue is readily reproducible by sending requests in a tight loop to a server with non-trivial latency or that returns a large response having a non-trivial transfer time. This issue does appear to arise with HTTP/2 connections or if the connection is idle at the moment the timer elapses.

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      javac JavaExample.java && java JavaExample

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      The process should run to completion with a few successful requests over ~15 seconds.
      ACTUAL -
      The process sends a few successful requests, but at ~10 seconds throws an exception like:
      ```
      Exception in thread "main" java.io.IOException: fixed content-length: 28490775, bytes received: 17112264
      at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
      at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
      at example.JavaExample.main(JavaExample.java:28)
      Caused by: java.io.IOException: fixed content-length: 28490775, bytes received: 17112264
      at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:351)
      at java.net.http/jdk.internal.net.http.Http1Response$BodyReader.onReadError(Http1Response.java:760)
      at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
      at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
      at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
      at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
      at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
      at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.io.IOException: connection closed locally
      at java.net.http/jdk.internal.net.http.SocketTube.signalClosed(SocketTube.java:159)
      at java.net.http/jdk.internal.net.http.PlainHttpConnection.close(PlainHttpConnection.java:372)
      at java.net.http/jdk.internal.net.http.AsyncSSLConnection.close(AsyncSSLConnection.java:111)
      at java.net.http/jdk.internal.net.http.Http1Exchange.cancelImpl(Http1Exchange.java:492)
      at java.net.http/jdk.internal.net.http.Http1Exchange.cancel(Http1Exchange.java:427)
      at java.net.http/jdk.internal.net.http.Exchange.cancel(Exchange.java:238)
      at java.net.http/jdk.internal.net.http.MultiExchange.cancel(MultiExchange.java:260)
      at java.net.http/jdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:71)
      at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)
      at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)
      ```

      ---------- BEGIN SOURCE ----------
      import java.net.URI;
      import java.net.http.HttpClient;
      import java.net.http.HttpRequest;
      import java.net.http.HttpResponse;
      import java.time.Duration;
      import java.time.Instant;

      import static java.net.http.HttpClient.Redirect.ALWAYS;
      import static java.net.http.HttpClient.Version.HTTP_1_1;

      public class JavaExample {

          public static void main(String[] args) throws Exception {
              int timeoutSeconds = 10;

              HttpClient client = HttpClient.newBuilder()
                      .followRedirects(ALWAYS)
                      .build();

              for (Instant start = Instant.now(), now = start; now.isBefore(start.plusSeconds(timeoutSeconds * 3 / 2)); now = Instant.now()) {
                  HttpRequest request = HttpRequest.newBuilder().uri(URI.create("https://github.com/SeleniumHQ/selenium/releases/download/selenium-4.8.0/selenium-java-4.8.1.zip"))
                          .GET()
                          .version(HTTP_1_1)
                          .timeout(Duration.ofSeconds(timeoutSeconds))
                          .build();
                  HttpResponse<Void> response = client.send(request, HttpResponse.BodyHandlers.discarding());
                  System.out.println(now + " -> " + response.headers().firstValue("date"));
              }
          }
      }
      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      Use HTTP/2 if available
      Add "Connection: close" header to request if possible (requires jdk.httpclient.allowRestrictedHeaders customization)
      Avoid using request timeouts if feasible


      FREQUENCY : often


            ccleary Conor Cleary (Inactive)
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: