Fix RESTEasy Reactive race

[stuartwdouglas]

These executor dispatch has to be the last thing in the method, to
prevent a possible race

Fixes #19471

[quarkus-bot]

Failing Jobs - Building b361dbe

Status	Name	Step	Test failures	Logs	Raw logs
✖	Gradle Tests - JDK 11 Windows	Build	Test failures	Logs	Raw logs

Full information is available in the Build summary check run.

Test Failures

⚙️ Gradle Tests - JDK 11 Windows #

📦 integration-tests/gradle

✖ io.quarkus.gradle.devmode.ModuleWithParentDependencyDevModeTest.main line 14 - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: Condition with lambda expression in io.quarkus.test.devmode.util.DevModeTestUtils that uses java.util.function.Supplier, java.util.function.Supplierjava.util.concurrent.atomic.AtomicReference, java.util.concurrent.atomic.AtomicReferencejava.lang.String, java.lang.Stringboolean was not fulfilled within 1 minutes.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:166)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:939)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:908)
	at io.quarkus.test.devmode.util.DevModeTestUtils.getHttpResponse(DevModeTestUtils.java:130)
	at io.quarkus.gradle.devmode.QuarkusDevGradleTestBase.getHttpResponse(QuarkusDevGradleTestBase.java:126)
	at io.quarkus.gradle.devmode.QuarkusDevGradleTestBase.getHttpRes...

[famod]

I'm afraid this broke AsyncRequestFilterTest in my fork's CI and I was also able to reproduce it locally:

org.opentest4j.AssertionFailedError: expected: <200> but was: <500>
        at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:55)
        at org.junit.jupiter.api.AssertionUtils.failNotEqual(AssertionUtils.java:62)
        at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:150)
        at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:145)
        at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:510)
        at io.quarkus.resteasy.reactive.server.test.resteasy.async.filters.AsyncRequestFilterTest.testRequestFilters(AsyncRequestFilterTest.java:94)

I bisected it via:

mvn -Dquickly -T6 -pl extensions/resteasy-reactive/quarkus-resteasy-reactive/deployment -am && mvn clean verify -Dtest=AsyncRequestFilterTest -f extensions/resteasy-reactive/quarkus-resteasy-reactive/deployment

I have absolutely no idea how this passed CI (the test was run).

But it showed at least once in another PR: #19532 (comment)

[geoand]

Hm, then I guess we should revert

[famod]

It was already backported to 2.1.3. But maybe it's just the test?
On the other hand, the reason it doesn't pop up all the time in CI might be the low concurrency potential given there are only 2 cores...

[geoand]

I wouldn't be surprised.

We sometimes get the opposite problem, but I wouldn't be surprised if low concurrency masked the problem this time

[famod]

I might have a hint what's going on: The test spits out so many errors that it's hard to see where the difference is, but I don't see the following before this change:

2021-08-20 20:56:53,259 ERROR [org.jbo.thr.errors] (executor-thread-1) Thread Thread[executor-thread-1,5,main] threw an uncaught exception: java.lang.RuntimeException: Callback called twice
        at io.quarkus.resteasy.reactive.server.test.resteasy.async.filters.AsyncRequestFilter.lambda$filter$2(AsyncRequestFilter.java:61)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.onComplete(AbstractResteasyReactiveContext.java:354)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.close(AbstractResteasyReactiveContext.java:104)
        at org.jboss.resteasy.reactive.server.core.ResteasyReactiveRequestContext.close(ResteasyReactiveRequestContext.java:366)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:178)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)

[famod]

I actually see the above multiple times, plus there is another new error (also multiple times):

2021-08-20 20:56:53,258 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-1) Request failed: java.lang.IllegalStateException: Response has already been written
        at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:394)
        at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:382)
        at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:451)
        at org.jboss.resteasy.reactive.server.vertx.VertxResteasyReactiveRequestContext.end(VertxResteasyReactiveRequestContext.java:311)
        at org.jboss.resteasy.reactive.server.handlers.ResponseWriterHandler.handle(ResponseWriterHandler.java:37)
        at org.jboss.resteasy.reactive.server.handlers.ResponseWriterHandler.handle(ResponseWriterHandler.java:15)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:135)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)

[stuartwdouglas]

The tests pass for me locally but I do see a lot of errors in the logs.

We probably should fail all our tests if there are errors in the logs (unless explicitly configured otherwise).

[stuartwdouglas]

#19568 should sort it out.