BasicKotlinApplicationModuleDevModeTest times out if run first with clean caches

[jskillin-idt]

Describe the bug

A clean .m2 and .gradle, followed by running the io.quarkus.gradle.devmode.BasicKotlinApplicationModuleDevModeTest Gradle integration test first, causes a timeout:

 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:167)
 	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:985)
 	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:954)
 	at io.quarkus.test.devmode.util.DevModeTestUtils.getHttpResponse(DevModeTestUtils.java:141)
 	at io.quarkus.gradle.devmode.QuarkusDevGradleTestBase.getHttpResponse(QuarkusDevGradleTestBase.java:162)
 	at io.quarkus.gradle.devmode.QuarkusDevGradleTestBase.getHttpResponse(QuarkusDevGradleTestBase.java:158)
 	at io.quarkus.gradle.devmode.BasicKotlinApplicationModuleDevModeTest.testDevMode(BasicKotlinApplicationModuleDevModeTest.java:19)
 	at io.quarkus.gradle.devmode.QuarkusDevGradleTestBase.main(QuarkusDevGradleTestBase.java:58)
 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
 	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
 	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
 	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
 	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
 	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
 	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
 	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
 	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
 	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
 	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
 	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
 	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
 	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
 	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
 	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
 	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
 	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
 	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
 	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:50)
 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:184)
 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:148)
 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:122)
 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
 	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)

This appears to be because the Kotlin dependencies take a proper age to download and populate the cache, which triggers this failure.

Even if the caches are populated, in my environment this test takes 70s~ to run which is of course 10s longer than the timeout in integration-tests/gradle/src/test/java/io/quarkus/gradle/devmode/QuarkusDevGradleTestBase.java 😆

I set the timeout to 10 minutes and the issue disappeared. (For me, caches took around 6-7m to populate.) A proper fix probably involves making sure that the tests' dependencies are somehow preloaded before running the actual test? I'm not sure.

Expected behavior

No response

Actual behavior

No response

How to Reproduce?

1. Delete the .m2 and .gradle directories (or otherwise clear all caches)
2. Run ./mvnw -f devtools/gradle/ install && ./mvnw -f integration-tests/gradle/ install -Dtest=BasicKotlinApplicationModuleDevModeTest in the Quarkus repo
3. You should see the test hang and network activity spike periodically as resources are fetched incrementally, for longer than 60 seconds.

Output of uname -a or ver

Linux jskillin-ubuntu-dev 6.2.0-20-generic #20-Ubuntu SMP PREEMPT_DYNAMIC Thu Apr 6 07:48:48 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

openjdk version "11.0.19" 2023-04-18 OpenJDK Runtime Environment (build 11.0.19+7-post-Ubuntu-0ubuntu123.04) OpenJDK 64-Bit Server VM (build 11.0.19+7-post-Ubuntu-0ubuntu123.04, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.1.0.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Gradle 8.1.1

Additional information

No response

[quarkus-bot]

/cc @evanchooly (kotlin), @geoand (kotlin), @gwenneg (cache)

[geoand]

A proper fix probably involves making sure that the tests' dependencies are somehow preloaded before running the actual test? I'm not sure.

Any chance you have the logs of the failing application?

[jskillin-idt]

Is this what you're looking for? This is from the very start of the tests to the end of the first test, which is the one that failed.

Edit: that log was from an earlier failure from a known Gradle + Kotlin cache corruption issue. Let me look again.

[jskillin-idt]

Here we are. This one is the one.
test.txt

[geoand]

I was hoping for the the application logs that would might be able to tell us what's going on.

In any case, I kinda doubt we'll be able to get to be the botton of this without it occuring in our CI. If you do however a timeout related fix, we can probably accept it.

[jskillin-idt]

Are you unable to reproduce it with the steps I gave in the issue?

[geoand]

I am going to close this as won't fix for the time being since it doesn't really impact our CI and fixing it properly is probably more effort than it's worth