Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

MutinyTest#testSSE can be unstable #11687

Closed
gsmet opened this issue Aug 27, 2020 · 7 comments · Fixed by #11828
Closed

MutinyTest#testSSE can be unstable #11687

gsmet opened this issue Aug 27, 2020 · 7 comments · Fixed by #11828
Assignees
@kenfinnigan
Labels
area/mutiny area/smallrye kind/bug Something isn't working
Milestone
1.8.0.Final

Comments

@gsmet
Copy link
Member

gsmet commented Aug 27, 2020 •
edited
Loading

Just got this failure on CI. Don't know if the timeout is just not enough or if there is a more problematic issue.

I disabled the test for now.

In this run https://github.com/quarkusio/quarkus/pull/11679/checks?check_run_id=1038350811 , I got the error for both the JDK 14 build and the Windows build.

2020-08-27T21:08:08.0316811Z [INFO] Running io.quarkus.it.resteasy.mutiny.MutinyTest
2020-08-27T21:08:13.5016662Z 2020-08-27 21:08:13,486 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT on JVM started in 2.199s. Listening on: http://0.0.0.0:8081
2020-08-27T21:08:13.5017074Z 2020-08-27 21:08:13,487 INFO  [io.quarkus] (main) Profile test activated. 
2020-08-27T21:08:13.5017471Z 2020-08-27 21:08:13,487 INFO  [io.quarkus] (main) Installed features: [cdi, mutiny, rest-client, resteasy, resteasy-jsonb, resteasy-mutiny, smallrye-context-propagation]
2020-08-27T21:08:25.6885373Z 2020-08-27 21:08:25,681 ERROR [org.jbo.res.res.i18n] (executor-thread-1) RESTEASY002020: Unhandled asynchronous exception, sending back 500: java.io.IOException: boom
2020-08-27T21:08:25.6886170Z 	at io.quarkus.it.resteasy.mutiny.MutinyResource.fail(MutinyResource.java:33)
2020-08-27T21:08:25.6886511Z 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2020-08-27T21:08:25.6886944Z 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2020-08-27T21:08:25.6888837Z 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2020-08-27T21:08:25.6889774Z 	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
2020-08-27T21:08:25.6891229Z 	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167)
2020-08-27T21:08:25.6892896Z 	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
2020-08-27T21:08:25.6894706Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:638)
2020-08-27T21:08:25.6897212Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:504)
2020-08-27T21:08:25.6899073Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:454)
2020-08-27T21:08:25.6901649Z 	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
2020-08-27T21:08:25.6903082Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:456)
2020-08-27T21:08:25.6904663Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:417)
2020-08-27T21:08:25.6906280Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
2020-08-27T21:08:25.6907923Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
2020-08-27T21:08:25.6909596Z 	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:488)
2020-08-27T21:08:25.6911296Z 	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:259)
2020-08-27T21:08:25.6913093Z 	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:160)
2020-08-27T21:08:25.6915649Z 	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
2020-08-27T21:08:25.6917258Z 	at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:163)
2020-08-27T21:08:25.6928616Z 	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:245)
2020-08-27T21:08:25.6929509Z 	at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
2020-08-27T21:08:25.6931330Z 	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:131)
2020-08-27T21:08:25.6933059Z 	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:37)
2020-08-27T21:08:25.6934673Z 	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:94)
2020-08-27T21:08:25.6936400Z 	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
2020-08-27T21:08:25.6937802Z 	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046)
2020-08-27T21:08:25.6939575Z 	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578)
2020-08-27T21:08:25.6941145Z 	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
2020-08-27T21:08:25.6942408Z 	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
2020-08-27T21:08:25.6944145Z 	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
2020-08-27T21:08:25.6944981Z 	at java.base/java.lang.Thread.run(Thread.java:832)
2020-08-27T21:08:25.6946010Z 	at org.jboss.threads.JBossThread.run(JBossThread.java:479)
2020-08-27T21:08:25.6946281Z 
2020-08-27T21:08:25.8616649Z 2020-08-27 21:08:25,752 WARN  [org.jbo.res.cli.jax.i18n] (Finalizer) RESTEASY004687: Closing a class org.jboss.resteasy.client.jaxrs.engines.ApacheHttpClient43Engine instance for you. Please close clients yourself.
2020-08-27T21:08:26.1391639Z [ERROR] Tests run: 9, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 18.095 s <<< FAILURE! - in io.quarkus.it.resteasy.mutiny.MutinyTest
2020-08-27T21:08:26.1392396Z [ERROR] io.quarkus.it.resteasy.mutiny.MutinyTest.testSSE  Time elapsed: 10.126 s  <<< ERROR!
2020-08-27T21:08:26.1394414Z org.awaitility.core.ConditionTimeoutException: Condition with lambda expression in io.quarkus.it.resteasy.mutiny.MutinyTest that uses java.util.List was not fulfilled within 10 seconds.
2020-08-27T21:08:26.1395696Z 	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:165)
2020-08-27T21:08:26.1397100Z 	at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
2020-08-27T21:08:26.1398236Z 	at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
2020-08-27T21:08:26.1428205Z 	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:895)
2020-08-27T21:08:26.1428739Z 	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:864)
2020-08-27T21:08:26.1430000Z 	at io.quarkus.it.resteasy.mutiny.MutinyTest.testSSE(MutinyTest.java:95)
2020-08-27T21:08:26.1431711Z 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2020-08-27T21:08:26.1433366Z 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2020-08-27T21:08:26.1435421Z 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2020-08-27T21:08:26.1436512Z 	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
2020-08-27T21:08:26.1438327Z 	at io.quarkus.test.junit.QuarkusTestExtension.runExtensionMethod(QuarkusTestExtension.java:753)
2020-08-27T21:08:26.1440407Z 	at io.quarkus.test.junit.QuarkusTestExtension.interceptTestMethod(QuarkusTestExtension.java:660)
2020-08-27T21:08:26.1441840Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
2020-08-27T21:08:26.1443732Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
2020-08-27T21:08:26.1446357Z 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
2020-08-27T21:08:26.1448005Z 	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
2020-08-27T21:08:26.1449936Z 	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
2020-08-27T21:08:26.1451727Z 	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
2020-08-27T21:08:26.1454245Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
2020-08-27T21:08:26.1455980Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
2020-08-27T21:08:26.1458477Z 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
2020-08-27T21:08:26.1460415Z 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
2020-08-27T21:08:26.1462482Z 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
2020-08-27T21:08:26.1464422Z 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
2020-08-27T21:08:26.1466026Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
2020-08-27T21:08:26.1467626Z 	at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
2020-08-27T21:08:26.1469966Z 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:212)
2020-08-27T21:08:26.1471786Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1474105Z 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:208)
2020-08-27T21:08:26.1476184Z 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:137)
2020-08-27T21:08:26.1478251Z 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:71)
2020-08-27T21:08:26.1625783Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:135)
2020-08-27T21:08:26.1633910Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1646240Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
2020-08-27T21:08:26.1655618Z 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
2020-08-27T21:08:26.1690073Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
2020-08-27T21:08:26.1697548Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1704947Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
2020-08-27T21:08:26.1710927Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
2020-08-27T21:08:26.1715222Z 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
2020-08-27T21:08:26.1724706Z 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
2020-08-27T21:08:26.1731828Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
2020-08-27T21:08:26.1738431Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1747977Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
2020-08-27T21:08:26.1753538Z 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
2020-08-27T21:08:26.1761536Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
2020-08-27T21:08:26.1768656Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1776191Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
2020-08-27T21:08:26.1782662Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
2020-08-27T21:08:26.1787150Z 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
2020-08-27T21:08:26.1796295Z 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
2020-08-27T21:08:26.1807786Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
2020-08-27T21:08:26.1814467Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1829281Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
2020-08-27T21:08:26.1834448Z 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
2020-08-27T21:08:26.1843206Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
2020-08-27T21:08:26.1850218Z 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
2020-08-27T21:08:26.1857311Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
2020-08-27T21:08:26.1864311Z 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
2020-08-27T21:08:26.1898210Z 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
2020-08-27T21:08:26.1906361Z 	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
2020-08-27T21:08:26.1914309Z 	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
2020-08-27T21:08:26.1920674Z 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248)
2020-08-27T21:08:26.1928404Z 	at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211)
2020-08-27T21:08:26.1936789Z 	at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226)
2020-08-27T21:08:26.1942511Z 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199)
2020-08-27T21:08:26.1948202Z 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132)
2020-08-27T21:08:26.1954745Z 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:188)
2020-08-27T21:08:26.1962280Z 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:154)
2020-08-27T21:08:26.1968806Z 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:128)
2020-08-27T21:08:26.1974591Z 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
2020-08-27T21:08:26.1979798Z 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
2020-08-27T21:08:26.1984806Z 	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
2020-08-27T21:08:26.1989855Z 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)
@gsmet gsmet added the kind/bug Something isn't working label Aug 27, 2020
@quarkusbot
Copy link

/cc @cescoffier

@cescoffier
Copy link
Member

As nothing change in Mutiny around that, it might be a recent change in RestEasy (CC @stuartwdouglas )

@stuartwdouglas
Copy link
Member

@cescoffier I think you meant @asoldano I have nothing to do with RESTEasy :-)

@jaikiran jaikiran mentioned this issue Aug 31, 2020
Closed
@asoldano
Copy link
Contributor

@cescoffier are you able to tell the RESTEasy version upgrade that might be related to this?

@loicmathieu loicmathieu mentioned this issue Aug 31, 2020
Closed
@cescoffier
Copy link
Member

cescoffier commented Aug 31, 2020 •
edited
Loading

@asoldano It's a total mystery.

Our investigations (from @loicmathieu and myself) have shown that it requires the item emitted by the Publisher to be emitted by the same thread. Otherwise, it may fail (it only fails on CI). So, there is some kind of race conditions. I want to track it a bit more.

What's not clear is why does it start failing now, while nothing changed except the CI that because a tiny bit faster.

@FroMage offered his help too.

@cescoffier
Copy link
Member

The cause might be different. After a few green runs, it failed again... so might not be a thread issue.

@cescoffier
Copy link
Member

After evaluation at #11727, @FroMage found the culprit.

@cescoffier cescoffier assigned kenfinnigan and radcortez and unassigned cescoffier Sep 2, 2020
@gsmet gsmet added this to the 1.8.0.Final milestone Sep 2, 2020
kenfinnigan added a commit to kenfinnigan/quarkus that referenced this issue Sep 2, 2020
@kenfinnigan
Re-enable MutinyTest
892f0a8 
 - Fixes quarkusio#11687
 - Moved JAX-RS ClientBuilder service file for native to RESTClientProcessor
 - Use existing ResteasyProviderFactory to register client providers with if it exists, and don't replace the provider directly
@kenfinnigan kenfinnigan mentioned this issue Sep 2, 2020
Merged
kenfinnigan added a commit to kenfinnigan/quarkus that referenced this issue Sep 4, 2020
@kenfinnigan
Re-enable MutinyTest
5e77962 
 - Fixes quarkusio#11687
 - Moved JAX-RS ClientBuilder service file for native to RESTClientProcessor
 - Use existing ResteasyProviderFactory to register client providers with if it exists, and don't replace the provider directly
gsmet pushed a commit to gsmet/quarkus that referenced this issue Sep 4, 2020
@kenfinnigan @gsmet
Re-enable MutinyTest
412f947 
 - Fixes quarkusio#11687
 - Moved JAX-RS ClientBuilder service file for native to RESTClientProcessor
 - Use existing ResteasyProviderFactory to register client providers with if it exists, and don't replace the provider directly
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kenfinnigan kenfinnigan

Labels
area/mutiny area/smallrye kind/bug Something isn't working
Projects
None yet
Milestone
1.8.0.Final
7 participants
@stuartwdouglas @cescoffier @asoldano @kenfinnigan @gsmet @radcortez @quarkusbot