java.lang.IllegalStateException: Committed

[mperktold]

trafficstars

Jetty version(s) 12.0.18 12.0.16

Jetty Environment core

Java version/vendor (use: java -version) OpenJDK 64-Bit Server VM Temurin-21.0.6+7 (build 21.0.6+7-LTS, mixed mode, sharing)

OS type/version Windows 11

Description In our production logs, the following Exception appears quite often:

java.lang.IllegalStateException: Committed
    at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send(HttpConnection.java:1410)
    at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.write(HttpChannelState.java:1300)
    at org.eclipse.jetty.io.content.ContentSinkOutputStream.write(ContentSinkOutputStream.java:54)
    at it/prodata/util/io/StdByteArrayOutputStream.writeTo (Ljava/io/OutputStream;)V(Unknown Source)
    at it/prodata/communication/www/WebServiceHttpHandler.handlePostRequest (LNee;)V(Unknown Source)
    at it/prodata/communication/www/WebServiceHttpHandler.handle (LNee;)Z(Unknown Source)
    at it/prodata/communication/www/StdHttpHandler.handle (Lorg/eclipse/jetty/server/Request;Lorg/eclipse/jetty/server/Response;Lorg/eclipse/jetty/util/Callback;)Z(Unknown Source)
    at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:611)
    at it/prodata/service/JettyManagerService$MainHandler.handle (LNee;)Z(Unknown Source)
    at it/prodata/service/JettyManagerService$MainHandler.handle (Lorg/eclipse/jetty/server/Request;Lorg/eclipse/jetty/server/Response;Lorg/eclipse/jetty/util/Callback;)Z(Unknown Source)
    at org.eclipse.jetty.server.Server.handle(Server.java:182)
    at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:418)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:480)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:443)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    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(Unknown Source)
    Suppressed: java.io.IOException: java.lang.IllegalStateException: Committed
        at org.eclipse.jetty.io.content.ContentSinkOutputStream.handleException(ContentSinkOutputStream.java:99)
        at org.eclipse.jetty.io.content.ContentSinkOutputStream.close(ContentSinkOutputStream.java:87)
        ... 21 more
    Suppressed: org.eclipse.jetty.server.internal.HttpConnection$HttpEofException: Early EOF
        at org.eclipse.jetty.server.internal.HttpConnection$RequestHandler.earlyEOF(HttpConnection.java:1057)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1753)
        at org.eclipse.jetty.server.internal.HttpConnection.parseRequestBuffer(HttpConnection.java:579)
        at org.eclipse.jetty.server.internal.HttpConnection.parseAndFillForContent(HttpConnection.java:506)
        at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.demand(HttpConnection.java:1373)
        at org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.lambda$demand$0(HttpChannelState.java:1004)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture.whenComplete(Unknown Source)
        at org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.demand(HttpChannelState.java:1004)
        at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:908)
        at org.eclipse.jetty.io.content.ContentSourceInputStream.read(ContentSourceInputStream.java:92)
        at com.sun.xml.messaging.saaj.util.ByteOutputStream.write(ByteOutputStream.java:66)
        at com.sun.xml.messaging.saaj.util.JAXMStreamSource.<init>(JAXMStreamSource.java:45)
        at com.sun.xml.messaging.saaj.soap.SOAPPartImpl.setContent(SOAPPartImpl.java:255)
        at com.sun.xml.messaging.saaj.soap.MessageImpl.init(MessageImpl.java:413)
        at com.sun.xml.messaging.saaj.soap.MessageImpl.<init>(MessageImpl.java:306)
        at com.sun.xml.messaging.saaj.soap.ver1_1.Message1_1Impl.<init>(Message1_1Impl.java:47)
        at com.sun.xml.messaging.saaj.soap.ver1_1.SOAPMessageFactory1_1Impl.createMessage(SOAPMessageFactory1_1Impl.java:51)
        ... 21 more

This is from a Handler that uses SAAJ to implement a SOAP service. It first reads all the request content into a byte array, converts that to a SOAP request and passes it to a handler that creates a SOAP response. This response is also first written to a byte array, then the array is written to the Jetty response.

This writing of the byte array to the Jetty response sometimes fails with the above exception.

I understand this exception means that the response has already been sent, and this write attempt effectively tries to send the same response again, which is not possible.

But I don't understand how that is possible in this case. I've checked the code and I'm pretty sure that no write attempts are made prior to this call, nor does any part call the handler's callback parameter.

Is there any other way to get this error?

How to reproduce? Unfortunately, I am not able to reproduce. There is also an error regarding early EOF, so I tried triggering that with a bad client, but that doesn't give me the other error. It's also the last suppressed exception, so it probably happens afterwards and is not really related.

[joakime]

The code for org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send(HttpConnection.java:1410) shows ...

https://github.com/jetty/jetty.project/blob/09e23e17430c08ed812993bebc9526dd3e67822a/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/internal/HttpConnection.java#L1407-L1411

So, this is an HTTP/1.0 connection / request. - why? And the response header for Connection: keep-alive is attempting to be set. But it cannot set it as the response is already committed when it gets to that code.

[mperktold]

Sorry I messed up the Jetty version. The production environment where this happens is still on 12.0.16.

So it's actually this line in HttpConnection.HttpStreamOverHTTP1.send: https://github.com/jetty/jetty.project/blob/c3f88bafb4e393f23204dc14dc57b042e84debc7/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/internal/HttpConnection.java#L1410

[janbartel]

@mperktold any progress on this one? I can't really tell enough from the elided stack trace you posted, but could it be that the app is trying to read the content of a post request where the input stream returns EOF prematurely and then tries to write the response out anyway to a closed stream/connection?

[mperktold]

@janbartel not really, no.

I can't really tell enough from the elided stack trace you posted

The suppressed exceptions all come from the same stack as the original exception as they are thrown synchronously. From WebServiceHttpHandler.handlePostRequest downwards, the stack should be the same.

could it be that the app is trying to read the content of a post request where the input stream returns EOF prematurely and then tries to write the response out anyway to a closed stream/connection?

That was my thinking as well, but I can't replicate by using a misbehaving client. Digging into Jetty code, I've also come to the conclusion that the response is only ever committed when the callback is invoked or an exception is thrown from the handler. Getting an EOF while reading doesn't seem to commit the response by itself.

[janbartel]

could it be that the app is trying to read the content of a post request where the input stream returns EOF prematurely and then tries to write the response out anyway to a closed stream/connection?

That was my thinking as well, but I can't replicate by using a misbehaving client. Digging into Jetty code, I've also come to the conclusion that the response is only ever committed when the callback is invoked or an exception is thrown from the handler. Getting an EOF while reading doesn't seem to commit the response by itself.

It's not necessarily that the response is committed, as such. See the code here: https://github.com/jetty/jetty.project/blob/c3f88bafb4e393f23204dc14dc57b042e84debc7/jetty-core/jetty-http/src/main/java/org/eclipse/jetty/http/HttpGenerator.java#L132 It's really testing whether the response is committed, or closing/closed. I'm guessing that it could be closed due to whatever caused the EOF on the inputstream?

[mperktold]

@janbartel Good catch!

Unfortunately, I still can't reproduce the case where isCommitted returns false before sending the response.

[mperktold]

I decided to give this another try, and while I haven't succeeded in reproducing yet, I have some new insights:

It happens over HTTP/1.1. This was actually already visible in the stack trace, but I've tried to reproduce more with HTTP/2, which is a bad idea. With HTTP/1.1, I'm able to reproduce the suppressed exception about early EOF, but not the other ones.

The order of the exceptions is odd. First, the code tries to read the request content, which fails due to early EOF, which is the last suppressed exception. In our handler, we catch this exception and log it independently. This log appears before the one reported, so this really must be the first error. We then try to send a corresponding error response, and that fails because the response has been committed already, which corresponds to the reported exception (which happens during write) and the first suppressed one (which happens during close). In my mind, it should be the other way around: The one regarding early EOF should be reported, and the others should be suppressed. I'm not sure which code suppresses the early EOF exception. The first that comes to mind would be here: https://github.com/jetty/jetty.project/blob/c3f88bafb4e393f23204dc14dc57b042e84debc7/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/internal/HttpConnection.java#L1064 But this would mean that the other exception has actually occurred already, which I don't believe.

I'm also wondering if somehow an old response instance is reused here, which would explain the behavior, but I don't know how we could end up in that state and I don't have any evidence supporting this theory.

I've attached the most relevant parts of our code involved here in case you want to have a look: WebServiceHttpHandler.java

I'm also thinking about adding a special case for EofException where we would just fail instead of trying to send an error response. I think that would make sense, but if there is something else wrong, I'd like to know.

[mperktold]

Here is a more minimal example of what I'm trying to do:

public class CommittedIssue extends Handler.Abstract {

    @Override
    public boolean handle(Request request, Response response, Callback callback) throws Exception {
        byte[] bytes;
        try (var in = Request.asInputStream(request)) {
            bytes = in.readAllBytes();
            response.setStatus(HttpStatus.OK_200);
            try (var out = Content.Sink.asOutputStream(response)) {
                out.write(bytes);
            }
        }
        catch (Exception e) {
            response.setStatus(HttpStatus.INTERNAL_SERVER_ERROR_500);
            try (var out = Content.Sink.asOutputStream(response)) {
                out.write(e.toString().getBytes(StandardCharsets.UTF_8));
            }
        }
        return true;
    }

    static class ServerSide {

        public static void main(String[] args) throws Exception {
            var server = new Server(8080);
            server.setHandler(new GzipHandler(new CommittedIssue()));
            server.start();
            server.join();
        }
    }

    static class ClientSide {

        public static void main(String[] args) throws Exception {
            try (var client = new HttpClient()) {
                client.setIdleTimeout(5000);
                client.start();

                var request = client.newRequest("http://localhost:8080")
                    .method(HttpMethod.POST)
                    .headers(h -> h.put(HttpHeader.CONTENT_LENGTH, 1000));
                try (var content = new OutputStreamRequestContent()) {
                    request.body(content);
                    var future = new CompletableResponseListener(request).send();

                    // Comment these 2 lines for a more graceful failure
                    Thread.sleep(Duration.ofSeconds(1));
                    System.exit(0);

                    future.get();
                }
            }
        }
    }
}

I've included GzipHandler as well because that's what we are using in our environment, I'm not sure whether that's relevant. When I run start the server and execute the client as is, I get the following logs on the server: server-log-sysexit.txt

There is one earlyEOF exception like in the stack trace above as well as a bunch of other exceptions regarding EOF and connection reset.

As you can see, the client is shut down quite harshly using System.exit. When commenting that line and the call to Thread.sleep, an idle timeout hits eventually and I get only one exception regarding earlyEOF: server-log-idle-timeout.txt

So it looks like this second variation more closely resembles the real scenario, but I'm not sure.

[sbordet]

@mperktold I'm not sure what you're asking here?

From your logs, the IllegalStateException is not present, so is it just the suppression order?

[gregw]

@mperktold neither example really reproduces the issue that causes your production error. But it is indeed likely to be something related to the client acting badly and closing the connection at some point. I suspect your framework is catching the exception and then trying to continue.

Perhaps have a look at the DebugHandler, which can be used in production, so you can capture more details of what is happening.

[mperktold]

@sbordet I just wanted to be more transparent in how I'm trying to replicate the issue, in case you have any ideas what else I could try to trigger this "Committed" error.

@gregw I wasn't aware of DebugHandler, thanks. It does look useful, so I'll try it out

[mperktold]

I suspect your framework is catching the exception and then trying to continue.

@gregw IIRC, older versions of Jetty did something along these lines, i.e. catching the exception and calling the same handler again with a DispatchType.ERROR to allow for handler-specific exception handling. But with Jetty 12, this is no longer the case, right?

[joakime]

@gregw IIRC, older versions of Jetty did something along these lines, i.e. catching the exception and calling the same handler again with a DispatchType.ERROR to allow for handler-specific exception handling. But with Jetty 12, this is no longer the case, right?

What you are describing, the redispatch with DispatcherType.ERROR, is a Servlet function. Within a ServletContextHandler (eg: WebAppContext), that still happens.

Eg: https://github.com/jetty/jetty-examples/tree/12.0.x/embedded/ee10-error-handling

Since you are using Handler.Abstract both the redispatch and DispatcherType concept does not apply. Instead, the normal Server.getErrorHandler() is used directly, not redispatched.

Eg: https://github.com/jetty/jetty-examples/tree/12.0.x/embedded/error-handling