vertx-howtos / hibernate-reactive-howto

Apache License 2.0
4 stars 6 forks source link

io.vertx.core.VertxException: Thread blocked #6

Open siddjain opened 2 years ago

siddjain commented 2 years ago

Hello,

we tried using this sample to learn vert.x. we can run it locally but when we deploy on google cloud run we get an exception:

io.vertx.core.VertxException: Thread blocked

The full log is below:

$ ./scripts/tail-logs.sh                                                                                                     ✘
Initializing tail session.
2022-10-03 16:39:35,216 INFO [main] io.vertx.howtos.hr.MainVerticle - 🚀 Starting Vert.x
Container Sandbox: Unsupported syscall getsockopt(0x5f,0x1,0xc,0x3e9a5e5fc3c8,0x3e9a5e5fc3cc,0x7). It is very likely that you can safely ignore this message and that this is not the cause of any error you might be troubleshooting. Please, refer to https://gvisor.dev/docs/user_guide/compatibility/linux/amd64/#getsockopt for more information.
Container Sandbox: Unsupported syscall getsockopt(0x5f,0x1,0x38,0x3e9a5e5fc3c8,0x3e9a5e5fc3cc,0x7). It is very likely that you can safely ignore this message and that this is not the cause of any error you might be troubleshooting. Please, refer to https://gvisor.dev/docs/user_guide/compatibility/linux/amd64/#getsockopt for more information.
2022-10-03 16:39:35,927 INFO [vert.x-worker-thread-0] org.hibernate.jpa.internal.util.LogHelper - HHH000204: Processing PersistenceUnitInfo [name: pg-demo]
2022-10-03 16:39:35,991 INFO [vert.x-worker-thread-0] org.hibernate.Version - HHH000412: Hibernate ORM core version 5.6.0.Final
2022-10-03 16:39:35,821 WARN [vert.x-eventloop-thread-0] io.netty.util.internal.MacAddressUtil - Failed to find a usable hardware address from the network interfaces; using random bytes: 76:18:fc:d9:ab:88:7e:fc
2022-10-03 16:39:35,874 INFO [vert.x-eventloop-thread-0] io.vertx.howtos.hr.MainVerticle - ✅ HTTP server listening on port 8080

2022-10-03 16:40:36,294 INFO [vert.x-worker-thread-0] org.hibernate.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2022-10-03 16:40:38,694 WARN [vertx-blocked-thread-checker] io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 60722 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
    at java.base@17.0.4.1/java.util.zip.ZipFile$Source.getEntryPos(ZipFile.java:1640)
    at java.base@17.0.4.1/java.util.zip.ZipFile.getEntry(ZipFile.java:331)
    at java.base@17.0.4.1/java.util.jar.JarFile.getEntry(JarFile.java:518)
    at java.base@17.0.4.1/java.util.jar.JarFile.getJarEntry(JarFile.java:473)
    at java.base@17.0.4.1/jdk.internal.loader.URLClassPath$JarLoader.getResource(URLClassPath.java:954)
    at java.base@17.0.4.1/jdk.internal.loader.URLClassPath.getResource(URLClassPath.java:319)
    at java.base@17.0.4.1/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:757)
    at java.base@17.0.4.1/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:681)
    at java.base@17.0.4.1/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:639)
    at java.base@17.0.4.1/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
    at java.base@17.0.4.1/java.lang.ClassLoader.loadClass(ClassLoader.java:520)
    at app//org.hibernate.annotations.common.reflection.java.JavaReflectionManager.<init>(JavaReflectionManager.java:51)
    at app//org.hibernate.boot.internal.BootstrapContextImpl.generateHcannReflectionManager(BootstrapContextImpl.java:311)
    at app//org.hibernate.boot.internal.BootstrapContextImpl.<init>(BootstrapContextImpl.java:89)
    at app//org.hibernate.boot.internal.MetadataBuilderImpl.<init>(MetadataBuilderImpl.java:124)
    at app//org.hibernate.boot.MetadataSources.getMetadataBuilder(MetadataSources.java:158)
    at app//org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.<init>(EntityManagerFactoryBuilderImpl.java:250)
    at app//org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.<init>(EntityManagerFactoryBuilderImpl.java:182)
    at app//org.hibernate.reactive.provider.impl.ReactiveEntityManagerFactoryBuilder.<init>(ReactiveEntityManagerFactoryBuilder.java:34)
    at app//org.hibernate.reactive.provider.ReactivePersistenceProvider.getEntityManagerFactoryBuilder(ReactivePersistenceProvider.java:145)
    at app//org.hibernate.reactive.provider.ReactivePersistenceProvider.getEntityManagerFactoryBuilderOrNull(ReactivePersistenceProvider.java:95)
    at app//org.hibernate.reactive.provider.ReactivePersistenceProvider.createEntityManagerFactory(ReactivePersistenceProvider.java:47)
    at app//javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:79)
    at app//io.vertx.howtos.hr.MainVerticle.lambda$asyncStart$0(MainVerticle.java:48)
    at app//io.vertx.howtos.hr.MainVerticle$$Lambda$94/0x0000000800d109c0.get(Unknown Source)
    at app//io.smallrye.mutiny.operators.uni.builders.UniCreateFromDeferredSupplier.subscribe(UniCreateFromDeferredSupplier.java:25)
    at app//io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
    at app//io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:50)
    at app//io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:90)
    at app//io.vertx.mutiny.core.Vertx$3.handle(Vertx.java:666)
    at app//io.vertx.mutiny.core.Vertx$3.handle(Vertx.java:664)
    at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
    at app//io.vertx.core.impl.ContextImpl$$Lambda$130/0x0000000800d25a40.handle(Unknown Source)
    at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
    at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
    at app//io.vertx.core.impl.ContextImpl$$Lambda$128/0x0000000800d27378.run(Unknown Source)
    at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
    at app//io.vertx.core.impl.TaskQueue$$Lambda$89/0x0000000800d0eaa0.run(Unknown Source)
    at java.base@17.0.4.1/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base@17.0.4.1/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base@17.0.4.1/java.lang.Thread.run(Thread.java:833)
2022-10-03 16:40:41,693 WARN [vertx-blocked-thread-checker] io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 63322 ms, time limit is 60000 ms
^C

Command killed by keyboard interrupt

To adapt the sample for google cloud run, we have made following modifications:

  1. remove
    <dependency>
      <groupId>org.testcontainers</groupId>
      <artifactId>postgresql</artifactId>
      <version>${testcontainers.version}</version>
    </dependency>

and add

        <dependency>
      <groupId>io.smallrye.reactive</groupId>
      <artifactId>smallrye-mutiny-vertx-mysql-client</artifactId>
      <version>${mutiny-vertx.version}</version>
    </dependency>
  1. modify the Java code and persistence.xml accordingly

  2. We use the Maven Jib plugin to build a Docker image that is required by google cloud run. The base image we use is amazoncorretto:17.0.4

I understand people here might not be able to provide help as I think this has something to do with the Docker image built by Jib but I was wondering if someone can at least tell how to modify the code in MainVerticle so that we can see the actual exception and program should halt instead of getting a io.vertx.core.VertxException: Thread blocked. It looks like the original exception has been lost and does not propagate to the main thread.

tsegismont commented 2 years ago

Jib puts libraries in a separate image layer, perhaps that's related to the time spent scanning the classpath. Although more than a minute to do this sounds very weird.

Perhaps there's an issue in the persistence.xml file. Or with Coretto in this environment.

siddjain commented 2 years ago

we are using the same persistence.xml as in this repo and overriding some fields using below code:

var props = new HashMap<String, String>();
    fetch("javax.persistence.jdbc.url", props);
    fetch("javax.persistence.jdbc.password", props);
    fetch("javax.persistence.jdbc.user", props);
    emf = Persistence
        .createEntityManagerFactory("pg-demo", props)
        .unwrap(Mutiny.SessionFactory.class);

we also tried using eclipse temurin but the same issue persists. One thing we have noticed is that the callstack is not identical everytime but each time the thread is blocked in the call to:

Persistence.createEntityManagerFactory

I did not understand this:

Jib puts libraries in a separate image layer, perhaps that's related to the time spent scanning the classpath.

we also changed the code like this and added a try/catch block:

        Uni<Void> startHibernate = Uni.createFrom().deferred(() -> {
            try {
                var props = new HashMap<String, String>();
                fetch("javax.persistence.jdbc.url", props);
                fetch("javax.persistence.jdbc.password", props);
                fetch("javax.persistence.jdbc.user", props);
                emf = Persistence
                        .createEntityManagerFactory("pg-demo", props)
                        .unwrap(Mutiny.SessionFactory.class);
                return Uni.createFrom().voidItem();
            } catch (Exception e) {
                return Uni.createFrom().failure(e);
            }
        });

Question for you: Without the try/catch block, if there is an exception in Persistence.createEntityManagerFactory, it will not propagate to main program and will be lost. is that correct?

tsegismont commented 2 years ago

I did not understand this:

Jib puts libraries in a separate image layer, perhaps that's related to the time spent scanning the classpath.

See https://github.com/GoogleContainerTools/jib#how-jib-works

Question for you: Without the try/catch block, if there is an exception in Persistence.createEntityManagerFactory, it will not propagate to main program and will be lost. is that correct?

I don't believe so, deferred should catch the exception and report it to the subscriber.

siddjain commented 2 years ago

any tips you can provide to help us debug? so far it seems then there is no exception, the thread is really blocked. we are unable to capture a thread dump because its running in cloud run environment.

tsegismont commented 2 years ago

Have you tried the debug mode? https://cloud.google.com/code/docs/intellij/debug-service