Async Content Complete bug results in org.eclipse.jetty.io.EofException: Async closed

[cstamas]

Jetty version
jetty-9.4.24.v20191120; built: 2019-11-20T21:37:49.771Z; git: 363d5f2;

Java version
openjdk version "1.8.0_232"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_232-b09)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.232-b09, mixed mode)

OS type/version
Linux Urnebes 4.15.0-70-generic #79-Ubuntu SMP Tue Nov 12 10:36:11 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
Linux Mint 19.2

Description
Am getting sporadic errors on server side org.eclipse.jetty.io.EofException: Async closed

To reproduce:

Servlet:

package org.cstamas.jetty.bug;

import java.io.ByteArrayInputStream;
import java.io.IOException;
import java.io.InputStream;

import javax.servlet.AsyncContext;
import javax.servlet.ServletOutputStream;
import javax.servlet.WriteListener;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

public class AsyncBugServlet
    extends HttpServlet
{
  private static final byte[] DATA = new byte[100_000_000];

  @Override
  protected void doGet(final HttpServletRequest req, final HttpServletResponse resp)
      throws IOException
  {
    byte[] data = (byte[]) req.getAttribute("data");

    if (data == null) {
      AsyncContext asyncContext = req.startAsync(req, resp);
      new Thread(() -> {
        req.setAttribute("data", DATA);
        asyncContext.dispatch();
      }).start();
    }
    else {
      resp.setContentType("application/octet-bytes");
      resp.setContentLengthLong(data.length);
      ServletOutputStream out = resp.getOutputStream();
      AsyncContext asyncContext = req.startAsync(req, resp);
      out.setWriteListener(new WL(asyncContext, new ByteArrayInputStream(data), out, resp.getBufferSize()));
    }
  }

  private static class WL
      implements WriteListener
  {
    private final AsyncContext asyncContext;

    private final InputStream inputStream;

    private final ServletOutputStream outputStream;

    private final byte[] buffer;

    private WL(final AsyncContext asyncContext,
               final InputStream inputStream,
               final ServletOutputStream outputStream,
               final int bufferSize)
    {
      this.asyncContext = asyncContext;
      this.inputStream = inputStream;
      this.outputStream = outputStream;
      this.buffer = new byte[bufferSize];
    }

    @Override
    public void onWritePossible() throws IOException {
      while (outputStream.isReady()) {
        int len = inputStream.read(buffer);
        if (len < 0) {
          asyncContext.complete();
          close();
          return;
        }
        outputStream.write(buffer, 0, len);
      }
    }

    @Override
    public void onError(final Throwable t) {
      t.printStackTrace();
      asyncContext.complete();
      close();
    }

    private void close() {
      try {
        inputStream.close();
      }
      catch (IOException e) {
        e.printStackTrace();
      }
    }
  }
}

web.xml

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/web-app_3_1.xsd"
         version="3.1">

  <display-name>Jetty bug</display-name>
  <servlet>
    <servlet-name>bug</servlet-name>
    <servlet-class>org.cstamas.jetty.bug.AsyncBugServlet</servlet-class>
    <async-supported>true</async-supported>
  </servlet>
  <servlet-mapping>
    <servlet-name>bug</servlet-name>
    <url-pattern>/</url-pattern>
  </servlet-mapping>
</web-app>

Am using maven jetty:run to run it.

Client side: just fire up several clients, for example:

$ for i in {1..400}; do ((echo -n S$i; curl -s -o /dev/null http://localhost:8080/ ; echo -n E$i) &); done

And server will start spitting out errors:

$ mvn jetty:run
[INFO] Scanning for projects...
[INFO] 
[INFO] --------------------< org.cstamas.jetty:jetty-bug >---------------------
[INFO] Building jetty-bug Maven Webapp 1.0-SNAPSHOT
[INFO] --------------------------------[ war ]---------------------------------
[INFO] 
[INFO] >>> jetty-maven-plugin:9.4.24.v20191120:run (default-cli) > test-compile @ jetty-bug >>>
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:resources (default-resources) @ jetty-bug ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /home/cstamas/tmp/jetty-bug/jetty-bug/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.8.1:compile (default-compile) @ jetty-bug ---
[INFO] Nothing to compile - all classes are up to date
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:testResources (default-testResources) @ jetty-bug ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /home/cstamas/tmp/jetty-bug/jetty-bug/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.8.1:testCompile (default-testCompile) @ jetty-bug ---
[INFO] No sources to compile
[INFO] 
[INFO] <<< jetty-maven-plugin:9.4.24.v20191120:run (default-cli) < test-compile @ jetty-bug <<<
[INFO] 
[INFO] 
[INFO] --- jetty-maven-plugin:9.4.24.v20191120:run (default-cli) @ jetty-bug ---
[INFO] webAppSourceDirectory not set. Trying src/main/webapp
[INFO] Reload Mechanic: automatic
[INFO] nonBlocking:false
[INFO] Classes = /home/cstamas/tmp/jetty-bug/jetty-bug/target/classes
[INFO] Configuring Jetty for project: jetty-bug Maven Webapp
[INFO] Logging initialized @1367ms to org.eclipse.jetty.util.log.Slf4jLog
[INFO] Context path = /
[INFO] Tmp directory = /home/cstamas/tmp/jetty-bug/jetty-bug/target/tmp
[INFO] Web defaults = org/eclipse/jetty/webapp/webdefault.xml
[INFO] Web overrides =  none
[INFO] web.xml file = file:///home/cstamas/tmp/jetty-bug/jetty-bug/src/main/webapp/WEB-INF/web.xml
[INFO] Webapp directory = /home/cstamas/tmp/jetty-bug/jetty-bug/src/main/webapp
[INFO] jetty-9.4.24.v20191120; built: 2019-11-20T21:37:49.771Z; git: 363d5f2df3a8a28de40604320230664b9c793c16; jvm 1.8.0_232-b09
[INFO] JVM Runtime does not support Modules
[INFO] Scanning elapsed time=30ms
[INFO] DefaultSessionIdManager workerName=node0
[INFO] No SessionScavenger set, using defaults
[INFO] node0 Scavenging every 600000ms
[INFO] Started o.e.j.m.p.JettyWebAppContext@365553de{Jetty bug,/,file:///home/cstamas/tmp/jetty-bug/jetty-bug/src/main/webapp/,AVAILABLE}{file:///home/cstamas/tmp/jetty-bug/jetty-bug/src/main/webapp/}
[INFO] Started ServerConnector@6ba7383d{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
[INFO] Started @1882ms
[INFO] Started Jetty Server
org.eclipse.jetty.io.EofException: Async closed
	at org.eclipse.jetty.server.HttpOutput.closed(HttpOutput.java:420)
	at org.eclipse.jetty.server.HttpChannel$SendCallback.succeeded(HttpChannel.java:1199)
	at org.eclipse.jetty.server.HttpConnection$SendCallback.onCompleteSuccess(HttpConnection.java:866)
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:326)
	at org.eclipse.jetty.util.IteratingCallback.succeeded(IteratingCallback.java:366)
	at org.eclipse.jetty.io.WriteFlusher.completeWrite(WriteFlusher.java:394)
	at org.eclipse.jetty.io.ChannelEndPoint$3.run(ChannelEndPoint.java:132)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:298)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
	at java.lang.Thread.run(Thread.java:748)

Am I doing something wrong in servlet?

[joakime]

The reproduction code provided here seems to overlap with ...

• Issue Improve handling of HttpOutput.close() for pending writes #4331 -
• Issue Clarify behaviour after ServletOutputStream.setWriteListener jakartaee/servlet#273

[cstamas]

Unsure, as I do invoke isReady() in between write and complete calls:

    @Override
    public void onWritePossible() throws IOException {
      while (outputStream.isReady()) {
        int len = inputStream.read(buffer);
        if (len < 0) {
          asyncContext.complete();
          close();
          return;
        }
        outputStream.write(buffer, 0, len);
      }
    }

Any other means to figure "is last write done"?

[gregw]

@cstamas I've been able to reproduce and we understand the problem and have a fix.
The issues is that because you set the content length, jetty knows that the response is complete on the last write and is required by the servlet spec to close the output stream.
It so happens that if the very last write happens to cause the output to become UNREADY (isReady returned false), then we are a bit overzealous in where we did the closing and didn't well handle the pending callback to onWritePossible.

The good news is that these exceptions are mostly ignorable... unless you have significant code in your onComplete handling.

Standby for a fix.

[gregw]

PR #4377

[cstamas]

@gregw @joakime cool and thanks for "async fast" 😄 response!

[cstamas]

As I debugged, I assumed as well that those EofExceptions are kinda "ignorable", but would be uneasy to have Jetty in prod that produces logspam, or worse, to have to "mute" Jetty and then maybe miss some important things from Jetty.

So am fine waiting for fix, I guess in 9.4.25?

[cstamas]

Sorry, but this above may be wrong: during tests LB was involved and it seems it was dropping connections.... stay tuned, we will repeat it w/o LB in equation (directly going to Jetty).

Our bad, sorry for noise.

[joakime]

Our bad, sorry for noise.

whew 😌, you had some worried people 😟 over here!

[cstamas]

Just to confirm, load testing on our QA system shows no errors whatsoever (LB left out of equation), so we are fine here. This issue is fixed as far as am concerned, the log noise "Async closed" is gone, actually, we had no errors at all on server/jetty side. Sorry again for hasty report above!

[sbordet]

@cstamas thanks for the feedback! Closing this issue.