Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jetty 12.0.5 (ee10) throws IllegalStateException for completed requests when Gzip Handler is used #11095

Closed
minduch opened this issue Dec 27, 2023 · 7 comments · Fixed by #11210 or eclipse/openvsx#969
Assignees
Labels
Bug For general bugs on Jetty side

Comments

@minduch
Copy link

minduch commented Dec 27, 2023

Jetty version(s)
12.0.5
I think this issue also exists for Jetty 12.0.4 (I know that we did not get it in 12.0.2 at least).

Jetty Environment
ee10

Java version/vendor (use: java -version)
openjdk version "17.0.9" 2023-10-17
OpenJDK Runtime Environment Temurin-17.0.9+9 (build 17.0.9+9)
OpenJDK 64-Bit Server VM Temurin-17.0.9+9 (build 17.0.9+9, mixed mode, sharing)

OS type/version
Windows 11 Pro, actually any OS.

Description
A seemingly successfully completed requests for most resources in our implementation with Embedded Jetty 12.0.5 logs (perhaps with GZIP involved):

[WARNING] 27 Dec 2023  13:08:08.686  <system>  <oeje10s.ServletChannel>  [<WebServer-pool>30,5,<WebServer-pool>]  /iz/css/externalBrowserPages.css: [java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
          	at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052)
          	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$3(ServletChannel.java:553)
          	at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:162)
          	at org.eclipse.jetty.ee10.servlet.HttpOutput.onWriteComplete(HttpOutput.java:250)
          	at org.eclipse.jetty.ee10.servlet.HttpOutput$WriteCompleteCB.succeeded(HttpOutput.java:1754)
          	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1202)
          	at org.eclipse.jetty.server.handler.ContextResponse$1.succeeded(ContextResponse.java:41)
          	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.write(GzipResponseAndCallback.java:142)
          	at org.eclipse.jetty.server.Response$Wrapper.write(Response.java:735)
          	at org.eclipse.jetty.server.handler.ContextResponse.write(ContextResponse.java:56)
          	at org.eclipse.jetty.ee10.servlet.HttpOutput.channelWrite(HttpOutput.java:204)
          	at org.eclipse.jetty.ee10.servlet.HttpOutput.complete(HttpOutput.java:435)
          	at org.eclipse.jetty.ee10.servlet.ServletContextResponse.completeOutput(ServletContextResponse.java:209)
          	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:553)
          	at org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:464)
          	at org.eclipse.jetty.ee10.servlet.SessionHandler.handle(SessionHandler.java:703)
          	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:761)
          	at com.iizix.jetty.ServletContextHandlers.handle(ServletContextHandlers.java:50)
          	at org.eclipse.jetty.server.Handler$Sequence.handle(Handler.java:781)
          	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:594)
          	at org.eclipse.jetty.server.Server.handle(Server.java:179)
          	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:594)
          	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:424)
          	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:478)
          	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
          	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:410)
          	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:971)
          	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1201)
          	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1156)
          	at java.base/java.lang.Thread.run(Thread.java:840)
          ]

How to reproduce?
In our product "IIZI" with embedded Jetty 12.

The only piece of our code being run is shown below. The handle(..) method is more used for internal debugging and passes on the execution into the org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:761).

class ServletContextHandlers extends ServletContextHandler
{
  /**
   * Constructor.
   * 
   * @param indexFiles  The index HTML files array.
   * @param rootDir     The root directory.
   */
  ServletContextHandlers(String [] indexFiles,File rootDir)
    {
    super(SESSIONS);
    
    // Set the base resource.
    setBaseResource(WSHelper.newResource(rootDir));

    // Set the context for all filters and servlets.
    // Required for the internal servlet & filter ServletContext to be sane.
    setContextPath("/");
    
    // The servlet context is what holds the welcome list 
    // (not the ResourceHandler or DefaultServlet)
    setWelcomeFiles(indexFiles);
    
    // Add the filter, and then use the provided FilterHolder to configure it.
    CORSFilter.configureInstance(this);
    }

  @Override
  public boolean handle(Request request,Response response,Callback callback) throws Exception
    {
    if ( WSHelper.DEBUG )
      ILog.INFO(getClass(),"> Handle  request: "+request.getHttpURI());
    
    boolean rc=super.handle(request,response,callback);
    
    if ( WSHelper.DEBUG )
      ILog.INFO(getClass(),"< Handled request = "+rc+": "+request.getHttpURI()+" - status = "+response.getStatus());
    
    return rc;
    }
}

The code in org.eclipse.jetty.ee10.servlet.ServletChannelState.java:1052 seems to be the cause:

    protected void completed(Throwable failure)
    {
        final List<AsyncListener> aListeners;
        final AsyncContextEvent event;
        boolean handle = false;

        try (AutoLock ignored = lock())
        {
            if (LOG.isDebugEnabled())
                LOG.debug("completed {}", toStringLocked());

            if (_requestState != RequestState.COMPLETING)
                throw new IllegalStateException(this.getStatusStringLocked());

            if (_event == null)
            {
                _requestState = RequestState.COMPLETED;
                aListeners = null;
                event = null;
                if (_state == State.WAITING)
                {
                    _state = State.WOKEN;
                    handle = true;
                }
            }
            else
            {
                aListeners = _asyncListeners;
                event = _event;
            }
        }

        // release any aggregate buffer from a closing flush
        _servletChannel.getHttpOutput().completed(failure);

        if (event != null)
        {
            cancelTimeout(event);
            if (aListeners != null)
            {
                runInContext(event, () ->
                {
                    for (AsyncListener listener : aListeners)
                    {
                        try
                        {
                            listener.onComplete(event);
                        }
                        catch (Throwable x)
                        {
                            if (LOG.isDebugEnabled())
                                LOG.warn("{} while invoking onComplete listener {}", x, listener, x);
                            else
                                LOG.warn("{} while invoking onComplete listener {}", x, listener);
                        }
                    }
                });
            }
            event.completed();

            try (AutoLock ignored = lock())
            {
                _requestState = RequestState.COMPLETED;
                if (_state == State.WAITING)
                {
                    _state = State.WOKEN;
                    handle = true;
                }
            }
        }

        if (handle)
            _servletChannel.handle();
    }

Are we doing something wrong?

@minduch minduch added the Bug For general bugs on Jetty side label Dec 27, 2023
@minduch minduch changed the title Jetty 12.0.5 (ee10) throws IllegalStateException for completed requests, perhaps with GZIP involved Jetty 12.0.5 (ee10) throws IllegalStateException for completed requests when Gzip Handler is used Dec 28, 2023
@ekupcik
Copy link

ekupcik commented Jan 1, 2024

I am getting this too after updating from 12.0.4 to 12.0.5. I have been running 12.0.4 since it was released and never seen this but with 12.0.5 I get it every time. So it seems to be something new in 12.0.5.

I can also confirm that it is somehow related to using the GzipHandler. Or at least that using the GzipHandler is one of the ways to trigger this.

The filter is set up using this code

        private Handler wrapGzip(WebAppContext aWebContext)
	{
		if(isUseGZip )
		{
			GzipHandler loGzipHandler = new GzipHandler();
			loGzipHandler.setHandler(aWebContext);
			loGzipHandler.addIncludedMimeTypes(
				"text/html",
				"text/plain",
				"text/xml",
				"text/css",
				"application/javascript",
				"application/json",
				"text/javascript");
			loGzipHandler.addIncludedMethods("POST", "GET");

			return loGzipHandler;
		}
		else
		{
			return aWebContext;
		}
	}

And once I do this requests to static JS files cause the mentioned error in the logs

[m2024/01/01 19:43:41.844 �[33mWARN  [ServletChannel                ]  /gatekeeper/idp/gatekeeper/js/util.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
	at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$3(ServletChannel.java:553)
	at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:162)

Without wrapping the the Webappcontext with the GZipHandler everything is fine

@sbordet sbordet self-assigned this Jan 1, 2024
@sbordet
Copy link
Contributor

sbordet commented Jan 1, 2024

The code is correct, and it is indeed the GzipHandler that is causing issues.
I'm preparing a PR, stay tuned.

sbordet added a commit that referenced this issue Jan 1, 2024
…andler.

Fixed 2 problems:
* In ServletChannel, in COMPLETE state, there was a check comparing the number of bytes written with that declared by Content-Length.
Unfortunately the check was wrong in case of gzip, because it was comparing the application length with the gzipped length, resulting in a late sendErrorOrAbort() that was an abort() because the response was already fully sent.
Furthermore, if sendErrorOrAbort() was actually an abort(), there was an unnecessary attempt to complete the output.
* In GzipHandlerResponseAndCallback there were 2 last writes: one when the application calls output.close(), and one when the callback is succeeded.
Furthermore, when no content needs to be written, it was still compressed, causing an IOException in ChannelResponse (again when double-checking the bytes written, since Content-Length was 0, but the gzip header and trailer were written).

Signed-off-by: Simone Bordet <[email protected]>
@sbordet
Copy link
Contributor

sbordet commented Jan 1, 2024

@minduch @ekupcik can you try the code in #11210?

@ekupcik
Copy link

ekupcik commented Jan 2, 2024

@sbordet The fix seems to work for me

@minduch
Copy link
Author

minduch commented Jan 2, 2024

@sbordet It will probably work in my case too as it seems to be the same kind of error. When is 12.0.6 expected, and will it include this PR?

@sbordet
Copy link
Contributor

sbordet commented Jan 2, 2024

12.0.6 expected by end of month, and yes will have this PR.

@minduch
Copy link
Author

minduch commented Jan 2, 2024

@sbordet We are so "full up with work" that I think takes too long time to setup this PR test environment, so we will wait for 12.0.6 that will probably fix more stuff... Let's hope - it's a new year - BTW: Happy New Year!

@sbordet sbordet moved this to 🏗 In progress in Jetty 12.0.6 FROZEN Jan 3, 2024
sbordet added a commit that referenced this issue Jan 27, 2024
…Handler (#11210)

* In ServletChannel, in COMPLETE state, there was a check comparing the number of bytes written with that declared by Content-Length.
Unfortunately the check was wrong in case of gzip, because it was comparing the application length with the gzipped length, resulting in a late sendErrorOrAbort() that was an abort() because the response was already fully sent.
Furthermore, if sendErrorOrAbort() was actually an abort(), there was an unnecessary attempt to complete the output.
* In GzipHandlerResponseAndCallback there were 2 last writes: one when the application calls output.close(), and one when the callback is succeeded.
Furthermore, when no content needs to be written, it was still compressed, causing an IOException in ChannelResponse (again when double-checking the bytes written, since Content-Length was 0, but the gzip header and trailer were written).
* Updates semantic of when to add the "Vary" header.
Now it is always only added by GzipHandler, when it would be possible to generate a response that might be compressed (even if it will not).
* Added *.bz2 mime-type.
Updated GzipHandler with the correct mime-type for *.bz2: application/x-bzip2.
* Improved checks for the number of bytes written against declared content-length.
This is necessary because welcome files are written by DefaultServlet (most of the times) bypassing the Servlet classes, using ServletContextResponse directly.

Signed-off-by: Simone Bordet <[email protected]>
Co-authored-by: Joakim Erdfelt <[email protected]>
@github-project-automation github-project-automation bot moved this from 🏗 In progress to ✅ Done in Jetty 12.0.6 FROZEN Jan 27, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For general bugs on Jetty side
Projects
No open projects
Status: ✅ Done
3 participants