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

Hibernate bumps to leads to NPE when using identity generation and batching inserts #40425

Closed
michalvavrik opened this issue May 2, 2024 · 22 comments · Fixed by #40861
Closed
Assignees
Labels
area/hibernate-reactive Hibernate Reactive area/persistence OBSOLETE, DO NOT USE kind/bug Something isn't working
Milestone

Comments

@michalvavrik
Copy link
Member

Describe the bug

After #40102 our app has NPEs and constrain validation failures for values that are clearly within limit.

Expected behavior

No NPE, no validation failure.

Actual behavior

00:44:00,489 INFO  [app] org.hibernate.HibernateException: java.lang.NullPointerException: Cannot invoke "java.util.concurrent.CompletionStage.toCompletableFuture()" because the return value of "java.util.function.Function.apply(Object)" is null
00:44:00,490 INFO  [app] 	at org.hibernate.reactive.session.impl.ReactiveExceptionConverter.convert(ReactiveExceptionConverter.java:28)
00:44:00,490 INFO  [app] 	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.lambda$doFlush$27(ReactiveSessionImpl.java:988)
00:44:00,491 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)
00:44:00,491 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911)
00:44:00,492 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
00:44:00,492 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2194)
00:44:00,493 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.lambda$unroll$0(AsyncTrampoline.java:123)
00:44:00,494 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
00:44:00,494 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
00:44:00,495 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
00:44:00,495 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2179)
00:44:00,496 INFO  [app] 	at io.vertx.core.Future.lambda$toCompletionStage$3(Future.java:581)
00:44:00,496 INFO  [app] 	at io.vertx.core.impl.future.FutureImpl$4.onSuccess(FutureImpl.java:176)
00:44:00,497 INFO  [app] 	at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:66)
00:44:00,497 INFO  [app] 	at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:259)
00:44:00,498 INFO  [app] 	at io.vertx.sqlclient.impl.QueryResultBuilder.tryComplete(QueryResultBuilder.java:88)
00:44:00,498 INFO  [app] 	at io.vertx.sqlclient.impl.QueryResultBuilder.tryComplete(QueryResultBuilder.java:32)
00:44:00,498 INFO  [app] 	at io.vertx.core.Promise.complete(Promise.java:66)
00:44:00,499 INFO  [app] 	at io.vertx.core.Promise.handle(Promise.java:51)
00:44:00,499 INFO  [app] 	at io.vertx.core.Promise.handle(Promise.java:29)
00:44:00,500 INFO  [app] 	at io.vertx.core.impl.future.FutureImpl$4.onSuccess(FutureImpl.java:176)
00:44:00,500 INFO  [app] 	at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:66)
00:44:00,501 INFO  [app] 	at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:259)
00:44:00,501 INFO  [app] 	at io.vertx.core.impl.future.PromiseImpl.onSuccess(PromiseImpl.java:49)
00:44:00,501 INFO  [app] 	at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:41)
00:44:00,502 INFO  [app] 	at io.vertx.sqlclient.impl.TransactionImpl.lambda$wrap$0(TransactionImpl.java:72)
00:44:00,502 INFO  [app] 	at io.vertx.core.impl.future.FutureImpl$4.onSuccess(FutureImpl.java:176)
00:44:00,503 INFO  [app] 	at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:60)
00:44:00,503 INFO  [app] 	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
00:44:00,504 INFO  [app] 	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
00:44:00,504 INFO  [app] 	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
00:44:00,504 INFO  [app] 	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
00:44:00,505 INFO  [app] 	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
00:44:00,505 INFO  [app] 	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
00:44:00,506 INFO  [app] 	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
00:44:00,506 INFO  [app] 	at java.base/java.lang.Thread.run(Thread.java:1583)
00:44:00,507 INFO  [app] Caused by: java.lang.NullPointerException: Cannot invoke "java.util.concurrent.CompletionStage.toCompletableFuture()" because the return value of "java.util.function.Function.apply(Object)" is null
00:44:00,507 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
00:44:00,508 INFO  [app] 	... 27 more
00:41:52,230 INFO  [app] Caused by: jakarta.validation.ConstraintViolationException: Validation failed for classes [io.quarkus.ts.hibernate.reactive.database.Author] during persist time for groups [jakarta.validation.groups.Default, ]
00:41:52,230 INFO  [app] List of constraint violations:[
00:41:52,230 INFO  [app] 	ConstraintViolationImpl{interpolatedMessage='size must be between 0 and 10', propertyPath=name, rootBeanClass=class io.quarkus.ts.hibernate.reactive.database.Author, messageTemplate='{jakarta.validation.constraints.Size.message}'}
00:41:52,230 INFO  [app] ]
00:41:52,230 INFO  [app] 	at org.hibernate.boot.beanvalidation.BeanValidationEventListener.validate(BeanValidationEventListener.java:151)
00:41:52,230 INFO  [app] 	at org.hibernate.boot.beanvalidation.BeanValidationEventListener.onPreInsert(BeanValidationEventListener.java:81)
00:41:52,230 INFO  [app] 	at org.hibernate.action.internal.EntityInsertAction.preInsert(EntityInsertAction.java:251)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.engine.impl.ReactiveEntityRegularInsertAction.reactiveExecute(ReactiveEntityRegularInsertAction.java:59)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.engine.impl.ReactiveEntityInsertActionHolder.reactiveExecute(ReactiveEntityInsertActionHolder.java:62)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.engine.ReactiveActionQueue.lambda$executeActions$9(ReactiveActionQueue.java:631)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.util.impl.CompletionStages.lambda$loop$7(CompletionStages.java:410)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.util.impl.CompletionStages$ArrayLoop.next(CompletionStages.java:484)
00:41:52,230 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline.lambda$asyncWhile$1(AsyncTrampoline.java:215)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.unroll(AsyncTrampoline.java:121)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.trampoline(AsyncTrampoline.java:102)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline.asyncWhile(AsyncTrampoline.java:197)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.async.impl.AsyncTrampoline.asyncWhile(AsyncTrampoline.java:215)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.impl.CompletionStages.loop(CompletionStages.java:411)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.util.impl.CompletionStages.loop(CompletionStages.java:382)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.engine.ReactiveActionQueue.executeActions(ReactiveActionQueue.java:628)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.engine.ReactiveActionQueue.lambda$executeActions$7(ReactiveActionQueue.java:526)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.engine.ReactiveActionQueue.executeActions(ReactiveActionQueue.java:526)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.event.impl.AbstractReactiveFlushingEventListener.performExecutions(AbstractReactiveFlushingEventListener.java:63)
00:41:52,231 INFO  [app] 	at org.hibernate.reactive.event.impl.DefaultReactiveFlushEventListener.lambda$reactiveOnFlush$0(DefaultReactiveFlushEventListener.java:42)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341)
00:41:52,231 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144)
00:41:52,232 INFO  [app] 	at org.hibernate.reactive.event.impl.DefaultReactiveFlushEventListener.reactiveOnFlush(DefaultReactiveFlushEventListener.java:42)
00:41:52,232 INFO  [app] 	at org.hibernate.event.service.internal.EventListenerGroupImpl.lambda$fireEventOnEachListener$0(EventListenerGroupImpl.java:153)
00:41:52,232 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
00:41:52,232 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341)
00:41:52,232 INFO  [app] 	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144)
00:41:52,232 INFO  [app] 	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:153)
00:41:52,232 INFO  [app] 	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.doFlush(ReactiveSessionImpl.java:982)
00:41:52,232 INFO  [app] 	... 117 more

How to Reproduce?

git clone git@github.com:quarkus-qe/quarkus-test-suite.git
cd quarkus-test-suite/sql-db/hibernate-reactive
mvn clean verify -Dreruns=0

The app code transforms errors to 400, so you might need to tweak it for debugging.

Output of uname -a or ver

Fedora 38

Output of java -version

OpenJDK 17

Quarkus version or git rev

999-SNAPSHOT

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

Apache Maven 3.9.4

Additional information

No response

@michalvavrik michalvavrik added kind/bug Something isn't working area/hibernate-validator Hibernate Validator area/hibernate-reactive Hibernate Reactive labels May 2, 2024
@quarkus-bot quarkus-bot bot added the area/persistence OBSOLETE, DO NOT USE label May 2, 2024
Copy link

quarkus-bot bot commented May 2, 2024

/cc @DavideD (hibernate-reactive), @gavinking (hibernate-reactive)

@michalvavrik
Copy link
Member Author

cc @yrodiere @Sanne

@yrodiere
Copy link
Member

yrodiere commented May 3, 2024

Hey @DavideD , could this be a regression in Hibernate Reactive?

@DavideD
Copy link
Contributor

DavideD commented May 3, 2024

I guess. I will check.

@DavideD DavideD self-assigned this May 3, 2024
@DavideD
Copy link
Contributor

DavideD commented May 3, 2024

I have some test failures, but I see a different error.
I'm working on it

@DavideD
Copy link
Contributor

DavideD commented May 3, 2024

@michalvavrik Not sure if this is related, but an association in Hibernate is supposed to be mapped in a different way than the one in the tests.

It should be:

@Entity
class Book {
   ...
    @ManyToOne
    Author author;
   ...
}

Is there a specific reason for the test to use just the id?

@michalvavrik
Copy link
Member Author

michalvavrik commented May 3, 2024

I have some test failures, but I see a different error.

Sorry, it was late night, if you want adjustments to the reproduce, just shout!

Is there a specific reason for the test to use just the id?

Hey @DavideD ,

In general, we just try to identify legit cases, I don't think it is required for this particular test. So we can change this. Before we do so, I'd like to understand this is not supported / encouraged use case:

class Book {
@NotNull
private Integer author;
}

I'd think that mapping only id when I don't need to work with entity is logical. I suppose if an entity instance is lazy loaded but still contains PK (that is loaded eagerly) then I can use the entity data type instead. So people shouldn't do this but it worked (with quotes :-)) in past and now the validation is improved?

@DavideD
Copy link
Contributor

DavideD commented May 3, 2024

It's supported in the sense that it should work for simple cases. Not encouraged.

But:

  • it's not mentioned in the official Hibernate documentation
  • Hibernate is not aware that that's an association, meaning that they are not covered by these tests
  • users might not understand that this approach is not encouraged and copy it

That said, I don't know the requirements for this project.
And I don't think it's related to this issue, so I will move on.

@DavideD
Copy link
Contributor

DavideD commented May 3, 2024

Sorry, I couldn't figure out why it's not working in Quarkus.
I've created a test for Hibernate Reactive and it seems to work as expected.

I couldn't really launch the test suite, when I've tried manually the validation didn't seem to work.
I think an error is happening when Hibernate is trying to initialize Validator: https://github.com/hibernate/hibernate-orm/blob/9ba0dd7af03d63dc39ce0ac8acd6688803ea0af9/hibernate-core/src/main/java/org/hibernate/boot/beanvalidation/BeanValidationIntegrator.java#L139

In theory, it should call TypeSafeActivator, but something happens before reaching that point. But the debugger couldn't tell me anything.

It's worth mentioning, that if something goes wrong with the creation of the validator factory, Hibernate won't say anything about it.

I don't think I will have more time to work on this, if somebody wants to continue.

@michalvavrik
Copy link
Member Author

Thank you for the time you put into the investigation @DavideD .

fedinskiy added a commit to fedinskiy/reproducer that referenced this issue May 6, 2024
@fedinskiy
Copy link
Contributor

fedinskiy commented May 6, 2024

@DavideD I prepared a minimalistic reproducer, which doesn't involve the TS.

  1. git clone https://github.com/fedinskiy/reproducer -b db-panache-no-update
  2. mvn quarkus:dev
  3. curl -X PUT http://localhost:8080/library/book/2/Around_the_World_in_Eighty_Days # fails
  4. mvn quarkus:dev -Dquarkus.platform.version=3.10.0
$ curl -X PUT http://localhost:8080/library/book/2/Around_the_World_in_Eighty_Days # succeeds
4
$ curl -XGET http://localhost:8080/library/book/4
Around_the_World_in_Eighty_Days

There is also a test, ResourceTest, which does the same. mvn clean test fails, mvn clean test -Dquarkus.platform.version=3.10.0 succeeds

UPD: It also looks like, that this error affects Postgres and Oracle, but not MariaDB, MySQL, or MSSQL

@DavideD
Copy link
Contributor

DavideD commented May 7, 2024

Thanks a lot! I can finally see the nullpointer and I'm trying to figure out what's going on.

@DavideD
Copy link
Contributor

DavideD commented May 7, 2024

Ooops...

@fedinskiy
Copy link
Contributor

@DavideD "debugging is a murder mystery, there you are a detective, a culprit and a victim".

Can we expect a fix during this week, or we better disable the affected tests for a while?

@yrodiere
Copy link
Member

yrodiere commented May 7, 2024

Can we expect a fix during this week, or we better disable the affected tests for a while?

The latter. Even if @DavideD is going to work during his PTO (bad!), there's little chance the fix makes its way to a Hibernate Reactive release and a Quarkus release by the end of the week.

@DavideD
Copy link
Contributor

DavideD commented May 8, 2024

Yes, sorry. Like Yoann said. At the moment, I can't make any promises.

@gsmet
Copy link
Member

gsmet commented May 13, 2024

Ideally, let's make sure we have a small test in Quarkus that verifies that.

@DavideD
Copy link
Contributor

DavideD commented May 23, 2024

This PR should solve the problem: hibernate/hibernate-reactive#1916
I've tested it with the reproducer and it seems to work as expected after the patch.

Note the Hibernate Validator wasn't the issue, the problem appears when using identity generation and batching inserts.
We didn't have a test in Hibernate Reactive for this specific use case and so we missed it.

@gsmet
Copy link
Member

gsmet commented May 23, 2024

@DavideD chances are I will do a 3.11.1 next Wednesday so if you can upgrade Hibernate Reactive by let's say next Monday (we have the Quarkus F2F next week so things will be a bit hectic on my side) it could be in it.

@DavideD
Copy link
Contributor

DavideD commented May 23, 2024

Seems doable.

@michalvavrik michalvavrik changed the title Hibernate bumps to leads to Hibernate Reactive NPE and Hibernate Validation constraint validation failures where it shouldn't Hibernate bumps to leads to NPE when using identity generation and batching inserts May 23, 2024
@michalvavrik michalvavrik removed the area/hibernate-validator Hibernate Validator label May 23, 2024
@DavideD
Copy link
Contributor

DavideD commented May 28, 2024

This issue should be fixed by the Hibernate Reactive upgrade to 2.3.1.Final

@michalvavrik
Copy link
Member Author

This issue should be fixed by the Hibernate Reactive upgrade to 2.3.1.Final

thank you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/hibernate-reactive Hibernate Reactive area/persistence OBSOLETE, DO NOT USE kind/bug Something isn't working
Projects
None yet
5 participants