NPE warning in native mode

[yanxuehe]

Describe the bug

2023-12-29 02:00:22,008 WARN  [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread) HHH000342: Could not obtain connection to query metadata: java.lang.NullPointerException
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.doTheWork(JtaIsolationDelegate.java:186)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.lambda$delegateWork$1(JtaIsolationDelegate.java:75)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.doInSuspendedTransaction(JtaIsolationDelegate.java:107)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.delegateWork(JtaIsolationDelegate.java:72)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.getJdbcEnvironmentUsingJdbcMetadata(JdbcEnvironmentInitiator.java:279)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:193)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:69)
	at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:119)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:264)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:239)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:216)
	at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:52)
	at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:125)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:248)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:216)
	at org.hibernate.boot.internal.SessionFactoryOptionsBuilder.<init>(SessionFactoryOptionsBuilder.java:273)
	at io.quarkus.hibernate.orm.runtime.recording.PrevalidatedQuarkusMetadata.buildSessionFactoryOptionsBuilder(PrevalidatedQuarkusMetadata.java:70)
	at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:81)
	at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:74)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
	at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:156)
	at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:64)
	at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
	at [email protected]/java.lang.Thread.run(Thread.java:1583)
	at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:832)
	at org.graalvm.nativeimage.builder/com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:211)

Expected behavior

no warnings.

Actual behavior

No response

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

21

Mandrel or GraalVM version (if different from Java)

with docker builder

Quarkus version or git rev

3.6.4

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

No response

Additional information

No response

[quarkus-bot[bot]]

/cc @Karm (mandrel), @galderz (mandrel), @zakkak (mandrel,native-image)

[gastaldi]

Can you please share a small reproducer?

[yanxuehe]

@gastaldi thanks for your help.

# java version
openjdk version "21.0.1" 2023-10-17
OpenJDK Runtime Environment GraalVM CE 21.0.1+12.1 (build 21.0.1+12-jvmci-23.1-b19)
OpenJDK 64-Bit Server VM GraalVM CE 21.0.1+12.1 (build 21.0.1+12-jvmci-23.1-b19, mixed mode, sharing)

# generate keystore
keytool -genkey -keyalg RSA -alias selfsigned -keystore keystore.jks -storepass changeit -validity 365 -keysize 2048

# build
./mvnw clean install \
  -Dmaven.test.skip=true \
  -Dnative \
-Dquarkus.native.additional-build-args=-J--enable-preview

# run (ref to application.yaml)
DB_USER=<> DB_PASS=<> DB_NAME=<> KEYSTORE_PASS=changeit ./target/37956-reproducer-1.0.0-SNAPSHOT-runner

37956-reproducer.zip

[gastaldi]

It seems that you're using H2 and that the server isn't running when the runner JAR is invoked?

[yanxuehe]

No, h2 is used for the dev profile. the runner jar is with db2.

the db2 is up and running when the runner is starting

[gastaldi]

I've run your reproducer locally against a running DB2 instance and I don't see the stacktrace you mentioned. Are you sure you have correctly set the DB_HOST environment on your end?

This is my output:

DB_USER=user DB_PASS=password DB_NAME=quarkus DB_HOST=my.host.com KEYSTORE_PASS=changeit ./target/37956-reproducer-1.0.0-SNAPSHOT-runner
Hibernate: create table TestEntity (id bigint not null, name varchar(255), primary key (id))
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2024-01-09 11:03:11,239 INFO  [com.tes.Startup] (main) Startup.init
2024-01-09 11:03:11,348 INFO  [io.quarkus] (main) 37956-reproducer 1.0.0-SNAPSHOT native (powered by Quarkus 3.6.4) started in 2.047s. Listening on: http://0.0.0.0:8080 and https://0.0.0.0:8443
2024-01-09 11:03:11,348 INFO  [io.quarkus] (main) Profile prod activated.
2024-01-09 11:03:11,348 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, config-yaml, hibernate-orm, hibernate-orm-panache, hibernate-validator, jdbc-db2, jdbc-h2, kafka-client, kubernetes, narayana-jta, rest-client, rest-client-jackson, rest-client-mutiny, resteasy, resteasy-jackson, security, security-jpa, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, smallrye-jwt, smallrye-openapi, smallrye-reactive-messaging, smallrye-reactive-messaging-kafka, vertx]

[yanxuehe]

@gastaldi

i tried with postgres the warn issue will be gone, for db2 it will come for always (db2 on our lab and db2 on my podman)

could it be something wrong in the driver?

podman run -d --name db2server --restart=always --detach --privileged=true -p  50000:50000 --env-file env_list.txt icr.io/db2_community/db2

cat env_list.txt
LICENSE=accept
DB2INSTANCE=db2inst1
DB2INST1_PASSWORD=password
DBNAME=quarkus
BLU=false
ENABLE_ORACLE_COMPATIBILITY=false
UPDATEAVAIL=NO
TO_CREATE_SAMPLEDB=true
REPODB=true
IS_OSXFS=false
PERSISTENT_HOME=false
HADR_ENABLED=false
ETCD_ENDPOINT=
ETCD_USERNAME=
ETCD_PASSWORD=

[gastaldi]

Can you post the complete output? It looks like the output in the issue description is caused by another error?

[yanxuehe]

➜ mne 37956-reproducer
➜ 37956-reproducer (develop) ✗ DB_HOST=10.0.0.10 DB_USER=db2inst1 DB_PASS=password DB_TYPE=db2 DB_NAME=MNEAAS KEYSTORE_PASS=changeit ./target/37956-reproducer-1.0.0-SNAPSHOT-runner
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2024-01-12 21:56:17,656 WARN  [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread) HHH000342: Could not obtain connection to query metadata: java.lang.NullPointerException
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.doTheWork(JtaIsolationDelegate.java:186)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.lambda$delegateWork$1(JtaIsolationDelegate.java:75)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.doInSuspendedTransaction(JtaIsolationDelegate.java:107)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate.delegateWork(JtaIsolationDelegate.java:72)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.getJdbcEnvironmentUsingJdbcMetadata(JdbcEnvironmentInitiator.java:279)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:193)
	at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:69)
	at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:119)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:264)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:239)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:216)
	at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:52)
	at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:125)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:248)
	at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:216)
	at org.hibernate.boot.internal.SessionFactoryOptionsBuilder.<init>(SessionFactoryOptionsBuilder.java:273)
	at io.quarkus.hibernate.orm.runtime.recording.PrevalidatedQuarkusMetadata.buildSessionFactoryOptionsBuilder(PrevalidatedQuarkusMetadata.java:70)
	at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:81)
	at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:74)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
	at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:156)
	at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:64)
	at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
	at [email protected]/java.lang.Thread.run(Thread.java:1583)
	at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:832)
	at org.graalvm.nativeimage.builder/com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:211)

2024-01-12 21:56:17,677 INFO  [com.tes.Startup] (main) Startup.init
2024-01-12 21:56:17,805 INFO  [io.quarkus] (main) 37956-reproducer 1.0.0-SNAPSHOT native (powered by Quarkus 3.6.4) started in 5.191s. Listening on: http://0.0.0.0:8080 and https://0.0.0.0:8443
2024-01-12 21:56:17,805 INFO  [io.quarkus] (main) Profile prod activated.
2024-01-12 21:56:17,805 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, config-yaml, hibernate-orm, hibernate-orm-panache, hibernate-validator, jdbc-db2, kafka-client, kubernetes, narayana-jta, rest-client, rest-client-jackson, rest-client-mutiny, resteasy-jackson, security, security-jpa, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, smallrye-jwt, smallrye-openapi, smallrye-reactive-messaging, smallrye-reactive-messaging-kafka, vertx]

[gastaldi]

I tried my reproducer again and I don't see this error. Maybe this is a dumb question, but can you connect to the DB in 10.0.0.10 using another local client?

[yanxuehe]

yes, i am 100% sure it is connectable.

[marko-bekhta]

hey, I've tried to reproduce this one with no luck as well 😕. But I did notice that the reason why Hibernate couldn't obtain the connection may be eaten by that java.lang.NullPointerException we see in the logs you've provided, so I've opened a PR here https://github.com/hibernate/hibernate-orm/pull/7865

Do you only see this error in native mode? Could you please try to use DB2 in dev and see if you get the error there?

[yanxuehe]

hi,

sorry for the late response, the error comes for native only.

[galderz]

@marko-bekhta Is there already a Quarkus version that includes the fix you did for https://github.com/hibernate/hibernate-orm/pull/7865? If so maybe @yanxuehe can try and see what he sees now?

[marko-bekhta]

Hey,

the fix we are talking about is for https://hibernate.atlassian.net/browse/HHH-17872, which is included in Hibernate ORM 6.4.5 and 6.5.0... 6.4.5 is not yet released and 6.5.0 is a CR2 (https://github.com/quarkusio/quarkus/pull/40102) so for now it won't be trivial to test it 😔

[yrodiere]

@marko-bekhta We just merged an upgrade to Hibernate ORM 6.4.5 in Quarkus. Snapshots of Quarkus should get deployed by tomorrow 2AM UTC. Testing may be easier now?

Here are instructions to use Quarkus snapshots: https://github.com/quarkusio/quarkus/blob/main/CONTRIBUTING.md#using-snapshots

[marko-bekhta]

Nice! Let's ping @yanxuehe to see if that can be done.

[yrodiere]

Closing due to being unable to reproduce, and lack of update. Feel free to comment/reopen if you have more information @yanxuehe.