Better resolve race between AsyncListener.onTimeout and AsyncContext.dispatch

[gregw]

There is an intrinsic race between an application calling AsyncContext.dispatch and the container calling AsyncListener.onTimeout.
Currently when an async timeout expires, the HttpChannelState is atomically changed from ASYNC to EXPIRE, so that any subsequent call by the application to AsyncContext.dispatch will receive an ISE.

However, once the container starts calling any AsyncListener.onTimeout listeners, it switches the state to EXPIRING as it is allowed for those listeners to call AsyncContext.dispatch as part of their valid handling. However, at this point the current implementation is unable to distinguish between a valid call to dispatch from a listener vs a late call to dispatch from the normal application logic. So the dispatch is allowed, which can result in either the container throwing an ISE when is doesn't see EXPIRING state just before calling onTimeout, or the handling within an onTimeout listener may get an ISE as the request has already been dispatched.

This results at least in a noisy logged exception. At worst, the application dispatch may be used even if onTimeout is called. Better handling would be that once EXPIRING, only the same thread is allowed to call dispatch (or complete for that matter) so that only a listener will be able to call them and any late application calls are rejected with an ISE.

Whilst this race has been seen in the wild, it will be very difficult to reproduce in a unit test as there is no suitable extension point.

[joakime]

I was able to reproduce this with a simple server and loadgenerator client setup.
Every run triggers the fault at least 4 times, and as many as 19 times on some runs.

• Server - https://github.com/joakime/load-server
• Client - https://github.com/joakime/load-client

Logs (partial DEBUG, full DEBUG doesn't trigger it for me) against 9.4.40 release -
server-java-11.0.10-20210430T163849.log.gz

The QoSFilter$QoSAsyncListener.onTimeout starts the issue with this stacktrace ...

16:38:59.906 [server-146] WARN  o.e.j.d.load.server.CustomQoSFilter - onTimeout() ERROR
java.lang.IllegalStateException: s=HANDLING rs=DISPATCH os=OPEN is=IDLE awp=false se=true i=false al=1
	at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:703)
	at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:72)
	at org.eclipse.jetty.demo.load.server.CustomQoSFilter$QoSAsyncListener.onTimeout(CustomQoSFilter.java:343)
	at org.eclipse.jetty.server.HttpChannelState$2.run(HttpChannelState.java:662)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1520)
	at org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:1206)
	at org.eclipse.jetty.server.HttpChannelState.onTimeout(HttpChannelState.java:679)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:401)
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:340)
	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:834)

From there, the HttpChannelState.onTimeout creates more WARN messages.

I'll try your branch next.

[onintwo2]

So is this patch ready?

[joakime]

This has exposed a deficiency in the Servlet API/Spec.

A new thread on the servlet-dev mailing list has been started about it ...
https://www.eclipse.org/lists/servlet-dev/msg00370.html

[sbordet]

@onintwo2 the patch for 9.4.x has been merged. If you can use 9.4.41-SNAPSHOT or build it yourself, you will be able to test it.

[onintwo2]

Where is the link to see the changes made. Dorion From: Simone Bordet ***@***.*** Sent: Wednesday, May 05, 2021 12:08 To: eclipse/jetty.project Cc: Dorion Carr; Mention Subject: Re: [eclipse/jetty.project] Better resolve race between `AsyncListener.onTimeout` and `AsyncContext.dispatch` (#6227) @onintwo2 <https://github.com/onintwo2> the patch for 9.4.x has been merged. If you can use 9.4.41-SNAPSHOT or build it yourself, you will be able to test it. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6227 (comment)> , or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADYCGKSV54G2DQS24EI7UMTTMFUNPANCNFSM433MQNRA> .Image removed by sender.

[sbordet]

@onintwo2 https://github.com/eclipse/jetty.project/pull/6228/files

[salberch]

Hi, We are using maven, can you publish the fix un a mvn repository?
Thanks