Servlet 3.1 ReadListener.onAllDataRead() is called twice under h2 or h2c if the server doesn't respond within 30s

[niloc132]

Jetty version(s)
tested 11.0.8, 11.0.11

Java version/vendor (use: java -version)

$ java -version
openjdk version "11.0.16" 2022-07-19
OpenJDK Runtime Environment (build 11.0.16+8)
OpenJDK 64-Bit Server VM (build 11.0.16+8, mixed mode)

OS type/version
Linux

$ uname -a
Linux runes 5.18.14-arch1-1 #1 SMP PREEMPT_DYNAMIC Sat, 23 Jul 2022 11:46:17 +0000 x86_64 GNU/Linux

Description
Steps to reproduce:

• Run an h2 or h2c (can be reproduced with or without ssl) server
• Host a filter or servlet that starts an async call
• Add a read listener to the call, and validate that onAllDataRead is only hit once
• Do not send a response from the server for 30 seconds - messages sent after this will have no effect.
• Make a call from a client, and "half-close" the request (relying only on server streamed results when they are ready)

Expected behavior is that the onAllDataRead only happens once (immediately after the client half-closes), but the actual behavior is that the listener gets a second onAllDataRead call, 30s after the first one. Note that it seems likely that this value is configuration or platform dependent and if so, the note above about "do not send a response from the server for 30 seconds") likely also depends on this.

Verified with a web browser as a client (note that h2c isn't an option for web browsers, and the bug does not happen with http/1.1), and also with curl commands (with flags to force http2 and allow insecure localhost certs):

• curl -k -XPOST https://localhost:8443/stream
• curl --http2-prior-knowledge -XPOST http://localhost:8080/stream

How to reproduce?
Example servlet:

public class StreamServlet extends HttpServlet {
    private final ScheduledExecutorService executorService = Executors.newSingleThreadScheduledExecutor();

    @Override
    protected void doPost(HttpServletRequest req, HttpServletResponse resp) throws IOException, ServletException {
        // Each time this method is called, create an async stream, and send out updates "periodically"

        AsyncContext asyncContext = req.startAsync();

        // Explicitly setting a long timeout, to ensure this isn't what is causing the 30s delay
        asyncContext.setTimeout(TimeUnit.MINUTES.toMillis(5));

        System.out.println("call started " + new Date());
        req.getInputStream().setReadListener(new ReadListener() {
            private final AtomicBoolean closed = new AtomicBoolean(false);
            @Override
            public void onDataAvailable() throws IOException {
                //ignore
            }

            @Override
            public void onAllDataRead() throws IOException {
                boolean wasOpen = closed.compareAndSet(false, true);
                if (!wasOpen) {
                    System.out.println("Already closed! " + new Date());
//                    throw new IllegalStateException("Already closed!");
                    return;
                }
                System.out.println("all data read " + new Date());
            }

            @Override
            public void onError(Throwable t) {
                t.printStackTrace();
            }
        });
        sendAsyncMessage(asyncContext, 3);
    }

    private void sendAsyncMessage(AsyncContext asyncContext, int count) {
        executorService.schedule(() -> {
            try {
                asyncContext.getResponse().getOutputStream().print("Hello\n");
                asyncContext.getResponse().getOutputStream().flush();

                if (count == 0) {
                    asyncContext.complete();
                } else {
                    sendAsyncMessage(asyncContext, count - 1);
                }
            } catch (IOException e) {
                e.printStackTrace();
            }
        }, 31, TimeUnit.SECONDS);//31 seconds to be slightly longer than the apparent 30s timeout
    }
}

A sample main() that enables both h2c and https, and the above servlet. This expects a app/index.html so a browser can experience the bug as well, also attached below. Note that if the SSL section is enabled, a keystore will be required.

public class Main {

    public static void main(String[] args) throws Exception {
        Server jetty = new Server();

        // https://www.eclipse.org/jetty/documentation/jetty-11/programming-guide/index.html#pg-server-http-connector-protocol-http2-tls
        final HttpConfiguration httpConfig = new HttpConfiguration();
        final HttpConnectionFactory http11 = new HttpConnectionFactory(httpConfig);

        {
            httpConfig.addCustomizer(new SecureRequestCustomizer(false));
            final HTTP2ServerConnectionFactory h2 = new HTTP2ServerConnectionFactory(httpConfig);
            final ALPNServerConnectionFactory alpn = new ALPNServerConnectionFactory();
            alpn.setDefaultProtocol(http11.getProtocol());

            // Configure the SslContextFactory with the keyStore information.
            SslContextFactory.Server sslContextFactory = new SslContextFactory.Server();
            sslContextFactory.setKeyStorePath("keystore.jks");
            sslContextFactory.setKeyStorePassword("secret");

            // The ConnectionFactory for TLS.
            SslConnectionFactory tls = new SslConnectionFactory(sslContextFactory, alpn.getProtocol());
            // The ServerConnector instance.
            ServerConnector connector = new ServerConnector(jetty, tls, alpn, h2, http11);
            connector.setPort(8443);
            jetty.addConnector(connector);
        }

        {
            HTTP2CServerConnectionFactory h2c = new HTTP2CServerConnectionFactory(httpConfig);
            ServerConnector connector = new ServerConnector(jetty, http11, h2c);
            connector.setPort(8080);
            jetty.addConnector(connector);
        }

        // serve contents from resources or jar
        final WebAppContext context = new WebAppContext(null, "/", null, null, null, new ErrorPageErrorHandler(), 0);

        URL index = Main.class.getResource("/app/index.html");
        context.setBaseResource(Resource.newResource(index.toExternalForm().replace("!/app/index.html", "!/")));

        // set up the stream servlet
        context.setContextPath("/");
        context.addServlet(StreamServlet.class, "/stream");
//        context.addFilter(new FilterHolder(new StreamFilter()), "/stream", EnumSet.noneOf(DispatcherType.class));

        jetty.setHandler(context);

        jetty.start();
        System.out.println("Server Started " + Arrays.toString(jetty.getConnectors()));
        jetty.join();
    }
}

Simple HTML file to load the stream and log messages as they arrive:

<!doctype html>
<html>
<head>
    <meta charset="UTF-8">
    <title>Document</title>
</head>
<body>
<script>
    function writeMessage(msg) {
        document.body.append(msg);
    }

    function handleMessage(reader) {
        reader.read().then(payload => {
            var done = payload.done;
            var value = new TextDecoder().decode(payload.value);
            document.body.append(value, document.createElement('br'));
            if (done) {
                document.body.append("Done.", document.createElement('hr'));
            } else {
                handleMessage(reader);
            }
        });
    }

    fetch('/stream', {method:'POST'}).then(result => {
        handleMessage(result.body.getReader());
    });
</script>

</body>
</html>

[joakime]

Looks like grpc added support for Jetty Servlet 4+ (javax and jakarta) but are hitting this as a bug.
See grpc/grpc-java#1621

[niloc132]

It looks as though this is related to HTTP2Session.streamIdleTimeout, but still fails in a confusing way. If this value is set explicitly to zero/negative, then this bug no longer occurs. Note however (will document in a follow-up ticket) that it isn't possible to directly set this to zero/negative via AbstractHTTP2ServerConnectionFactory.streamIdleTimeout, as AbstractHTTP2ServerConnectionFactory.newConnection will not pass the value to the session unless it is greater than zero.

Setting the stream idle timeout to very large values will presumably just delay the time until the unexpected behavior takes place.

[sbordet]

@niloc132 thank you for the detailed report, it is indeed a bug. Standby for a fix.

[sbordet]

@niloc132 I have a fix at #10174.

Would you be able to try it out and confirm the issue is solved for you?