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.

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

Quarkus startup hangs after upgrade to version 2.11.x.Final #27589

Closed
dlabordus opened this issue Aug 30, 2022 · 24 comments · Fixed by #27633
Closed

Quarkus startup hangs after upgrade to version 2.11.x.Final #27589

dlabordus opened this issue Aug 30, 2022 · 24 comments · Fixed by #27633
Labels
kind/bug Something isn't working
Milestone

Comments

@dlabordus
Copy link

dlabordus commented Aug 30, 2022

Describe the bug

After upgrading our services one of the service isn't starting up anymore, at first even the build hangs. The other services are working correctly, but this one repository (CoMPAS SCL Validator) doesn't work anymore.

This repository is using a Library (RiseClipse) that's based on the Eclipse Framework and Eclipse OCL. To make it compile and run we are using the plugin 'tycho-eclipserun-plugin' to create a local maven mirror from a Eclipse P2 Site. Maybe this is causing the problem in the new version or the way the Eclipse Framework is working.

First the build stopped at the goal 'generate-code-tests' from the Quarkus plugin. after adding some configuration (skipSourceGeneration) to the plugin

<plugin>
  <groupId>io.quarkus</groupId>
  <artifactId>quarkus-maven-plugin</artifactId>
  <version>${quarkus.platform.version}</version>
  <extensions>true</extensions>
  <executions>
    <execution>
      <goals>
        <goal>build</goal>
        <goal>generate-code</goal>
        <goal>generate-code-tests</goal>
      </goals>
    </execution>
  </executions>
  <configuration>
    <skipSourceGeneration>true</skipSourceGeneration>
  </configuration>
</plugin>

The build continued but next hangs when trying to execute the HealthCheckTest where Quarkus is started and we first check if the server starts. In all situation the CPU is running at 100%, so something is happening.

Expected behavior

Build runs correctly and application starts.

Actual behavior

It look when the application tries to startup it comes in a loop, because the CPU stays at 100%.

How to Reproduce?

The problem is that it only occurs in this specific repository (CoMPAS SCL Validator) after upgrading from the latest 2.10.x.Final to all version of 2.1.x.Final.

And see the Additional information, there isn't much info to go for.

Output of uname -a or ver

Linux ubuntu 5.15.0-46-generic #49-Ubuntu SMP Thu Aug 4 18:03:25 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

OpenJDK 64-Bit Server VM (build 17.0.4+8-Ubuntu-122.04, mixed mode, sharing)

GraalVM version (if different from Java)

Quarkus version or git rev

2.11.3.Final

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

Apache Maven 3.8.6 (84538c9988a25aec085021c365c560670ad80f63)

Additional information

In this PR #98 of the project I tried some different changes to make it work and investigate if I could figure out what is going wrong.

When starting the application without executing the tests in development mode it stays running at 100% without any output.

[INFO] 
[INFO] --- quarkus-maven-plugin:2.11.3.Final:dev (default-cli) @ app ---
^C%                                                                                                                                                                                                                                     

I needed to cancel the command to stop it.

When setting the log level for test on debug this is the last logging that is shown

2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "GET /com-pas/*/org/eclipse/jdt/org.eclipse.jdt.annotation/maven-metadata.xml HTTP/1.1[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Cache-control: no-cache[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Pragma: no-cache[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "User-Agent: Apache-Maven/3.8.6 (Java 17.0.4; Linux 5.15.0-46-generic)[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Host: maven.pkg.github.com[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "Authorization: Basic ZGxhYm9yZHVzOmdocF94SmFwcHZ3aDRYanc1RURwdDE0TUpBZjhkV0cyUHEzejBjTTA=[\r][\n]"
2022-08-30 11:06:21,224 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 >> "[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "HTTP/1.1 404 Not Found[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "access-control-allow-methods: GET, HEAD, OPTIONS[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Access-Control-Allow-Origin: *[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Content-Security-Policy: default-src 'none';[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Content-Type: text/plain; charset=utf-8[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Server: GitHub Registry[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Strict-Transport-Security: max-age=31536000;[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "X-Frame-Options: DENY[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "X-XSS-Protection: 1; mode=block[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Date: Tue, 30 Aug 2022 09:06:21 GMT[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "Content-Length: 143[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "X-GitHub-Request-Id: A99C:F9C0:62FE6:6950A:630DD30D[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "[\r][\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.wire] (main) http-outgoing-0 << "unable to fetch maven-metadata for package : "maven package "org.eclipse.jdt.org.eclipse.jdt.annotation" does not exist under owner "com-pas""[\n]"
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << HTTP/1.1 404 Not Found
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << access-control-allow-methods: GET, HEAD, OPTIONS
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Access-Control-Allow-Origin: *
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Content-Security-Policy: default-src 'none';
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Content-Type: text/plain; charset=utf-8
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Server: GitHub Registry
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Strict-Transport-Security: max-age=31536000;
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << X-Content-Type-Options: nosniff
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << X-Frame-Options: DENY
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << X-XSS-Protection: 1; mode=block
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Date: Tue, 30 Aug 2022 09:06:21 GMT
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << Content-Length: 143
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.headers] (main) http-outgoing-0 << X-GitHub-Request-Id: A99C:F9C0:62FE6:6950A:630DD30D
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.imp.exe.MainClientExec] (main) Connection can be kept alive indefinitely
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.imp.aut.HttpAuthenticator] (main) Authentication succeeded
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.imp.cli.TargetAuthenticationStrategy] (main) Caching 'basic' auth scheme for https://maven.pkg.github.com:443
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.imp.con.PoolingHttpClientConnectionManager] (main) Connection [id: 0][route: {s}->https://maven.pkg.github.com:443] can be kept alive indefinitely
2022-08-30 11:06:21,445 DEBUG [org.apa.htt.imp.con.DefaultManagedHttpClientConnection] (main) http-outgoing-0: set socket timeout to 0
2022-08-30 11:06:21,446 DEBUG [org.apa.htt.imp.con.PoolingHttpClientConnectionManager] (main) Connection released: [id: 0][route: {s}->https://maven.pkg.github.com:443][total available: 2; route allocated: 1 of 20; total allocated: 2 of 40]
2022-08-30 11:06:21,446 DEBUG [org.ecl.aet.int.imp.TrackingFileManager] (main) Writing tracking file /home/dlabordus/.m2/repository/org/eclipse/jdt/org.eclipse.jdt.annotation/resolver-status.properties
2022-08-30 11:06:21,747 DEBUG [org.ecl.aet.int.imp.DefaultRemoteRepositoryManager] (main) Using mirror maven-default-http-blocker (http://0.0.0.0/) for jboss-public-repository-group (http://repository.jboss.org/nexus/content/groups/public/).
2022-08-30 11:06:21,841 DEBUG [org.ecl.aet.int.imp.DefaultRemoteRepositoryManager] (main) Using mirror maven-default-http-blocker (http://0.0.0.0/) for apache.snapshots (http://repository.apache.org/snapshots).
2022-08-30 11:06:21,856 DEBUG [org.ecl.aet.int.imp.DefaultRemoteRepositoryManager] (main) Using mirror maven-default-http-blocker (http://0.0.0.0/) for ow2-snapshot (http://repository.ow2.org/nexus/content/repositories/snapshots).
^C%                                                                                                                                                                                                                                     

And then the CPU is again at 100% and I need to cancel the command.

@gsmet
Copy link
Member

gsmet commented Aug 30, 2022

Could you get a thread dump with kill -3 <pid>? Make sure you anonymize any sensitive information in there before posting.

@dlabordus
Copy link
Author

Is this what you are looking for

[INFO] --- quarkus-maven-plugin:2.11.3.Final:dev (default-cli) @ app ---
2022-08-30 12:40:14
Full thread dump OpenJDK 64-Bit Server VM (17.0.4+8-Ubuntu-122.04 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007ff36c002a60, length=22, elements={
0x00007ff46c0127d0, 0x00007ff46c17a600, 0x00007ff46c17b9e0, 0x00007ff46c180b40,
0x00007ff46c181ef0, 0x00007ff46c183300, 0x00007ff46c184cb0, 0x00007ff46c1861e0,
0x00007ff46c18f640, 0x00007ff46c196d90, 0x00007ff46c19a650, 0x00007ff46da45e40,
0x00007ff46dba75b0, 0x00007ff46da0f830, 0x00007ff46dcd9f00, 0x00007ff46de34fb0,
0x00007ff46de55850, 0x00007ff46e035370, 0x00007ff46e0d5a50, 0x00007ff374000fe0,
0x00007ff46e1bd820, 0x00007ff46e1e8640
}

"main" #1 prio=5 os_prio=0 cpu=66689.62ms elapsed=85.48s tid=0x00007ff46c0127d0 nid=0x94f1 runnable  [0x00007ff473dc2000]
   java.lang.Thread.State: RUNNABLE
	at java.util.Arrays.hashCode(java.base@17.0.4/Arrays.java:4499)
	at java.util.Objects.hash(java.base@17.0.4/Objects.java:133)
	at io.quarkus.maven.dependency.GACT.hashCode(GACT.java:140)
	at java.util.HashMap.hash(java.base@17.0.4/HashMap.java:338)
	at java.util.HashMap.remove(java.base@17.0.4/HashMap.java:797)
	at java.util.HashSet.remove(java.base@17.0.4/HashSet.java:237)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:306)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.transformGraph(ApplicationDependencyTreeResolver.java:287)
	at org.eclipse.aether.internal.impl.collect.DefaultDependencyCollector.collectDependencies(DefaultDependencyCollector.java:273)
	at org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveDependencies(DefaultRepositorySystem.java:309)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver.resolveRuntimeDeps(ApplicationDependencyTreeResolver.java:313)
	at io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver.resolve(ApplicationDependencyTreeResolver.java:132)
	at io.quarkus.bootstrap.resolver.BootstrapAppModelResolver.buildAppModel(BootstrapAppModelResolver.java:317)
	at io.quarkus.bootstrap.resolver.BootstrapAppModelResolver.doResolveModel(BootstrapAppModelResolver.java:282)
	at io.quarkus.bootstrap.resolver.BootstrapAppModelResolver.resolveManagedModel(BootstrapAppModelResolver.java:162)
	at io.quarkus.bootstrap.resolver.BootstrapAppModelResolver.resolveModel(BootstrapAppModelResolver.java:146)
	at io.quarkus.maven.DevMojo.newLauncher(DevMojo.java:1058)
	at io.quarkus.maven.DevMojo$DevModeRunner.<init>(DevMojo.java:889)
	at io.quarkus.maven.DevMojo.execute(DevMojo.java:405)
	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:370)
	at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:351)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:215)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:171)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:163)
	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
	at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
	at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:294)
	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
	at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
	at org.apache.maven.cli.MavenCli.execute(MavenCli.java:960)
	at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:293)
	at org.apache.maven.cli.MavenCli.main(MavenCli.java:196)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.4/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.4/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.4/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@17.0.4/Method.java:568)
	at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282)
	at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225)
	at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406)
	at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.4/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.4/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.4/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@17.0.4/Method.java:568)
	at org.apache.maven.wrapper.BootstrapMainStarter.start(BootstrapMainStarter.java:39)
	at org.apache.maven.wrapper.WrapperExecutor.execute(WrapperExecutor.java:122)
	at org.apache.maven.wrapper.MavenWrapperMain.main(MavenWrapperMain.java:61)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=5.92ms elapsed=85.46s tid=0x00007ff46c17a600 nid=0x94f8 waiting on condition  [0x00007ff47022b000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.4/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@17.0.4/Reference.java:253)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.4/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=2.11ms elapsed=85.46s tid=0x00007ff46c17b9e0 nid=0x94f9 in Object.wait()  [0x00007ff47012b000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.4/ReferenceQueue.java:155)
	- locked <0x0000000706800af8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.4/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@17.0.4/Finalizer.java:172)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.16ms elapsed=85.45s tid=0x00007ff46c180b40 nid=0x94fa waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=5.55ms elapsed=85.45s tid=0x00007ff46c181ef0 nid=0x94fb runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=1.73ms elapsed=85.45s tid=0x00007ff46c183300 nid=0x94fc runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=14296.02ms elapsed=85.45s tid=0x00007ff46c184cb0 nid=0x94fd waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #10 daemon prio=9 os_prio=0 cpu=5101.34ms elapsed=85.45s tid=0x00007ff46c1861e0 nid=0x94fe waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #11 daemon prio=9 os_prio=0 cpu=255.27ms elapsed=85.45s tid=0x00007ff46c18f640 nid=0x94ff runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Notification Thread" #12 daemon prio=9 os_prio=0 cpu=0.11ms elapsed=85.45s tid=0x00007ff46c196d90 nid=0x9500 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #13 daemon prio=8 os_prio=0 cpu=2.91ms elapsed=85.45s tid=0x00007ff46c19a650 nid=0x9502 in Object.wait()  [0x00007ff44c99a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.4/ReferenceQueue.java:155)
	- locked <0x0000000706800d08> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@17.0.4/CleanerImpl.java:140)
	at java.lang.Thread.run(java.base@17.0.4/Thread.java:833)
	at jdk.internal.misc.InnocuousThread.run(java.base@17.0.4/InnocuousThread.java:162)

"Active Thread: Equinox Container: 19b333be-7b51-4c0b-8650-e0b8861e6c79" #38 prio=5 os_prio=0 cpu=27.76ms elapsed=82.31s tid=0x00007ff46da45e40 nid=0x9524 waiting on condition  [0x00007ff3b7afc000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17.0.4/Native Method)
	- parking to wait for  <0x00000007093f0120> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.4/LockSupport.java:252)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@17.0.4/AbstractQueuedSynchronizer.java:1672)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.4/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.4/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.4/ThreadPoolExecutor.java:1062)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.4/ThreadPoolExecutor.java:1122)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.4/ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(java.base@17.0.4/Thread.java:833)

"Framework Event Dispatcher: Equinox Container: 19b333be-7b51-4c0b-8650-e0b8861e6c79" #40 daemon prio=5 os_prio=0 cpu=3.73ms elapsed=82.26s tid=0x00007ff46dba75b0 nid=0x9525 in Object.wait()  [0x00007ff3b79fc000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at java.lang.Object.wait(java.base@17.0.4/Object.java:338)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- locked <0x000000070b817a60> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"Start Level: Equinox Container: 19b333be-7b51-4c0b-8650-e0b8861e6c79" #41 daemon prio=5 os_prio=0 cpu=5.12ms elapsed=82.26s tid=0x00007ff46da0f830 nid=0x9526 in Object.wait()  [0x00007ff3b78fc000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <0x000000070b82ec38> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at java.lang.Object.wait(java.base@17.0.4/Object.java:338)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- locked <0x000000070b82ec38> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"Refresh Thread: Equinox Container: 19b333be-7b51-4c0b-8650-e0b8861e6c79" #42 daemon prio=5 os_prio=0 cpu=91.94ms elapsed=82.14s tid=0x00007ff46dcd9f00 nid=0x9527 in Object.wait()  [0x00007ff3b77fc000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <0x000000070b800768> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at java.lang.Object.wait(java.base@17.0.4/Object.java:338)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- locked <0x000000070b800768> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"Gogo shell" #45 prio=5 os_prio=0 cpu=8.65ms elapsed=81.99s tid=0x00007ff46de34fb0 nid=0x952a waiting on condition  [0x00007ff3b6bfe000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17.0.4/Native Method)
	- parking to wait for  <0x000000070b817df0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@17.0.4/LockSupport.java:341)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.4/AbstractQueuedSynchronizer.java:506)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.4/ForkJoinPool.java:3463)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.4/ForkJoinPool.java:3434)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.4/AbstractQueuedSynchronizer.java:1623)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@17.0.4/LinkedBlockingQueue.java:435)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.4/ThreadPoolExecutor.java:1062)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.4/ThreadPoolExecutor.java:1122)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.4/ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(java.base@17.0.4/Thread.java:833)

"SCR Component Actor" #48 daemon prio=5 os_prio=0 cpu=0.19ms elapsed=81.97s tid=0x00007ff46de55850 nid=0x952d in Object.wait()  [0x00007ff3b69fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <0x000000070b82f0c8> (a java.util.LinkedList)
	at java.lang.Object.wait(java.base@17.0.4/Object.java:338)
	at org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:83)
	- locked <0x000000070b82f0c8> (a java.util.LinkedList)
	at java.lang.Thread.run(java.base@17.0.4/Thread.java:833)

"Worker-JM" #50 prio=5 os_prio=0 cpu=0.29ms elapsed=81.73s tid=0x00007ff46e035370 nid=0x952f in Object.wait()  [0x00007ff3b68fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <0x00000007093f03f0> (a java.util.ArrayList)
	at org.eclipse.core.internal.jobs.InternalWorker.run(InternalWorker.java:61)
	- locked <0x00000007093f03f0> (a java.util.ArrayList)

"Worker-0" #51 prio=5 os_prio=0 cpu=268.42ms elapsed=81.50s tid=0x00007ff46e0d5a50 nid=0x9530 in Object.wait()  [0x00007ff3b67fe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:200)
	- locked <0x000000070b818050> (a org.eclipse.core.internal.jobs.WorkerPool)
	at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:242)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:58)

"Worker-2" #53 prio=5 os_prio=0 cpu=97.39ms elapsed=80.95s tid=0x00007ff374000fe0 nid=0x9533 in Object.wait()  [0x00007ff44c4fe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:200)
	- locked <0x000000070b818050> (a org.eclipse.core.internal.jobs.WorkerPool)
	at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:242)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:58)

"Provisioning Event Dispatcher" #54 daemon prio=5 os_prio=0 cpu=1.90ms elapsed=80.63s tid=0x00007ff46e1bd820 nid=0x9536 in Object.wait()  [0x00007ff44c5fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.4/Native Method)
	- waiting on <no object reference available>
	at java.lang.Object.wait(java.base@17.0.4/Object.java:338)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- locked <0x000000070b82f5b0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"process reaper" #56 daemon prio=10 os_prio=0 cpu=1.77ms elapsed=71.50s tid=0x00007ff46e1e8640 nid=0x954a waiting on condition  [0x00007ff47002b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17.0.4/Native Method)
	- parking to wait for  <0x0000000708489ac8> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.4/LockSupport.java:252)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.4/SynchronousQueue.java:401)
	at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.4/SynchronousQueue.java:903)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.4/ThreadPoolExecutor.java:1061)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.4/ThreadPoolExecutor.java:1122)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.4/ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(java.base@17.0.4/Thread.java:833)

"VM Thread" os_prio=0 cpu=245.57ms elapsed=85.47s tid=0x00007ff46c1766e0 nid=0x94f7 runnable  

"GC Thread#0" os_prio=0 cpu=384.89ms elapsed=85.47s tid=0x00007ff46c07efa0 nid=0x94f2 runnable  

"GC Thread#1" os_prio=0 cpu=347.43ms elapsed=85.17s tid=0x00007ff434005ec0 nid=0x9505 runnable  

"GC Thread#2" os_prio=0 cpu=400.84ms elapsed=85.17s tid=0x00007ff4340068f0 nid=0x9506 runnable  

"GC Thread#3" os_prio=0 cpu=363.68ms elapsed=85.17s tid=0x00007ff434007320 nid=0x9507 runnable  

"GC Thread#4" os_prio=0 cpu=325.33ms elapsed=85.17s tid=0x00007ff434007d50 nid=0x9508 runnable  

"GC Thread#5" os_prio=0 cpu=357.51ms elapsed=85.17s tid=0x00007ff434008780 nid=0x9509 runnable  

"GC Thread#6" os_prio=0 cpu=348.46ms elapsed=84.74s tid=0x00007ff43400cfd0 nid=0x950a runnable  

"GC Thread#7" os_prio=0 cpu=352.10ms elapsed=84.74s tid=0x00007ff43400d750 nid=0x950b runnable  

"G1 Main Marker" os_prio=0 cpu=4.05ms elapsed=85.47s tid=0x00007ff46c08ff20 nid=0x94f3 runnable  

"G1 Conc#0" os_prio=0 cpu=328.46ms elapsed=85.47s tid=0x00007ff46c090e80 nid=0x94f4 runnable  

"G1 Conc#1" os_prio=0 cpu=311.11ms elapsed=82.79s tid=0x00007ff440000ea0 nid=0x9517 runnable  

"G1 Refine#0" os_prio=0 cpu=13.62ms elapsed=85.47s tid=0x00007ff46c145ab0 nid=0x94f5 runnable  

"G1 Refine#1" os_prio=0 cpu=6.87ms elapsed=83.85s tid=0x00007ff438000ea0 nid=0x950c runnable  

"G1 Refine#2" os_prio=0 cpu=2.08ms elapsed=83.85s tid=0x00007ff3d8000ea0 nid=0x950d runnable  

"G1 Refine#3" os_prio=0 cpu=0.23ms elapsed=77.29s tid=0x00007ff3dc001a30 nid=0x953f runnable  

"G1 Service" os_prio=0 cpu=18.69ms elapsed=85.47s tid=0x00007ff46c1469a0 nid=0x94f6 runnable  

"VM Periodic Task Thread" os_prio=0 cpu=45.95ms elapsed=85.45s tid=0x00007ff46c1986d0 nid=0x9501 waiting on condition  

JNI global refs: 18, weak refs: 0

Heap
 garbage-first heap   total 827392K, used 634170K [0x0000000706800000, 0x0000000800000000)
  region size 2048K, 178 young (364544K), 1 survivors (2048K)
 Metaspace       used 84552K, committed 85888K, reserved 1130496K
  class space    used 9967K, committed 10560K, reserved 1048576K

@gsmet
Copy link
Member

gsmet commented Aug 30, 2022

Yes, exactly. You took this while the process was running with CPU at 100%, right?

If so, I suppose we have some sort of infinite loop in ApplicationDependencyTreeResolver.

I don't know how practical it is to create a reproducer for you? I think you could probably find the culprit by attaching a debugger with a breaking point on io.quarkus.bootstrap.resolver.maven.ApplicationDependencyTreeResolver$1.walk(ApplicationDependencyTreeResolver.java:305) once the process is going berserk.

Once you have the culprit, it should be easier to put together a reproducer so that @aloubyansky can have a look.

@dlabordus
Copy link
Author

Hi @gsmet, I tried attaching a debugger against the process, but that doesn't seem to work (Unable to connect).
I first tried running the App from IntelliJ in Debug mode with breakpoints, but IntelliJ doesn't even stop at the breakpoints.

Looking at the code the only line that could in theory cause a loop is at Line 306. Here the key is at the end removed from the visited list, but that should finally work, it may process a Artifact multiple times, but should not cause a loop.

  visited.remove(key);

I will try to make a reproducer.

Remark: adding the option "-Dquarkus.bootstrap.converged-tree-only=true" will disable the new way and then the application starts again. But looking at the comment this is a temporary switch that will be removed in the future.

@dlabordus
Copy link
Author

dlabordus commented Aug 31, 2022

Creating the reproducer went pretty fast. The problem occurs when using the Eclipse Dependencies from the converted Eclipse P2 Site.

I just created a basic Quarkus project using https://code.quarkus.io/. Next added the Eclipse Tycho Plugin with the needed aggregator and the Eclipse Dependencies. The Test for the class GreetingResource now already is causing the problem, Quarkus won't start for this test. (./mwnw verify)

dependency-resolver.zip

@aloubyansky
Copy link
Member

Thanks a lot @dlabordus I'll have a look.

@aloubyansky
Copy link
Member

@dlabordus how do you create the eclipse p2 mirror?

@dlabordus
Copy link
Author

dlabordus commented Aug 31, 2022

The plugin 'tycho-eclipserun-plugin' is doing this using the file 'riseclipse.aggr'.
A mirror is created in the directory 'target/maven/repository/final' when running './mvnw verify'

And by adding this directory as a Repository in the POM File, maven can use these dependencies.

@aloubyansky
Copy link
Member

It fails for me because Maven can't initialize the project.

@aloubyansky
Copy link
Member

Do you have a Maven extension enabled somewhere?

@dlabordus
Copy link
Author

I just download the ZIP File again and started executing './mvnw verify' and it works from the command line. No extensions as far as I know.
What is the error message?

@dlabordus
Copy link
Author

I'm using Java 17, can this be the problem for you?

@aloubyansky
Copy link
Member

[INFO] ------------------< org.example:dependency-resolver >-------------------
[INFO] Building dependency-resolver 1.0.0-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[WARNING] The POM for org.eclipse.core:org.eclipse.core.resources:jar:3.17.0 is missing, no dependency information available
[WARNING] The POM for org.eclipse.ocl:org.eclipse.ocl.pivot:jar:1.17.0 is missing, no dependency information available
[WARNING] The POM for org.eclipse.ocl:org.eclipse.ocl.xtext.completeocl:jar:1.17.0 is missing, no dependency information available
[WARNING] The POM for org.eclipse.ocl:org.eclipse.ocl.xtext.oclstdlib:jar:1.17.0 is missing, no dependency information available
[WARNING] The POM for org.antlr.runtime:org.antlr.runtime:jar:3.2.0 is missing, no dependency information available
[WARNING] The POM for org.apache.log4j:org.apache.log4j:jar:1.2.19 is missing, no dependency information available
[WARNING] The POM for javax.inject:javax.inject:jar:1.0.0 is missing, no dependency information available
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  3.073 s
[INFO] Finished at: 2022-08-31T08:58:42+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal on project dependency-resolver: Could not resolve dependencies for project org.example:dependency-resolver:jar:1.0.0-SNAPSHOT: The following artifacts could not be resolved: org.eclipse.core:org.eclipse.core.resources:jar:3.17.0, org.eclipse.ocl:org.eclipse.ocl.pivot:jar:1.17.0, org.eclipse.ocl:org.eclipse.ocl.xtext.completeocl:jar:1.17.0, org.eclipse.ocl:org.eclipse.ocl.xtext.oclstdlib:jar:1.17.0, org.antlr.runtime:org.antlr.runtime:jar:3.2.0, org.apache.log4j:org.apache.log4j:jar:1.2.19, javax.inject:javax.inject:jar:1.0.0: org.eclipse.core:org.eclipse.core.resources:jar:3.17.0 was not found in file:////home/aloubyansky/playground/dependency-resolver/target/maven/repository/final during a previous attempt. This failure was cached in the local repository and resolution is not reattempted until the update interval of local-eclipse-p2-mirror has elapsed or updates are forced -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/DependencyResolutionException

@dlabordus
Copy link
Author

dlabordus commented Aug 31, 2022

Wait, maybe it has something to do with my local M2 Repository.

@aloubyansky
Copy link
Member

aloubyansky commented Aug 31, 2022

Right. The eclipse-run is configured to be executed in the generate-resources phase but it can't get to that phase.

@dlabordus
Copy link
Author

I got a way to get it working. Normally the Repo creation is in a separate module in our project.

But if you first execute
./mvnw org.eclipse.tycho.extras:tycho-eclipserun-plugin::eclipse-run
And next
./mvnw verify
it should work.

@dlabordus
Copy link
Author

I sometimes just remove the directory '~/.m2/repository/org/eclipse' to clear my local maven cache regarding these eclipse dependencies to be sure everything is still working.
The mirroring of the Eclipse P2 Site is a fragile solution sometimes, but we don't have a alternative for now.

@aloubyansky
Copy link
Member

Now it can't resolve org.antlr.runtime:org.antlr.runtime:jar:3.2.0

@aloubyansky
Copy link
Member

Got passed it. Needed to re-generate the P2 mirror for some reason.

@aloubyansky
Copy link
Member

aloubyansky commented Aug 31, 2022

Unfortunately it's getting stuck at

Downloading from local-eclipse-p2-mirror: file:////home/aloubyansky/playground/dependency-resolver/target/maven/repository/final/org/antlr/antlr-runtime/maven-metadata.xml
Downloading from central: https://repo.maven.apache.org/maven2/org/eclipse/ocl/org.eclipse.ocl.examples.xtext.serializer/maven-metadata.xml

It simply hangs at this point. Tried cleaning it up a couple of times already.

@dlabordus
Copy link
Author

dlabordus commented Aug 31, 2022

This is when the GreetingResourceTest is being executed?

Because this is the problem, when you do a kill -3 you should see something similar I have.
And the CPU should be at something like a 100%.

For this test Quarkus is started and that is not working, it looks like it's in a loop.

Adding this option '-Dquarkus.bootstrap.converged-tree-only=true' to the command should pass the build again.
Or something like '-DskipTests=true' will also do that.

@aloubyansky
Copy link
Member

Oh, ok, thanks, got it!

@aloubyansky
Copy link
Member

It looks like an infinite loop but probably it isn't exactly that. It seems like a very "dirty" dependency graph with lots of alternative versions. Anyway, it has to be fixed.

@aloubyansky
Copy link
Member

@dlabordus I opened a PR with a fix. Thanks a lot for the reproducer.

@quarkus-bot quarkus-bot bot added this to the 2.13 - main milestone Aug 31, 2022
@gsmet gsmet modified the milestones: 2.13 - main, 2.12.1.Final Sep 5, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants