Example fails with ORM 5.4.24 #453

DavideD · 2020-11-20T14:00:42Z

Example of one of the logs using org.hibernate:hibernate-core:5.5.0-SNAPSHOT:20201117.201048-196:

Feersum Endjinn is a great book!
[ERROR] failed to execute statement [select author0_.id as id1_0_0_, author0_.name as name2_0_0_ from authors author0_ where author0_.id in (?,?)]
[ERROR] could not load an entity batch: [org.hibernate.example.reactive.Author#<1, 3>]
java.util.concurrent.CompletionException: org.hibernate.LazyInitializationException: Collection cannot be initialized: org.hibernate.example.reactive.Author.books
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:673) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:683) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2010) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:110) ~[?:1.8.0_275]
	at org.hibernate.reactive.loader.ReactiveLoaderBasedResultSetProcessor.reactiveInitializeEntitiesAndCollections(ReactiveLoaderBasedResultSetProcessor.java:150) ~[hibernate-reactive-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.hibernate.reactive.loader.ReactiveLoaderBasedResultSetProcessor.reactiveExtractResults(ReactiveLoaderBasedResultSetProcessor.java:83) ~[hibernate-reactive-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
Error: Exception in thread "main" java.util.concurrent.CompletionException: org.hibernate.LazyInitializationException: Collection cannot be initialized: org.hibernate.example.reactive.Author.books
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
	at org.hibernate.reactive.loader.ReactiveLoader.reactiveProcessResultSet(ReactiveLoader.java:123) ~[hibernate-reactive-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.hibernate.reactive.loader.ReactiveLoader.lambda$doReactiveQueryAndInitializeNonLazyCollections$0(ReactiveLoader.java:71) ~[hibernate-reactive-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at java.util.concurrent.CompletableFuture.uniCompose(CompletableFuture.java:966) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:940) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_275]
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) ~[?:1.8.0_275]

...

Caused by: org.hibernate.LazyInitializationException: Collection cannot be initialized: org.hibernate.example.reactive.Author.books
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.initializeCollection(ReactiveSessionImpl.java:320)
	at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:589)
	at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264)
	at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:585)
	at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:149)

The text was updated successfully, but these errors were encountered:

gavinking · 2020-11-20T14:23:14Z

Goops, you're right: @Sanne and I both missed this because of other spurious failures in the CI.

gavinking · 2020-11-20T14:25:46Z

I hazard a guess that this is related to #443.

DavideD · 2020-11-20T18:56:08Z

Is that issue related to DirtyChecking?
I think that problem is related to this: #447

Anyway, it happens after the update to ORM 5.4.24

gavinking · 2020-11-23T18:35:56Z

Is that issue related to DirtyChecking?

Well, I figured that the bug is related to batch loading. I might be wrong though.

gavinking · 2020-11-23T18:49:21Z

Is that issue related to DirtyChecking?

Well, I figured that the bug is related to batch loading. I might be wrong though.

Oh well, it looks like I'm wrong and the problem is indeed elsewhere.

DavideD · 2020-11-23T18:57:48Z

I'm working on a test case. Hopefully I will be able to confirm this soon enough.

It makes sense though because only the example fails and it is the only place where we enable the bytecode enhancements

gavinking · 2020-11-23T19:27:15Z

OK, great.

DavideD · 2020-11-24T16:55:42Z

So, yes. The problem is the dirty checking of the collection when byte code enhancements are enabled. I don't know why it was working before. Probably, this bug in ORM was hiding the problem and now that it's fixed we see it.

gavinking · 2020-11-24T17:09:16Z

Uff, what a PITA.

gavinking · 2020-11-24T17:30:58Z

OTOH, why does collection dirty checking even matter when we don't even have CollectionPersisters yet?

DavideD · 2020-11-24T17:56:24Z

This is the issue:

The enhanced method $$_hibernate_hasDirtyAttributes has changed, from

    public boolean $$_hibernate_hasDirtyAttributes() {
        boolean var1 = false;
        var1 = this.$$_hibernate_tracker != null && !this.$$_hibernate_tracker.isEmpty();
        return var1;
    }

to

    public boolean $$_hibernate_hasDirtyAttributes() {
        boolean var1 = false;
        var1 = this.$$_hibernate_tracker != null && !this.$$_hibernate_tracker.isEmpty() || this.$$_hibernate_areCollectionFieldsDirty();
        return var1;
    }

    public boolean $$_hibernate_areCollectionFieldsDirty() {
        boolean var1 = false;
        if (!var1 && this.$$_hibernate_collectionTracker != null) {
            if (this.movies == null && this.$$_hibernate_collectionTracker.getSize("movies") != -1) {
                var1 = true;
            } else if (this.movies != null && this.$$_hibernate_collectionTracker.getSize("movies") != this.movies.size()) {
                var1 = true;
            }
        }

        return var1;
    }

the call to this.movies.size() causes a LazyInitializationException

DavideD · 2020-11-24T17:56:55Z

movies is the name of the association inside the test I've created

gavinking · 2020-11-24T19:50:33Z

@DavideD so do you think that what is going on here is just that we don't have transparent lazy init (i.e. it is missing a call to fetch()), or is it something deeper?

gavinking · 2020-11-24T19:59:23Z

@DavideD I've commented on hibernate/hibernate-orm#3645, because that call to size() doesn't look right to me. (But I could easily be missing something.)

DavideD · 2020-11-25T08:06:49Z

@DavideD so do you think that what is going on here is just that we don't have transparent lazy init (i.e. it is missing a call to fetch()), or is it something deeper?

I think that's the issue. I'm trying to see if I can fetch the collection somewhere so that it is already fetched.
By the way, everything works if I set the association for EAGER fetching.

gavinking · 2020-11-25T08:15:57Z

I'm trying to see if I can fetch the collection somewhere so that it is already fetched.

OK, but don't kill yourself on that right now because it still feels wrong to me that we're fetching an un fetched association with mappedBy just to dirty check its elements. Let's see what @beikov and @Sanne have to say.

(OTOH, even if core isn't doing the right thing in this particular case, we still might need the fix your working on in other cases.)

DavideD · 2020-11-25T08:19:16Z

For additional info, this is branch with the test case (still a work in progress): https://github.com/DavideD/hibernate-reactive/tree/447-dirtychecking

Test:
https://github.com/DavideD/hibernate-reactive/blob/447-dirtychecking/it-bytecode-enhancements/src/test/java/org/hibernate/reactive/it/bytecodeenhancements/BytecodeTest.java

Entities:
https://github.com/DavideD/hibernate-reactive/tree/447-dirtychecking/it-bytecode-enhancements/src/main/java/org/hibernate/reactive/it/bytecodenhancements

DavideD · 2020-11-25T08:20:41Z

Thanks @gavinking

beikov · 2020-11-25T10:21:43Z

Why is the movies collection != null? I tried to reproduce this in core, but couldn't because such a collection should never be non-null if lazy.

gavinking · 2020-11-25T10:33:19Z

Well I recall that there was a kinda long discussion somewhere. An issue I opened where I argued that this "double-laziness" or collections was at least arguably bad in Hibernate ORM, and a much worse problem for HR, where fetching isn't transparent. We need to let you obtain a reference to the collection to call fetch() on it.

gavinking · 2020-11-25T10:43:06Z

OK found it. So could this be related to #374?

gavinking · 2020-11-25T10:46:28Z

And hibernate/hibernate-orm#3558

beikov · 2020-11-25T11:01:54Z

Is collectionsInDefaultFetchGroupEnabled always true in RX?

beikov · 2020-11-25T11:10:16Z

Hmm, if I set it to true, the collection is eagerly initialized.

gavinking · 2020-11-25T11:10:49Z

Is collectionsInDefaultFetchGroupEnabled always true in RX?

Yup, it is.

gavinking · 2020-11-25T11:11:35Z

Hmm, if I set it to true, the collection is eagerly initialized.

Ummmm ... really? That wasn't the intention!

gavinking · 2020-11-25T11:12:48Z

collectionsInDefaultFetchGroupEnabled is supposed to just include the collection proxy in the default fetch group. It's not supposed to actually fetch the collection itself.

So either I totally screwed up, or something has changed since I wrote that code.

beikov · 2020-11-25T11:21:28Z

I'm with you that the current approach to enhancement is not ideal and that the field should be initialized to a persistent collection, but I think that the issue you are having in RX might be caused by something else. When I set the flag to true, I see the collection being initialized through this trace:

org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:585)
org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:149)
org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:178)
org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:163)
org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264)
org.hibernate.collection.internal.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:162)
org.hibernate.collection.internal.PersistentBag.size(PersistentBag.java:371)
org.hibernate.test.bytecode.enhancement.dirty.DirtyTrackingCollectionTest$StringsEntity.$$_hibernate_removeDirtyFields(DirtyTrackingCollectionTest.java)
org.hibernate.test.bytecode.enhancement.dirty.DirtyTrackingCollectionTest$StringsEntity.$$_hibernate_clearDirtyCollectionNames(DirtyTrackingCollectionTest.java)
org.hibernate.test.bytecode.enhancement.dirty.DirtyTrackingCollectionTest$StringsEntity.$$_hibernate_clearDirtyAttributes(DirtyTrackingCollectionTest.java)
org.hibernate.tuple.entity.PojoEntityTuplizer.afterInitialize(PojoEntityTuplizer.java:228)
org.hibernate.persister.entity.AbstractEntityPersister.afterInitialize(AbstractEntityPersister.java:5093)
org.hibernate.engine.internal.TwoPhaseLoad.afterInitialize(TwoPhaseLoad.java:405)
org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.afterInitialize(AbstractRowReader.java:271)
org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.finishUp(AbstractRowReader.java:214)
org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl.extractResults(ResultSetProcessorImpl.java:96)
org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:105)
org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:285)
org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:4441)
org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4431)
org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:569)
org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:537)
org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:208)
org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:332)
org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:108)
org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:74)
org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:121)
org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1186)
org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1175)
org.hibernate.internal.SessionImpl.access$2100(SessionImpl.java:193)
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2786)
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.lambda$load$1(SessionImpl.java:2767)
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.perform(SessionImpl.java:2723)
org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2767)
org.hibernate.internal.SessionImpl.find(SessionImpl.java:3322)
org.hibernate.internal.SessionImpl.find(SessionImpl.java:3284)
org.hibernate.test.bytecode.enhancement.dirty.DirtyTrackingCollectionTest.lambda$test$1(DirtyTrackingCollectionTest.java:57)
org.hibernate.testing.transaction.TransactionUtil.doInJPA(TransactionUtil.java:235)
org.hibernate.testing.transaction.TransactionUtil.doInJPA(TransactionUtil.java:276)
org.hibernate.test.bytecode.enhancement.dirty.DirtyTrackingCollectionTest.test(DirtyTrackingCollectionTest.java:56)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
org.hibernate.testing.junit4.ExtendedFrameworkMethod.invokeExplosively(ExtendedFrameworkMethod.java:45)
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
java.lang.Thread.run(Thread.java:748)

gavinking · 2020-11-25T11:28:32Z

So $$_hibernate_removeDirtyFields() is calling size() on an uninitialized collection. Should it be?

DavideD · 2020-11-25T11:34:05Z

I'm with you that the current approach to enhancement is not ideal and that the field should be initialized to a persistent collection, but I think that the issue you are having in RX might be caused by something else. When I set the flag to true, I see the collection being initialized through this trace:

I'm probably missing something, but isn't this the same issue?
It's still calling size() but from a different method

beikov · 2020-11-25T12:06:30Z

You are right. Apparently the collections aren't registered as being lazy which causes this problem. I'm investigating now.

beikov · 2020-11-25T14:07:08Z

Here a PR that should fix these issues: hibernate/hibernate-orm#3664

DavideD · 2020-11-25T15:03:15Z

Thanks @beikov, the test seems to work using that branch

gavinking · 2020-11-25T18:42:40Z

@beikov excellent, thanks

gavinking · 2020-11-26T14:23:12Z

Thanks @beikov, the test seems to work using that branch

@DavideD can you retest now, @beikov just updated the PR, let's see if it still fixes the problem.

gavinking · 2020-11-27T21:08:51Z

Here a PR that should fix these issues: hibernate/hibernate-orm#3664

Confirmed, we just need a release of hibernate-core.

DavideD · 2020-12-01T17:23:47Z

Fixed by #463

Thanks all

DavideD added the bug Something isn't working label Nov 20, 2020

DavideD self-assigned this Nov 20, 2020

DavideD closed this as completed Nov 20, 2020

DavideD reopened this Nov 20, 2020

DavideD changed the title ~~Build fails with latest ORM 5.x~~ Build fails with latest ORM 5.4.24 Nov 20, 2020

DavideD changed the title ~~Build fails with latest ORM 5.4.24~~ Example fails with ORM 5.4.24 Nov 20, 2020

gavinking mentioned this issue Nov 24, 2020

HHH-14329 Test and fix for DirtinessTracker usage for enhanced entities doesn't respect mutable types hibernate/hibernate-orm#3645

Merged

DavideD closed this as completed Nov 25, 2020

DavideD reopened this Nov 25, 2020

DavideD linked a pull request Dec 1, 2020 that will close this issue

[#463] Upgrade to ORM 5.4.25 #464

Merged

DavideD closed this as completed Dec 1, 2020

m-jayson mentioned this issue Dec 17, 2020

Collection cannot be initialized: #492

Closed

chrisknoll mentioned this issue Jan 28, 2021

Vulnerabilities in hibernate-core OHDSI/WebAPI#1697

Closed

Example fails with ORM 5.4.24 #453

Example fails with ORM 5.4.24 #453

Comments

DavideD commented Nov 20, 2020 • edited

gavinking commented Nov 20, 2020

gavinking commented Nov 20, 2020

DavideD commented Nov 20, 2020 • edited

gavinking commented Nov 23, 2020

gavinking commented Nov 23, 2020

DavideD commented Nov 23, 2020

gavinking commented Nov 23, 2020

DavideD commented Nov 24, 2020

gavinking commented Nov 24, 2020

gavinking commented Nov 24, 2020

DavideD commented Nov 24, 2020

DavideD commented Nov 24, 2020 • edited

gavinking commented Nov 24, 2020

gavinking commented Nov 24, 2020

DavideD commented Nov 25, 2020

gavinking commented Nov 25, 2020 • edited

DavideD commented Nov 25, 2020

DavideD commented Nov 25, 2020

beikov commented Nov 25, 2020

gavinking commented Nov 25, 2020

gavinking commented Nov 25, 2020

gavinking commented Nov 25, 2020

beikov commented Nov 25, 2020

beikov commented Nov 25, 2020

gavinking commented Nov 25, 2020

gavinking commented Nov 25, 2020

gavinking commented Nov 25, 2020

beikov commented Nov 25, 2020

gavinking commented Nov 25, 2020

DavideD commented Nov 25, 2020

beikov commented Nov 25, 2020

beikov commented Nov 25, 2020

DavideD commented Nov 25, 2020

gavinking commented Nov 25, 2020

gavinking commented Nov 26, 2020

gavinking commented Nov 27, 2020

DavideD commented Dec 1, 2020

DavideD commented Nov 20, 2020 •

edited

DavideD commented Nov 20, 2020 •

edited

DavideD commented Nov 24, 2020 •

edited

gavinking commented Nov 25, 2020 •

edited