IllegalStateException is QosFilter: AsyncContext completed and/or Request lifecycle recycled

[michael-gehmayr-dynatrace]

Jetty version 9.4.30.v20200611 (embedded)

Java version OpenJDK 64-Bit Server VM, Version: 11.0.8, Vendor: AdoptOpenJDK

OS type/version Linux

Description

We observed this IllegalStateException once in one of our automated load tests:

java.lang.IllegalStateException: AsyncContext completed and/or Request lifecycle recycled
	at org.eclipse.jetty.server.AsyncContextState.state(AsyncContextState.java:52)
	at org.eclipse.jetty.server.AsyncContextState.getRequest(AsyncContextState.java:112)
	at org.eclipse.jetty.servlets.QoSFilter.doFilter(QoSFilter.java:226)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1618)
	at .....ExceptionLoggingFilter.doFilter(ExceptionLoggingFilter.java:71)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1618)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:549)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:717)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1369)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:489)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1284)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:173)
	at .....JettyStatisticsHandler.handle(JettyStatisticsHandler.java:63)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at .....JettyExceptionHandler.handle(JettyExceptionHandler.java:31)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:501)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:272)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
	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:375)
	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.base/java.lang.Thread.run(Thread.java:834)

This request is not async. We use Jersey to handle the request in a synchronous way. The application code also does not recycle or modify the request in any way.

[EricBlanquer]

I have this same issue with our customer, I cannot reproduce it, seems to be linked to the load

Jetty 9.4.41.v20210516, Java openjdk version "11.0.11" 2021-04-20 LTS

[joakime]

This happens because there is an attempt to use the Request outside of its lifecycle.

Servlet containers enforce this restriction, as they can (and many containers do) recycle the HttpServletRequest objects (as they are often one of the heaviest objects created). This recycle behavior and the reasons for this exception are documented in the Servlet spec as well.

If you encounter this, then your code has a bug where it is using a reference to the HttpServletRequest object outside of either the normal Servlet dispatch, or the AsyncContext lifecycle (post-complete).

This means that your code is using the HttpServletRequest after the doGet() (or similar calls) call returns all the way through the filter chain (if synchronous). Or your code is using the HttpServletRequest object after the AsyncContext.complete() has been called.

[EricBlanquer]

thanks you @joakime for your answer, but I don't see where my code is wrong after the AsyncContext.complete() has been called: nothing is done after and I cannot reproduce what we can see into traces I've removed all code I'm not allowed to share: if you can take a look... clusterHttp.zip

thanks

[EricBlanquer]

2021/06/09-15:02:28.186 org.eclipse.jetty.util.thread.QueuedThreadPool WARN java.lang.IllegalStateException: AsyncContext completed and/or Request lifecycle recycled at org.eclipse.jetty.server.AsyncContextState.state(AsyncContextState.java:52) at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:72) at com.centile.cluster.http.ClusterHttp.proxy(ClusterHttp.java:158) at com.centile.cluster.http.ClusterHttp.lambda$doAsynch$0(ClusterHttp.java:115) at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1520) at org.eclipse.jetty.server.AsyncContextState$1.run(AsyncContextState.java:153) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036) at java.base/java.lang.Thread.run(Thread.java:829)

[EricBlanquer]

our client get an error 500 instead of the 200 OK of our backend server

[EricBlanquer]

After an upgrade with Jetty 10.0.6, this issue still occurs :(

[gregw]

@EricBlanquer I had a quick look at your code and I can't see anything wrong in that simplified version, although it doesn't look particularly async. My understanding is that the ClusterHttp class is invoked b the servlet, it starts the async, but then starts a context managed thread to call the proxy method. This thread then uses the client in a blocking mode to send a request and wait for a response before completing the async cycle in a finally block.

So you've not really got an async process happening as you have a thread blocking. To be async you really need to use the client in async style and then do the asyncContext.complete() in the success/failure callbacks of the client. That way you can threadlessly wait for the async response.

My first thought is that perhaps the async context is timing out before the proxied request responds? You probably need to add an AsyncListener to the AsyncContext to check for onError/onTimeout callbacks. You then typically need to protect against multiple callbacks racing against each other. You can do this by holding the AsyncContext in an AtomicReference so that only 1 callback can take and null the AsyncContext - it can then write the reply and complete the AsyncContext. At the very least add an onError/onTimeout callbacks to see if a they are happening.

Note also that jetty has the AsyncMiddleManServlet that does a lot of this complex async logic for you.... so perhaps look at that for an example.

[github-actions[bot]]

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

[github-actions[bot]]

This issue has been closed due to it having no activity.