Visitar URL original
Better resolve race between `AsyncListener.onTimeout` and `AsyncContext.dispatch` · Issue #6227 · jetty/jetty.project · GitHub
Skip to content

Better resolve race between AsyncListener.onTimeout and AsyncContext.dispatch #6227

New issue
New issue
Closed
#6231
#6228
Closed
Better resolve race between AsyncListener.onTimeout and AsyncContext.dispatch#6227
#6231
#6228
Assignees
gregw

Description

@gregw
gregw
opened on Apr 30, 2021

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.

Activity

  1. gregw
    self-assigned this
    on Apr 30, 2021
  2. gregw
    added a commit that references this issue on Apr 30, 2021

    Fix #6227 Async timeout dispatch race

    9a03f4d

  3. joakime commented on Apr 30, 2021

    @joakime
    joakime
    on Apr 30, 2021
    Contributor

    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.

    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.

  4. gregw
    added a commit that references this issue on Apr 30, 2021

    Fix #6227 Async timeout dispatch race

    c50cffa

  5. onintwo2 commented on May 3, 2021

    @onintwo2
    onintwo2
    on May 3, 2021

    So is this patch ready?

  6. joakime commented on May 3, 2021

    @joakime
    joakime
    on May 3, 2021
    Contributor

    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

  7. gregw
    added 2 commits that reference this issue on May 4, 2021

    Fix #6227 Async timeout dispatch race (#6228)

    ad6d23f

    Fix #6227 Async timeout dispatch race (#6228)

    9420863
  8. sbordet
    linked a pull request that will close this issueFix #6227 Async timeout dispatch race #6228on May 5, 2021
  9. sbordet
    linked a pull request that will close this issueFix #6227 Async timeout dispatch race (#6228) #6231on May 5, 2021

  10. sbordet commented on May 5, 2021

    @sbordet
    sbordet
    on May 5, 2021
    Contributor

    @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.

  11. onintwo2 commented on May 5, 2021

    @onintwo2
    onintwo2
    on May 5, 2021 via email

  12. sbordet commented on May 5, 2021

    @sbordet
    sbordet
    on May 5, 2021
    Contributor

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

  13. gregw
    closed this as completedin #6231on May 5, 2021
  14. gregw
    added a commit that references this issue on May 5, 2021

    Fix #6227 Async timeout dispatch race (#6228) (#6231)

    1263732

  15. salberch commented on May 6, 2021

    @salberch
    salberch
    on May 6, 2021

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions