Seeing `java.lang.IllegalArgumentException: demand pending` during load testing

[joakime]

Jetty version(s) 12.0.8

Jetty Environment ee10

Java version/vendor (use: java -version) JDK21

OS type/version Linux

Description

java.lang.IllegalArgumentException: demand pending
 	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.demand(HttpChannelState.java:955)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.handler.ContextRequest.demand(ContextRequest.java:41)
 	at org.eclipse.jetty.ee10.servlet.AsyncContentProducer.isReady(AsyncContentProducer.java:252)
 	at org.eclipse.jetty.ee10.servlet.HttpInput.run(HttpInput.java:325)
 	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$1(ServletChannel.java:537)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1292)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1285)
 	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:537)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1298)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.lambda$execute$0(ContextHandler.java:1315)
 	at org.eclipse.jetty.util.thread.MonitoredQueuedThreadPool$1.run(MonitoredQueuedThreadPool.java:73)
 	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)

How to reproduce?

Load testing

[lorban]

Here is my theory about what could be the cause of this:

TL;DR I think Jersey is reading from the ServletInputStream while the core Handler's callback is being succceeded.

IAE thrown because HttpChannelState._onContentAvailable != null:

  if (httpChannelState._onContentAvailable != null)
    throw new IllegalArgumentException("demand pending");

The recycling happens when the core Handler's callback is succeeded and its order is:

HttpStreamOverHttp1.succeeded()
  CompletionStreamWrapper.succeeded()
    CompletionStreamWrapper.onCompletion()
      ServletChannel.recycle()
        ServletChannelState.recycle() // resets the inputState to IDLE
        << if the thread with the stack below executes here, it throws ISE >>
        HttpInput.recycle() // flips the ContentProducer to the blocking one, making isReady() return false 
  HttpChannelState.recycle()
    _onContentAvailable = null

Repeating the reported stack trace:

java.lang.IllegalArgumentException: demand pending
 	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.demand(HttpChannelState.java:955)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803)
 	at org.eclipse.jetty.server.handler.ContextRequest.demand(ContextRequest.java:41)
 	at org.eclipse.jetty.ee10.servlet.AsyncContentProducer.isReady(AsyncContentProducer.java:252)
 	at org.eclipse.jetty.ee10.servlet.HttpInput.run(HttpInput.java:325)
 	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$1(ServletChannel.java:537)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1292)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1285)
 	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:537)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1298)
 	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.lambda$execute$0(ContextHandler.java:1315)
 	at org.eclipse.jetty.util.thread.MonitoredQueuedThreadPool$1.run(MonitoredQueuedThreadPool.java:73)
 	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)

If ServletInputStream.read() executes DURING the handler's callback being succeeded:

HttpInput.read()
  AsyncContentProducer.nextChunk() // returns EOF
  _consumedEof = true;
  // If EOF do we need to wake for allDataRead callback?
  if (onContentProducible()) // sets inputState to READY; also sets state to WOKEN if it was WAITING, return true in that case
    scheduleReadListenerNotification(); // dispatches a thread that will have the stack trace above

The dispatched thread would eventually call AsyncContentProducer.isReady() which could see that the inputState is IDLE if it happens between ServletChannelState.recycle() and HttpInput.recycle(). In that case, it would try to register a demand.

Can we have a demand already registered at this point? YES! because the thread that called HttpInput.read() would have this loop:

while (isReady()) // sets the inputState to READY and returns true on the 1st check; sets the inputState to UNREADY, registers a demand and returns false on the 2nd check
 httpInput.read(); // reads -1, prepares the dispatch to call onAllDataRead()

But that needs to be confirmed.

[perok]

Hi! We are running Jetty 12.0.10 with ee8 and Java17. We are seeing what seems to be the same error:

demand pending.
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.demand(HttpChannelState.java:955) 
	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803) 
	at org.eclipse.jetty.server.Request$Wrapper.demand(Request.java:803) 
	at org.eclipse.jetty.server.handler.ContextRequest.demand(ContextRequest.java:41) 
	at org.eclipse.jetty.ee8.nested.HttpChannel.needContent(HttpChannel.java:162) 
	at org.eclipse.jetty.ee8.nested.AsyncContentProducer.isReady(AsyncContentProducer.java:247) 
	at org.eclipse.jetty.ee8.nested.HttpInput.isReady(HttpInput.java:199) 
	at org.http4s.servlet.NonBlockingServletIo.go$1(ServletIo.scala:187) 
	at org.http4s.servlet.NonBlockingServletIo.$anonfun$reader$5(ServletIo.scala:211) 
	at async @ org.http4s.servlet.NonBlockingServletIo.$anonfun$reader$4(ServletIo.scala:178) 
	at flatMap @ fs2.Compiler$Target.flatMap(Compiler.scala:163) 
	at handleErrorWith @ fs2.Compiler$Target.handleErrorWith(Compiler.scala:161) 
	at flatMap @ fs2.Compiler$Target.flatMap(Compiler.scala:163) 
	at flatMap @ fs2.Compiler$Target.flatMap(Compiler.scala:163) 
	at flatMap @ fs2.Compiler$Target.flatMap(Compiler.scala:163) 
	at flatMap @ fs2.Compiler$Target.flatMap(Compiler.scala:163) 
	at flatMap @ fs2.Pull$.goEval$1(Pull.scala:1090) 
	at flatMap @ fs2.Pull$.$anonfun$compile$26(Pull.scala:1249) 
	at flatMap @ fs2.Pull$.$anonfun$compile$26(Pull.scala:1249) 

Could it be that ee8 needs the same fix as ee10 got in https://github.com/jetty/jetty.project/pull/11721?

The library that is running the requests is https://github.com/http4s/http4s-servlet/blob/v0.23.15/servlet/src/main/scala/org/http4s/servlet/AsyncHttp4sServlet.scala.

[lorban]

@perok Can you create a reproducer and publish it as some github repo?

While the symptoms of your EE8 problem look similar to the original EE10 one, EE8/9 have a very different implementation than EE10 so only a deep investigation would be able to confirm what the problem actually is.