search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.86k stars 1.91k forks source link

Jetty 12 ee9/ee10 doesn't invoke callbacks when h2 client sends RST_STREAM #12313

Closed niloc132 closed 3 weeks ago

niloc132 commented 1 month ago

Jetty version(s) Compared Jetty 12.0.13 with Jetty 11.0.24

Jetty Environment Tested EE9 and EE10

Java version/vendor

$ java -version
openjdk version "21.0.4" 2024-07-16
OpenJDK Runtime Environment (build 21.0.4+7)
OpenJDK 64-Bit Server VM (build 21.0.4+7, mixed mode, sharing)

OS type/version

$ uname -a
Linux runes 6.10.4-arch2-1 #1 SMP PREEMPT_DYNAMIC Sun, 11 Aug 2024 16:19:06 +0000 x86_64 GNU/Linux

Description

When an h2 client disconnects from an async servlet by sending RST_STREAM, Jetty 11 (and earlier) would invoke onError callbacks. It seems that this no longer happens in Jetty 12 - you either have to try to write and see if it works, or wait for a timeout. The Jetty 12 behavior is slightly different for ee9 and ee10 - I believe both are wrong, but might be misinterpreting how a servlet implementation should handle this case?

I created an example async servlet that logs each event it receives, and compared behavior when a client connects, some content streamed back and forth, and the client disconnecting from the server with a RST_STREAM(CANCEL).

After that RST_STREAM, Jetty11 calls ReadListener.onError immediately. This seems reasonable to me, but I don't see an obvious reason in the spec that the AsyncListener.onError couldn't be called instead. 

137 [main] INFO org.eclipse.jetty.server.Server - jetty-11.0.24; built: 2024-08-26T18:11:22.448Z; git: 5dfc59a691b748796f922208956bd1f2794bcd16; jvm 21.0.4+7
207 [main] INFO org.eclipse.jetty.server.session.DefaultSessionIdManager - Session workerName=node0
221 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@588df31b{/,null,AVAILABLE}
229 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@16b4a017{h2c, (h2c)}{0.0.0.0:10000}
254 [main] INFO org.eclipse.jetty.server.Server - Started Server@68c4039c{STARTING}[11.0.24,sto=0] @320ms
4572 [qtp610998173-33] INFO com.example.servlet.AsyncStreamingServlet - New request #0
4573 [qtp610998173-33] INFO com.example.servlet.AsyncStreamingServlet - AllDataRead #0
4574 [qtp610998173-33] INFO com.example.servlet.AsyncStreamingServlet - WritePossible #0
5133 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
6133 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
7133 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
7438 [qtp610998173-49] INFO com.example.servlet.AsyncStreamingServlet - Read Error #0
7440 [qtp610998173-49] INFO com.example.servlet.AsyncStreamingServlet - Complete #0

Under Jetty 12/EE9, instead there is no error when the RST_STREAM occurs, but instead WriteListener.onError is invoked on the first write by the server. This seems suspect, since it could be some time in a bidirectional stream before the server needs to send a message. Instead, the ReadListener probably should have its onError called, or possibly the AsyncListener.onError (and the caller probably then should avoid writing to begin with).

281 [main] INFO org.eclipse.jetty.server.Server - jetty-12.0.13; built: 2024-09-03T03:04:05.240Z; git: 816018a420329c1cacd4116799cda8c8c60a57cd; jvm 21.0.4+7
324 [main] INFO org.eclipse.jetty.session.DefaultSessionIdManager - Session workerName=node0
343 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started oeje9n.ContextHandler$CoreContextHandler@7bb58ca3{ROOT,/,b=null,a=AVAILABLE,h=oeje9n.ContextHandler$CoreContextHandler$CoreToNestedHandler@c540f5a{STARTED}}
362 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@3ec300f1{h2c, (h2c)}{0.0.0.0:10000}
377 [main] INFO org.eclipse.jetty.server.Server - Started oejs.Server@480bdb19{STARTING}[12.0.13,sto=0] @439ms
4487 [qtp314337396-70] INFO com.example.servlet.AsyncStreamingServlet - New request #0
4490 [qtp314337396-70] INFO com.example.servlet.AsyncStreamingServlet - AllDataRead #0
4490 [qtp314337396-70] INFO com.example.servlet.AsyncStreamingServlet - WritePossible #0
5278 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
6278 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
7277 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
8277 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
8279 [qtp314337396-70] INFO com.example.servlet.AsyncStreamingServlet - Write Error #0
8281 [qtp314337396-70] INFO com.example.servlet.AsyncStreamingServlet - Complete #0

Under Jetty 12/EE10, the error is a synchronously thrown exception - thrown by the ServletOutputStream.print/write calls. This seems to be different from servlet 3.1-9 implementation that I've worked with. Instead, as with Jetty 12/EE9, if the AsyncListener/ReadListener had one of their onError callbacks invoked, the writer could have known not to call to begin with.

267 [main] INFO org.eclipse.jetty.server.Server - jetty-12.0.13; built: 2024-09-03T03:04:05.240Z; git: 816018a420329c1cacd4116799cda8c8c60a57cd; jvm 21.0.4+7
310 [main] INFO org.eclipse.jetty.session.DefaultSessionIdManager - Session workerName=node0
325 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started oeje10s.ServletContextHandler@dd3b207{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@551bdc27{STARTED}}
329 [main] INFO org.eclipse.jetty.ee10.servlet.ServletContextHandler - Started oeje10s.ServletContextHandler@dd3b207{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@551bdc27{STARTED}}
346 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@400cff1a{h2c, (h2c)}{0.0.0.0:10000}
360 [main] INFO org.eclipse.jetty.server.Server - Started oejs.Server@646d64ab{STARTING}[12.0.13,sto=0] @424ms
4792 [qtp1634198-69] INFO com.example.servlet.AsyncStreamingServlet - New request #0
4795 [qtp1634198-69] INFO com.example.servlet.AsyncStreamingServlet - AllDataRead #0
4795 [qtp1634198-69] INFO com.example.servlet.AsyncStreamingServlet - WritePossible #0
5264 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
6264 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
7264 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
8264 [pool-1-thread-1] INFO com.example.servlet.AsyncStreamingServlet - Hello
8264 [pool-1-thread-1] WARN com.example.jetty12.ee10.Server - Error writing in exec service
java.io.UncheckedIOException: java.io.IOException: Closed
        at com.example.servlet.AsyncStreamingServlet$ClientConnection.println(AsyncStreamingServlet.java:117)
        at com.example.servlet.AsyncStreamingServlet.sayHi(AsyncStreamingServlet.java:142)
        at com.example.jetty12.ee10.Server.lambda$main$0(Server.java:39)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.io.IOException: Closed
        at org.eclipse.jetty.ee10.servlet.HttpOutput.print(HttpOutput.java:1018)
        at org.eclipse.jetty.ee10.servlet.HttpOutput.println(HttpOutput.java:1012)
        at com.example.servlet.AsyncStreamingServlet$ClientConnection.println(AsyncStreamingServlet.java:110)
        ... 8 more

For all three, the wire traffic is effectively the same, captured via wireshark - run in the same order as described above. This is to say that there doesn't seem to be any sort of bug outside of how Jetty notifies the running servlet that the error has occurred. screenshot921

How to reproduce? https://github.com/niloc132/jetty-stream-reset/tree/jetty-12313

The linked project contains some gradle setup to use the current latest releases of Jetty 11 and 12, and a simple Jetty 12 based client that will connect to any of them. The basis of the example is this servlet:

public class AsyncStreamingServlet extends HttpServlet {
    private static final Logger LOG = LoggerFactory.getLogger(AsyncStreamingServlet.class);

    private final List<ClientConnection> connections = Collections.synchronizedList(new ArrayList<>());
    private final AtomicInteger nextId = new AtomicInteger(0);

    private final class ClientConnection {
        private final AsyncContext ctx;
        private final ServletInputStream in;
        private final ServletOutputStream out;

        private ClientConnection(int id, AsyncContext ctx) throws IOException {
            this.ctx = ctx;
            in = ctx.getRequest().getInputStream();
            out = ctx.getResponse().getOutputStream();
            ctx.addListener(new AsyncListener() {
                @Override
                public void onComplete(AsyncEvent asyncEvent) throws IOException {
                    LOG.info("Complete #" + id);
                }

                @Override
                public void onTimeout(AsyncEvent asyncEvent) throws IOException {
                    LOG.info("Timeout #" + id);
                }

                @Override
                public void onError(AsyncEvent asyncEvent) throws IOException {
                    LOG.info("Error #" + id);
                    connections.remove(ClientConnection.this);
                    ctx.complete();
                }

                @Override
                public void onStartAsync(AsyncEvent asyncEvent) throws IOException {
                    LOG.info("Start #" + id);
                }
            });
            in.setReadListener(new ReadListener() {
                @Override
                public void onDataAvailable() throws IOException {
                    int total = 0;
                    byte[] bytes = new byte[1024];
                    while (in.isReady()) {
                        int read = in.read(bytes);
                        total += read;
                    }
                    LOG.info("DataAvailable #" + id + ", " + total + "bytes");
                }

                @Override
                public void onAllDataRead() throws IOException {
                    LOG.info("AllDataRead #" + id);
                }

                @Override
                public void onError(Throwable throwable) {
                    LOG.info("Read Error #" + id);
                    connections.remove(ClientConnection.this);
                    ctx.complete();
                }
            });

            out.setWriteListener(new WriteListener() {
                @Override
                public void onWritePossible() throws IOException {
                    LOG.info("WritePossible #" + id);
                }

                @Override
                public void onError(Throwable t) {
                    LOG.info("Write Error #" + id);
                    connections.remove(ClientConnection.this);
                    ctx.complete();
                }
            });
        }

        public void close() {
            ctx.complete();
        }

        public void println(String msg) {
            try {
                if (out.isReady()) {
                    LOG.info(msg);
                    out.println(msg);
                    if (out.isReady()) {
                        out.flush();
                    }
                } // else normally we'd enqueue
            } catch (IOException e) {
                connections.remove(ClientConnection.this);
                throw new UncheckedIOException(e);
            }
        }
    }

    @Override
    protected void doPost(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        doGet(req, resp);
    }

    @Override
    protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        AsyncContext asyncCtx = req.startAsync(req, resp);
        asyncCtx.setTimeout(10_000);

        final int id = nextId.getAndIncrement();

        LOG.info("New request #" + id);

        ClientConnection c = new ClientConnection(id, asyncCtx);
        connections.add(c);
    }

    public void sayHi() {
        for (ClientConnection client : connections) {
            client.println("Hello");
        }
    }
}

Each of the three server impls in the repo has this same body, with only changes made for the jakarta servlet package changes between releases/environments:

public class Server {
    private static final Logger LOG = LoggerFactory.getLogger(Server.class);

    public static void main(String[] args) throws Exception {
        org.eclipse.jetty.server.Server s = new org.eclipse.jetty.server.Server();
        HttpConfiguration httpConfiguration = new HttpConfiguration();

        HTTP2CServerConnectionFactory factory = new HTTP2CServerConnectionFactory(httpConfiguration);
        ServerConnector sc = new ServerConnector(s, factory);
        sc.setPort(10000);

        s.setConnectors(new Connector[] { sc });

        ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS);
        context.setContextPath("/");
        AsyncStreamingServlet servlet = new AsyncStreamingServlet();
        context.addServlet(new ServletHolder(servlet), "/connect");
        s.setHandler(context);

        ScheduledExecutorService executorService = Executors.newSingleThreadScheduledExecutor();
        executorService.scheduleAtFixedRate(() -> {
            try {
                servlet.sayHi();
            } catch (Exception e) {
                // log and continue
                LOG.warn("Error writing in exec service", e);
            }
        }, 1, 1, TimeUnit.SECONDS);

        s.start();
        s.join();
    }
}

Note that this client uses h2c, but this behavior is observed in h2 (with tls) as well, which is how it was first observed.

The client in turn is simple, half closing after sending a simple payload:

public class Client {
    private static final Logger LOG = LoggerFactory.getLogger(Client.class);

    public static void main(String[] args) throws Exception {
        HttpClient client = new HttpClient(new HttpClientTransportOverHTTP2(new HTTP2Client()));
        client.start();
        Request post = client.POST("http://localhost:10000/connect");

        BufferingResponseListener listener = new BufferingResponseListener() {
            @Override
            public void onComplete(Result result) {
                LOG.info("Complete");
            }
        };

        post.send(listener);
        // wait three seconds, take what we get and get out
        Thread.sleep(3000);
        byte[] content = listener.getContent();
        System.out.println(new String(content, StandardCharsets.UTF_8));

        post.abort(new Exception());

        System.exit(0);
    }
}
niloc132 commented 1 month ago

Any triage/response for this, given the pending EOL on Jetty 11? We're trying to follow the Jetty team's advice and migrate away ASAP, but this seems like a pretty egregious bug.

sbordet commented 1 month ago

I'm looking into this.

sbordet commented 1 month ago

What happens on the server:

http2's onReset()
  HttpChannelState.onFailure() => generates a Runnable
    Runnable invokes failure listener registered in ServletChannelState.startAsync()
      ServletChannelState.asyncError()
        ServletChannel.handle(), case ASYNC_ERROR, that just rethrows
          ServletChannel.handleException() => if committed abort() else onError()

The last frame shows that we do not call AsyncContext.onError() but rather we just abort the response.

The abort will in turn cause ServletChannel.handle() to loop around, hit case TERMINATED, and then ServletChannel.onCompleted().

@niloc132 Jetty 11's behavior is wrong, as obviously the ReadListener has already been notified of onAllDataRead() so there is no point notifying of some other, non-read related, error.

The correct behavior would be to notify AsyncListener.onError(), but applications needs to be very careful there, as the response is already committed, so many operations would throw IllegalStateException, for example adding headers, etc.

Note also that your use case is racy by nature: if you have a failure arriving at exactly the same time you are writing, you may see WriteListener.onError() being called or an exception thrown while trying to write.

sbordet commented 1 month ago

Regarding writes, Jetty 12 EE10 behavior is the correct one.

In Jetty 12 EE10, after 3 seconds the response is aborted and the ServletChannel recycled by a CompletionListener registered in ServletContextHandler.wrapRequest(); at 4 seconds there is another write that is a "write after recycle" and it correctly throws.

In Jetty 12 EE9 the HttpChannel is not recycled, so the WriteListener is erroneously notified.

niloc132 commented 1 month ago

To confirm, I do consider it correct that if the client half closes (on a DATA or HEAD, onAllDataRead() is called. However, if the client closes the stream unilaterally via RST_STREAM, you're saying that Jetty12EE10 is correct in never notifying the application because some applications may misinterpret it?

I'm specifically not asking "is it correct that a write will cause an error", but "is it correct that a closed h2 stream will never result in notification on the server". That's the breakage here - I think I agree that Jetty 10/11 calling ReadListener.onError is technically wrong, but not getting any notification is far worse, and will prevent Jetty from being used as a gRPC server (along I'm sure with other use cases). If the write doesn't happen immediately, this bug transforms from "it is weird that I get this error now" to "we never get any notification that the client is gone".

Note also that your use case is racy by nature: if you have a failure arriving at exactly the same time you are writing, you may see WriteListener.onError() being called or an exception thrown while trying to write. The use case is certainly racy, but in Jetty 10/11 and 12+ee9 the async writes do result in async errors, rather than synchronous errors, so I definitely consider 11 to be "least wrong" of the options so far, followed closely by 12+ee9. That is, I'm not asking about the races, but about the clearly-unracy code, where the client ends the connection, and the server can't tell.

I don't want to discount the need for handling a race, only to emphasize that this bug isn't about races, just about the failure of the server to notify the servlet and its listeners that the connection is dead (and in some cases, has been for many seconds, see below), without any possibility for a race.

In Jetty 12 EE10, after 3 seconds the response is aborted and the ServletChannel recycled by a CompletionListener registered in ServletContextHandler.wrapRequest(); at 4 seconds there is another write that is a "write after recycle" and it correctly throws.

I modified the example to not send payloads on a timer (emulating a case where the response won't be ready for some time, and the RST_STREAM is expected to be able to cancel no longer needed work). Jetty 12+EE9 will immediately call AsyncListener.onError, so that's good. I also increased the timeout from 10s to 100s to ensure that there was no chance of it interfering with the 3/4 second checks you mentioned, and then had the server write a response immediately, so that the server is effectively waiting on the client to send its next message, and thus must know if the client is still there. (EDIT: changes added in this commit: https://github.com/niloc132/jetty-stream-reset/commit/0646f88)

In Jetty 12 EE9, we wait a little over 100 seconds after the start of the call (that delay could account for the extra three seconds that the client delays before sending RST_STREAM? Again, this means that the server saw the RST_STREAM, but explicitly reset the timeout delay until that many seconds after the stream was terminated?

300 [main] INFO org.eclipse.jetty.server.Server - jetty-12.0.13; built: 2024-09-03T03:04:05.240Z; git: 816018a420329c1cacd4116799cda8c8c60a57cd; jvm 21.0.4+7
350 [main] INFO org.eclipse.jetty.session.DefaultSessionIdManager - Session workerName=node0
373 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started oeje9n.ContextHandler$CoreContextHandler@29ba4338{ROOT,/,b=null,a=AVAILABLE,h=oeje9n.ContextHandler$CoreContextHandler$CoreToNestedHandler@57175e74{STARTED}}
391 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@1b083826{h2c, (h2c)}{0.0.0.0:10000}
407 [main] INFO org.eclipse.jetty.server.Server - Started oejs.Server@76b0bfab{STARTING}[12.0.13,sto=0] @487ms
121613 [qtp314337396-68] INFO com.example.servlet.AsyncStreamingServlet - New request #0
121616 [qtp314337396-68] INFO com.example.servlet.AsyncStreamingServlet - startup
121620 [qtp314337396-68] INFO com.example.servlet.AsyncStreamingServlet - AllDataRead #0
121620 [qtp314337396-68] INFO com.example.servlet.AsyncStreamingServlet - WritePossible #0
224466 [qtp314337396-69] INFO com.example.servlet.AsyncStreamingServlet - Timeout #0
224466 [qtp314337396-69] WARN org.eclipse.jetty.util.thread.QueuedThreadPool - Job failed
java.lang.IllegalStateException: ABORTED
        at org.eclipse.jetty.ee9.nested.HttpChannelState.sendError(HttpChannelState.java:930)
        at org.eclipse.jetty.ee9.nested.HttpChannelState.nextAction(HttpChannelState.java:505)
        at org.eclipse.jetty.ee9.nested.HttpChannelState.unhandle(HttpChannelState.java:430)
        at org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:656)
        at org.eclipse.jetty.ee9.nested.HttpChannel.run(HttpChannel.java:470)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
        at java.base/java.lang.Thread.run(Thread.java:1583)

In Jetty 12 EE10, no errors occurred at all - there are no notifications at all to the server that the client is gone (since the server is waiting for the client's next message, which never comes because the stream is closed.

257 [main] INFO org.eclipse.jetty.server.Server - jetty-12.0.13; built: 2024-09-03T03:04:05.240Z; git: 816018a420329c1cacd4116799cda8c8c60a57cd; jvm 21.0.4+7
302 [main] INFO org.eclipse.jetty.session.DefaultSessionIdManager - Session workerName=node0
316 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started oeje10s.ServletContextHandler@23a5fd2{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@78a2da20{STARTED}}
319 [main] INFO org.eclipse.jetty.ee10.servlet.ServletContextHandler - Started oeje10s.ServletContextHandler@23a5fd2{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@78a2da20{STARTED}}
335 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@55040f2f{h2c, (h2c)}{0.0.0.0:10000}
348 [main] INFO org.eclipse.jetty.server.Server - Started oejs.Server@6acdbdf5{STARTING}[12.0.13,sto=0] @410ms
8587 [qtp1634198-32] INFO com.example.servlet.AsyncStreamingServlet - New request #0
8589 [qtp1634198-32] INFO com.example.servlet.AsyncStreamingServlet - startup
8595 [qtp1634198-32] INFO com.example.servlet.AsyncStreamingServlet - AllDataRead #0
8595 [qtp1634198-32] INFO com.example.servlet.AsyncStreamingServlet - WritePossible #0

I manually shut down the server after 30 minutes of no notification.

Neither of these outcomes are ideal - even if timeouts are set, we are required to send application-level messages to keep the stream alive, and the timeout has to be low enough to catch this lack of message, but high enough to avoid requiring sending no-op messages every second or whatnot. The fact that ee10 further never alerts on timeouts sounds like a separate bug...

sbordet commented 1 month ago

@niloc132 can you try #12370 and report back if it fixed the problem for you?

niloc132 commented 1 month ago

Thank you - I've built locally and can confirm that this issue appears to be resolved. I had a follow-up issue that we had experienced with Jetty 10/11 (AsyncContext.complete() seems to send RST_STREAM with error='cancel' instead of error='no error'), but that appears to also be resolved in Jetty 12.

We'll continue our testing with the 12.0.15 release when available, but I'll run more grpc-java integration test locally to see if I can confirm that this snapshot passes other test too.

Thanks again for the quick patch!

sbordet commented 1 month ago

@niloc132 just to be clear, I agree that upon receiving a RST_STREAM from the client, it must be notified to the server. Actually, this behavior is configurable via HttpConfiguration.setNotifyRemoteAsyncErrors() which defaults to true.

There is actually a big hole in the specification about how exactly notify the application, see https://github.com/jakartaee/servlet/issues/433.

We'll try to do the right thing with the PR associated to this issue, so thanks for testing it.

niloc132 commented 1 month ago

Sorry for the misunderstanding on my part, I understand now that you were trying to acknowledge the issue but also point out that a race was possible (and must still be defended against). I'll follow that PR and re-test when merged, and when the release goes out.

Aside, the RST_STREAM(cancel) issue is not fixed, I just tested it incorrectly before. We've confirmed that tomcat and undertow don't have this "bug", but it may well be a difference of interpretation in the spec - I'll try to write this up clearly as a separate Jetty issue, and go from there.

Thanks again for your help with this bug.

sbordet commented 1 month ago

@niloc132 can you please elaborate on your testing results?

I ask because now we have an explicit test that verifies that onError() is called, so Jetty should behave like Tomcat and Undertow. Thanks!

niloc132 commented 1 month ago

I'm sorry, that should have been more clear.

I can confirm that with the linked PR, the example project behaves as I would expect in Jetty 12 EE9 and EE10 - AsyncListener.onError is called (where in Jetty 11 ReadListener.onError was previously called). I tested this with and without trying to write while waiting for the stream to be canceled by the client.

Additionally, I can confirm that this patch works in our project, and resolves the issue there as well.

I will file a separate issue for the other RST_STREAM confusion I am having, which may well be simply due to ambiguity in the spec.

wendigo commented 3 weeks ago

I've tested this in our case and this eliminates a lot of warnings that we were getting from jersey when client aborted suspended requests in our code. Thanks!

basil commented 1 week ago

@sbordet After upgrading Jenkins from Jetty 12.0.14 (EE 9) to Jetty 12.0.15 (EE 9) in https://github.com/jenkinsci/jenkins/pull/9951, #12397 is resolved, but I am now seeing a different change in behavior when running under HTTP/2. I now see the following stack traces logged at warning level when browsing in the Jenkins UI:

Stack traces 
2024-11-07 17:29:08.375+0000 [id=91]        WARNING        o.e.jetty.ee9.nested.HttpChannel#handleException: /static/c673cd5a/favicon.svg
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)
2024-11-07 17:29:08.376+0000 [id=34]        WARNING        o.e.jetty.ee9.nested.HttpChannel#handleException: /static/c673cd5a/apple-touch-icon.png
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:575)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)
2024-11-07 17:29:08.376+0000 [id=91]        WARNING        o.e.j.e.nested.HttpChannelState#onError: onError not handled due to invalid requestState s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)
2024-11-07 17:29:08.376+0000 [id=34]        WARNING        o.e.j.e.nested.HttpChannelState#onError: onError not handled due to invalid requestState s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:575)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)

The warnings are not related to gzip compression, as they appear whether or not GzipHandler is enabled.

I bisected this change in behavior to jetty/jetty.project@f48be0d8fcac6a714c6200f2dbd94d83bc927aea, part of this issue and #12370. The warning can be reproduced by building Jenkins with the new version of Winstone/Jetty and browsing from one project to another in the Jenkins UI.

I am not sure what to make of this, but I do not think we should ship this update to users before this change in behavior is understood.