quarkus:dev continuous testing stuck

[michalszynkiewicz]

Describe the bug

running mvn quarkus:dev on https://github.com/michalszynkiewicz/todos-with-rr-and-grpc results in:

[/tmp/todos]$ mvn clean quarkus:dev                         
[INFO] Scanning for projects...
[INFO] 
[INFO] -------------------------< com.example:todos >--------------------------
[INFO] Building todos 1.0.0-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ todos ---
[INFO] Deleting /tmp/todos/target
[INFO] 
[INFO] --- quarkus-maven-plugin:999-SNAPSHOT:dev (default-cli) @ todos ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 2 resources
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 14 source files to /tmp/todos/target/classes
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /tmp/todos/src/test/resources
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 4 source files to /tmp/todos/target/test-classes
Listening for transport dt_socket at address: 5005
2021-06-09 12:40:04,470 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-52) Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2021-06-09 12:40:04,696 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-52) Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
2021-06-09 12:40:04,697 INFO  [org.tes.DockerClientFactory] (build-52) Docker host IP address is localhost
2021-06-09 12:40:04,716 INFO  [org.tes.DockerClientFactory] (build-52) Connected to docker: 
  Server Version: 20.10.7
  API Version: 1.41
  Operating System: Fedora 34 (KDE Plasma)
  Total Memory: 64294 MB
2021-06-09 12:40:04,718 INFO  [org.tes.uti.ImageNameSubstitutor] (build-52) Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2021-06-09 12:40:04,734 INFO  [org.tes.uti.RegistryAuthLocator] (build-52) Failure when attempting to lookup auth config. Please ignore if you don't have images in an authenticated registry. Details: (dockerImageName: testcontainers/ryuk:0.3.1, configFile: /home/michal/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/michal/.docker/config.json (Nie ma takiego pliku ani katalogu)
2021-06-09 12:40:05,402 INFO  [org.tes.DockerClientFactory] (build-52) Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2021-06-09 12:40:05,402 INFO  [org.tes.DockerClientFactory] (build-52) Checking the system...
2021-06-09 12:40:05,403 INFO  [org.tes.DockerClientFactory] (build-52) ✔︎ Docker server version should be at least 1.6.0
2021-06-09 12:40:05,457 INFO  [org.tes.DockerClientFactory] (build-52) ✔︎ Docker environment should have more than 2GB free disk space
2021-06-09 12:40:05,478 INFO  [🐳 .2]] (build-52) Creating container for image: postgres:13.2
2021-06-09 12:40:05,624 INFO  [🐳 .2]] (build-52) Starting container with ID: ae25f45c88c1731bb38188a980210e9e377555351b12f4d063751b5743cdf19a
2021-06-09 12:40:06,080 INFO  [🐳 .2]] (build-52) Container postgres:13.2 is starting: ae25f45c88c1731bb38188a980210e9e377555351b12f4d063751b5743cdf19a
2021-06-09 12:40:10,245 INFO  [🐳 .2]] (build-52) Container postgres:13.2 started in PT4.787415S
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2021-06-09 12:40:10,722 INFO  [io.qua.grp.run.GrpcServerRecorder] (Quarkus Main Thread) Registering gRPC reflection service
2021-06-09 12:40:10,762 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) gRPC Server started on 0.0.0.0:9000 [SSL enabled: false]
2021-06-09 12:40:10,808 INFO  [org.hib.rea.pro.imp.ReactiveIntegrator] (JPA Startup Thread: default-reactive) HRX000001: Hibernate Reactive Preview
2021-06-09 12:40:10,882 WARN  [io.ver.sql.imp.SocketConnectionBase] (vert.x-eventloop-thread-1) Backend notice: severity='NOTICE', code='00000', message='table "todo" does not exist, skipping', detail='null', hint='null', position='null', internalPosition='null', internalQuery='null', where='null', file='tablecmds.c', line='1217', routine='DropErrorMsgNonExistent', schema='null', table='null', column='null', dataType='null', constraint='null'
2021-06-09 12:40:10,883 WARN  [io.ver.sql.imp.SocketConnectionBase] (vert.x-eventloop-thread-1) Backend notice: severity='NOTICE', code='00000', message='sequence "hibernate_sequence" does not exist, skipping', detail='null', hint='null', position='null', internalPosition='null', internalQuery='null', where='null', file='tablecmds.c', line='1217', routine='DropErrorMsgNonExistent', schema='null', table='null', column='null', dataType='null', constraint='null'
2021-06-09 12:40:10,886 WARN  [io.ver.sql.imp.SocketConnectionBase] (vert.x-eventloop-thread-1) Backend notice: severity='NOTICE', code='00000', message='table "todo" does not exist, skipping', detail='null', hint='null', position='null', internalPosition='null', internalQuery='null', where='null', file='tablecmds.c', line='1217', routine='DropErrorMsgNonExistent', schema='null', table='null', column='null', dataType='null', constraint='null'
2021-06-09 12:40:10,886 WARN  [io.ver.sql.imp.SocketConnectionBase] (vert.x-eventloop-thread-1) Backend notice: severity='NOTICE', code='00000', message='sequence "hibernate_sequence" does not exist, skipping', detail='null', hint='null', position='null', internalPosition='null', internalQuery='null', where='null', file='tablecmds.c', line='1217', routine='DropErrorMsgNonExistent', schema='null', table='null', column='null', dataType='null', constraint='null'
2021-06-09 12:40:10,929 INFO  [io.quarkus] (Quarkus Main Thread) todos 1.0.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 6.858s. Listening on: http://localhost:8080
2021-06-09 12:40:10,930 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-06-09 12:40:10,930 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, grpc-server, hibernate-orm, hibernate-reactive, hibernate-reactive-panache, reactive-pg-client, resteasy-reactive, resteasy-reactive-jackson, sma2021-06-09 12:42:58,694 WARN  [io.ver.cor.imp.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 60281 ms, time limit is 60000 ms: io.vertx.core.VertxException: Thread blocked
        at io.quarkus.deployment.dev.testing.TestSupport.pause(TestSupport.java:198)
        at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.doScan(RuntimeUpdatesProcessor.java:360)
        at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.doScan(RuntimeUpdatesProcessor.java:350)
        at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup$2.handle(VertxHttpHotReplacementSetup.java:64)
        at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup$2.handle(VertxHttpHotReplacementSetup.java:54)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:160)
        at io.vertx.core.impl.ContextImpl$$Lambda$853/0x0000000800989840.handle(Unknown Source)
        at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:158)
        at io.vertx.core.impl.ContextImpl$$Lambda$852/0x0000000800989040.run(Unknown Source)
        at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2442)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1476)
        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@11.0.2/java.lang.Thread.run(Thread.java:834)

The error message is repeated for a long time, I quit waiting after 5 minutes.

[quarkus-bot[bot]]

/cc @stuartwdouglas

[michalszynkiewicz]

stack says:

Java stack information for the threads listed above:

  which is held by "Aesh InputStream Reader"
  waiting to lock monitor 0x00007f62bc035880 (object 0x000000046ce59490, a io.quarkus.deployment.dev.testing.TestSupport),
"vert.x-worker-thread-0":
  which is held by "vert.x-worker-thread-0"
  waiting for ownable synchronizer 0x000000046ce59090, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
"Aesh InputStream Reader":

the whole stack trace: https://gist.github.com/michalszynkiewicz/46fcbc089b19411064e9f0ce4398a4aa

[stuartwdouglas]

Can you test out https://github.com/quarkusio/quarkus/pull/17794 ? I did not see the deadlock locally

[michalszynkiewicz]

works like a charm :) thanks!