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 fails on complex orphanDelete=true cases and bump version upon merge calls involving entities without change #7462

Closed
masini opened this issue Feb 27, 2020 · 38 comments · Fixed by #44391
Labels
area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE kind/bug Something isn't working
Milestone

Comments

@masini
Copy link
Contributor

masini commented Feb 27, 2020

Describe the bug
A production application, working with 1.2.1 and ported to 1.3.0.Alpha2 stopped working with the aforementioned Exception during merge.

Expected behavior
No HibernateException

Actual behavior
An Exception is thrown

Environment (please complete the following information):

  • Output of java -version: 1.8.0_152-b16
  • Quarkus version or git rev: 1.3.0.Alpha2

Additional context
The code and Hibernate version are the same, but something in the Quarkus integration code is driving that difference in behaviour.

@masini masini added the kind/bug Something isn't working label Feb 27, 2020
@quarkusbot
Copy link

/cc @gsmet @Sanne

@quarkusbot quarkusbot added area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE labels Feb 27, 2020
@Sanne
Copy link
Member

Sanne commented Feb 27, 2020

Thanks @masini . Will you be able to provide a test?
Did it work with Alpha1 ?

@Sanne
Copy link
Member

Sanne commented Feb 28, 2020

on the mailing list, @emmanuelbernard suggested that this might be caused by us having disabled automatic management of bi-directional relations.

You might want to verify that all relations are consistently updated on both sides?

See examples of "righ" and "wrong" here:

@masini
Copy link
Contributor Author

masini commented Feb 28, 2020

Some information:

  1. Is plain JPA (was migrated from EclipseLink 2.6) and doesn't use Panache
  2. Can't try with Alpha1 because the app doesn't even start...

@emmanuelbernard
Copy link
Member

Also was mentioned that versioned entities were forcing version changes even if no change was actually real.

@emmanuelbernard
Copy link
Member

I tried a minimal project to reproduce what you saw especially the version bump.
But I cannot reproduce https://github.com/emmanuelbernard/quarkus-issue-7462

@masini
Copy link
Contributor Author

masini commented Mar 1, 2020

It tooks me hours to clean as much as I could from the original project with many submodules and classes, now it has only 70 classes and tests to reproduce the problems.

test-case-jpa.zip

To reproduce unzip the attached "reproducer" and from project dir:

./mvnw test

This should run two tests:

  • TestBarLayoutService.testSaveModalitaNotificaDelegate shows the fact that version behave differellty
  • TestMergeOrdine.testCreateAndMergeOrdine shows how the relationship now raise an error

Let me know if you need further infos to understand the problem.

@emmanuelbernard
Copy link
Member

Thanks @masini I've spent a few hours looking at your test.

You are using Lombok which making the debugging of collection mutation much harder (not that it's simple initially).

First off "org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance" can come from a few areas:

  1. in your code you set piattoOrdinato / use setPiattoOrdinato and replace the managed collection instance. This is the primary reason
  2. you have a faulty equals / hashCode implementation which makes Hibernate believes that the managed collection is unreacheable (i.e. not referenced by an entity anymore)

You use Lombok so I could not figure out whether Lombok was messing with 1. According to some people, it can as it changes the value of the collection when using the builder https://stackoverflow.com/a/49106446/200911 (the builder is used at creation time so that does not full compute to me. I noted quite a few calls to change the property but they seemed to come from Jackson deserializing things which I imagine are net new objects.

I see that you use identity equality in some entities and I am pretty sure that could potentially mess up with the merge operations. But I tried to remove them to no avail.

I understand that these proposed explanation do not explain why it was working in 1.2 and not in 1.3 Alpha. But we did disable the association management from being handled by the bytecode to having to be manual (a good practice). I suspect the bug shows up because your manual code does not update both sides of a relationship somewhere. I did not dig through your code to see if that was a correct assumption, it's quite hairy and I was running out of time.

Another question I have, in testCreateAndMergeOrdine, what is the meaning of ordiniResourceDelegate.salvaOrdine(ordineAperto);? I understand the prior line to save the newly created object. but not the meaning of this one.

@masini
Copy link
Contributor Author

masini commented Mar 6, 2020

Hi Emmanuel, thank you for your deep analisys.

I think that the setPiattoordinato is done during deserialization. The collection and the owner are also using @JsonManagedReference and @JsonBackReference, so that is Jackson that during deserialization take care of settings correctly the pointer around of the data coming from the client.

And debugging I can see that this is done correctly.

Maybe this is really the effect of a change tracking changes in Quarkus code ?

From what I understood debugging, I noticed that the problem come from the only collection mapped with orphanRemoval = true, which is PiattoOrdinati.abbinamento.

This come also from the client, is deserialized and when it is merged for some reason two collection instances exists with the same content, one pointed by PiattoOrdinato.abbinamento and the other not point by any other owning side.

From what experience what is wrong in our mapping that can cause this kind of problems ?

@masini
Copy link
Contributor Author

masini commented Mar 6, 2020

Now short answers to some of your questions:

  1. ordiniResourceDelegate.salvaOrdine(ordineAperto) make the REST call to the service using restassured
  2. To debug Lombok you can use Idea Plugin, is very good, or delombok using Maven plugin, you choice
  3. The faulty equals/hashCode is from Ordine, where we consider that an Order is equals to another if they have the same barcode. This is wrong and will be soon fixed, has a deep impact in business code
  4. We don't use Lombok builder in that piece of code because the Ordine come from the JAX-RS endpoint

@emmanuelbernard
Copy link
Member

only orphanRemoval=true leads to Hibernate checking that you are not derefencing the collection. Because we rely on it to implement the orphanRemoval behavior. That's why you only see this problem here. Other collections have this dereference problem most likely but Hibernate can recover.

I tried to use the IntelliJ IDEA plugin indeed but it did not help me on the debug side. I am probably not familiar with the tool enough.

This come also from the client, is deserialized and when it is merged for some reason two collection instances exists with the same content, one pointed by PiattoOrdinato.abbinamento and the other not point by any other owning side.

Can you provide some info in how you found the double collections? I have not been able to find them in the debugger but that's the core of the problem.

@masini
Copy link
Contributor Author

masini commented Mar 9, 2020

The original object deserialised by Jackson is:

after_jackson_deserialization

The abbinamenti collection is somewhere transformed to a PersistentBag but in a way I don’t fully understand, there must be still some enhancement magic under the hood because the setter method is never called and the collection from ArrayList is transformed to a PersistentBag.

Infact, here we can see that the unreachable abbinamenti/PersistentBag@15547 point to his owner “PiattoOrdinato” which point to another abbinamenti/PersistentBag@13569

after_hibernate_merge

@emmanuelbernard
Copy link
Member

Right we are getting to the core of the problem.
How come a JSON file leads to the use of a PersistentBag for the List implementation? Only Hibernate should do that work but Hibernate is not invoved on the JSON deserialization. Unless Jackson comes with magical Hibernate binding that are screwing us in this case?

@masini
Copy link
Contributor Author

masini commented Mar 9, 2020

Hi @emmanuelbernard, the object deserialized by Jackson has only ArrayList (picture number 1), the PersistentBag come when we enter inside the EntityManager#merge method (picture number 2), why do you think the opposite ?

@emmanuelbernard
Copy link
Member

@masini Ah I did not know it was in the merge. You said the original object was and right there was the cast to PersistentBag.

@emmanuelbernard
Copy link
Member

In the second TestMergeOrdine.testCreateAndMergeOrdine "salvaOrdine" call, I see that inside HasSaveOrUpdate.saveOrUpdateInternal (from OrdiniService), then the ordine entity is merge returning a different Ordine instance as expected but it still contains reference to the ArrayList and not the PersistentBag. As if the merge operation did not cascade to the abbinamenti instance. The other copllections of Ordini seem PersistentBag alright like menus and piattiOrdinatti

@masini @Sanne can you get a second pair of eyes maybe you will see why the cascade is not happening (e.g. wring mapping??)

@emmanuelbernard
Copy link
Member

Oh and importantly, during the merge I do see the PersistentBag creation of the abbinamenti instances, so it's as if hibernate was not setting the values of these collections.

@masini
Copy link
Contributor Author

masini commented Mar 10, 2020

Correct @emmanuelbernard, the created PersistentBag then raise the Exception.

I want to debug again, may be I can notice something, but I'm pessimistic since you haven't seen it....

@Sanne help us :)

@emmanuelbernard
Copy link
Member

I tried to reproduce with a simpler Foo ->orphanDlete=true -> Bar but this one works perfectly.

@Sanne
Copy link
Member

Sanne commented Mar 10, 2020

hi all, looks like I need to catch up on a lot of reading :) TBH I also need to finish some other PR reviews first.

But at first glance, I see being mentioned this is about a merge and with Jackson .. which raises some red flags as there are other open issues related to that; what Jackson does as "optimisations" are very tricky to spot changes in how default fields of classes are being initialized.

I'll spare you the details, but the short story is that entities being deserialized by Jackson don't have the full state that we would expect.

So @masini do you think you could extract a reproducer with & without jackson and compare?

See also #2815 ; to be clear this is how Hibernate ORM always did things so I'm not classifying it as a regression; we should fix it but it's rather complex and I won't be able to do it for this cycle. I'd recommend to not use Jackson on managed entities.

@masini
Copy link
Contributor Author

masini commented Mar 10, 2020

I did some other experiments, I hope that with this data you can understand what is going on.

During "merge" Ordine and PiattoOrdinato are loaded in the first query and piattiOrdinati collection is wrapped inside a bag, then a second query triggers the load of abbinamenti (which is LAZY) but this is not wrapped inside a PersistentBag, a vanilla ArrayList is used to contains the objects in the collection.

When this is true then during flush() in the org.hibernate.event.internal.WrapVisitor#processArrayOrNewCollection a new PersistentBag with the Abbinamento collection elements is created and added into the persistentContext (line 110), this collection is updated inside the values object array with the decomposition of the properties but is never reflected on the root object Ordine.

The proof of this behaviour is that inverting the EAGER fetching between menus and abbinamenti, the latter is wrapper inside a PersistentBag and everything works fine.

So the key is “when” is loaded, during the first query or during the subsequents lazy fetching

Can you add an EAGER ElementCollection in the first object of your reproducer or share it so that I can it ?

@emmanuelbernard emmanuelbernard changed the title org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance migrating to 1.3.0.Alpha2 Hibernate fails on complex orphanDelete=true cases and bump version upon merge calls involving entities without change Mar 10, 2020
@emmanuelbernard
Copy link
Member

emmanuelbernard commented Mar 11, 2020

I decided to track the version bump problem in a separate issue #7770

@emmanuelbernard
Copy link
Member

Back on the orphanDelete case, @masini thanks for digging.
You have seen that I've shared an invite with you of a GitHub repo with the reproducer for the version case. https://github.com/emmanuelbernard/quarkus-7462
I kept it private because that's your code base and I did not know how much you wanted to share.

But if you look at it, you will find TestBarLayoutService.testVersionWithServerSideEquivalent, which is cool for a few reasons:

  • it's much simpler as it has a minimal set of state
  • it removes the use of Lombok and thus clears the mud around multiple issues
  • it reproduces the steps of your original test but all from within the server (via some manual shallow copy "serialization", and em.clear / em.flush usages. If you can build a set of D, E, F, G entities with the same structure as Ordini with the 3 collections that interest us (and not the rest), that would be very helpful as we could move the test to Hibernate ORM proper to move forward.

I suspect in the end that we might find the same problem we found for #7770 but we can't rule things out.

@masini
Copy link
Contributor Author

masini commented Mar 11, 2020

Thank you for keeping private, I'll create some data so that we can understand better what is going on.

@masini
Copy link
Contributor Author

masini commented Mar 11, 2020

Pushed a replicator of the original Exception.

This is very rude now, but it works.

Start Quarkus in dev mode and then:

curl -X GET http://localhost:8080/ordini-bar/o1
curl -X POST http://localhost:8080/ordini-bar/o1

you will get the Exception:

Resulted in: org.jboss.resteasy.spi.UnhandledException: javax.persistence.PersistenceException: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: net.lucamasini.testcase.server.entity.PO1.a1s
If you think this can be a good replicator I'll add it to a test and a RestAssured call.

Let me know.

@emmanuelbernard
Copy link
Member

@masini yes it looks like a good reproducer. I would try and remove more if possible. Like the embedded object, I wonder if it is necessary. Likewise the GenericEntity, if the error happens without version object we can remove GenericEntity altogether to get to the core of the problem.

@masini
Copy link
Contributor Author

masini commented Mar 12, 2020

Ok, I created a new version

  • without equals/hashCode
  • wihout attributes
  • without @ManyToOne not used in tested relationship
  • without GenericEntity (and its version, date, @PrePersist)
  • without @Embeddable

I also created a new test method net.lucamasini.testcase.server.boundary.TestMergeOrdine#testCreateAndMergeO1 that make the two call and check if the correct Exception is raised.

It's pushed on github, let me know if your thoughts.

@andrzejszywala
Copy link

andrzejszywala commented Oct 24, 2020

I have similar problem.
I've created entity with two collections which have orphanremoval property.

@Entity
public class Parent {
  @Id
  private Long id;
  private String name;
  @OneToMany(orphanRemoval = true, mappedBy = "parent")
  private List<Child1> child1;
  @OneToMany(orphanRemoval = true, mappedBy = "parent")
  private List<Child2> child2;
...

I've added one record to the database:
insert into parent(id, name) values (1, 'name');
In resource I just merge my entity with new name

@GET
@Produces(MediaType.TEXT_PLAIN)
@Transactional
public String merge() {
    	Parent parent = new Parent();
    	parent.setId(1L);
    	parent.setName("new name");    	
    	em.merge(parent);
        return "hello";
}

In result I've got error:

javax.persistence.PersistenceException: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:188)
	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1366)
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:453)
	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3212)
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2380)
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447)
	at org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:355)
	at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47)
	at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37)
	at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1295)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
	at io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:97)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:311)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:160)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:100)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:32)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
	at org.acme.resteasy.ExampleResource_Subclass.merge(ExampleResource_Subclass.zig:159)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
	at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:643)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:507)
	at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:457)
	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:459)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:419)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:393)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
	at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
	at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:131)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:37)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:94)
	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at java.base/java.lang.Thread.run(Thread.java:834)
	at org.jboss.threads.JBossThread.run(JBossThread.java:479)
Caused by: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1
	at org.hibernate.engine.internal.Collections.processDereferencedCollection(Collections.java:100)
	at org.hibernate.engine.internal.Collections.processUnreachableCollection(Collections.java:51)
	at org.hibernate.event.internal.AbstractFlushingEventListener.lambda$flushCollections$1(AbstractFlushingEventListener.java:255)
	at org.hibernate.engine.internal.StatefulPersistenceContext.forEachCollectionEntry(StatefulPersistenceContext.java:1136)
	at org.hibernate.event.internal.AbstractFlushingEventListener.flushCollections(AbstractFlushingEventListener.java:252)
	at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:93)
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:102)
	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1362)
	... 57 more

Here is the reproducer code-with-quarkus.zip
Just run ExampleResourceTest

@stevefavez
Copy link

Hi, I got exactly the same kind of issues. One parent with two children lists. If only one is "loaded" before using "merge", it works fine, if both are loaded, got the "A collection with cascade....",
You can find in attachment a sample - unit test only - OrmResourceTest.
orm-starter.zip

@andrzejszywala
Copy link

I think the problem is in Hibernate when entities are enhanced in build phase. I've reproduce this problem in plain hibernate with hibernate-enhance-maven-plugin. I've created bug in Hibernate https://hibernate.atlassian.net/browse/HHH-14387

@yrodiere
Copy link
Member

yrodiere commented Nov 4, 2022

From what I can see, HHH-14387 was fixed upstream, and Quarkus upgraded to the version of ORM that fixes the problem.

I also ran this reproducer:

orm-starter.zip

And tests pass on Quarkus 2.14.0.

So, I'll close this issue as fixed. Feel free to reopen or ping me if that's not true.

@yrodiere yrodiere closed this as completed Nov 4, 2022
@andrzejszywala
Copy link

I've ran my test case on Quarkus 2.14.0.Final and there is still an exception.

As I can see HHH-14387 has been fixed in Hibernate 6.1.3 but Quarkus uses Hibernate 5.6.12.Final so the fix is not included.

I've attached updated test case:
code-with-quarkus.zip

Run mvn test

It should pass but there is an exception:
javax.persistence.PersistenceException: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1

@yrodiere
Copy link
Member

yrodiere commented Jan 3, 2023

As I can see HHH-14387 has been fixed in Hibernate 6.1.3 but Quarkus uses Hibernate 5.6.12.Final so the fix is not included.

The fix was backported to 5.6.10. See https://hibernate.atlassian.net/browse/HHH-14387.

I've attached updated test case:

Thanks, I'll have a look. It may just be a different bug.

@yrodiere
Copy link
Member

yrodiere commented Jan 3, 2023

As I can see HHH-14387 has been fixed in Hibernate 6.1.3 but Quarkus uses Hibernate 5.6.12.Final so the fix is not included.

The fix was backported to 5.6.10. See https://hibernate.atlassian.net/browse/HHH-14387.

So that was just plain wrong, the fix was only in 6.0, but Quarkus supposedly changed default settings in 2.12 or 2.13 which should have fixed the bug. Apparently it didn't, at least not in all cases.

Still investigating.

@yrodiere
Copy link
Member

yrodiere commented Jan 3, 2023

Ok, we need patches in Hibernate ORM (which we don't have in Quarkus 2) on top of changing a default setting (which we did in Quarkus 2.13) in order to fix this.

Reopening; most likely we will have to wait for Quarkus 3 (and Hibernate ORM 6) before this gets fixed. This shouldn't take ages, so I guess that's fine.

@yrodiere yrodiere reopened this Jan 3, 2023
@yrodiere
Copy link
Member

Hibernate ORM 6.2 / Quarkus 3 is apparently still affected, after upgrading the reproducer
(quarkus-7462.zip) I'm getting:

2023-04-20 14:47:48,755 WARN  [com.arj.ats.arjuna] (executor-thread-1) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffffc0a80120:9add:64413474:1, org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@4f24223f >: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1
        at org.hibernate.engine.internal.Collections.processDereferencedCollection(Collections.java:98)
        at org.hibernate.engine.internal.Collections.processUnreachableCollection(Collections.java:49)
        at org.hibernate.event.internal.AbstractFlushingEventListener.lambda$flushCollections$1(AbstractFlushingEventListener.java:265)
        at org.hibernate.engine.internal.StatefulPersistenceContext.forEachCollectionEntry(StatefulPersistenceContext.java:1114)
        at org.hibernate.event.internal.AbstractFlushingEventListener.flushCollections(AbstractFlushingEventListener.java:262)
        at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:91)
        at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:38)
        at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:127)
        at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1412)
        at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:485)
        at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2296)
        at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:1961)
        at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:439)

@yrodiere
Copy link
Member

Same problem in Quarkus 3.5: https://github.com/yrodiere/quarkus-playground/tree/i7462

[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 4.579 s <<< FAILURE! - in org.acme.resteasy.ExampleResourceTest
[ERROR] org.acme.resteasy.ExampleResourceTest.testHelloEndpoint  Time elapsed: 0.715 s  <<< FAILURE!
java.lang.AssertionError: 
1 expectation failed.
Expected status code <200> but was <500>.

	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
	at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:73)
	at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrapNoCoerce.callConstructor(ConstructorSite.java:108)
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:57)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:263)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:277)
	at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure.validate(ResponseSpecificationImpl.groovy:512)
	at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure$validate$1.call(Unknown Source)
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:139)
	at io.restassured.internal.ResponseSpecificationImpl.validateResponseIfRequired(ResponseSpecificationImpl.groovy:696)
	at io.restassured.internal.ResponseSpecificationImpl.this$2$validateResponseIfRequired(ResponseSpecificationImpl.groovy)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:43)
	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:198)
	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:62)
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:49)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:171)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:185)
	at io.restassured.internal.ResponseSpecificationImpl.statusCode(ResponseSpecificationImpl.groovy:135)
	at io.restassured.specification.ResponseSpecification$statusCode$0.callCurrent(Unknown Source)
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:49)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:171)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:185)
	at io.restassured.internal.ResponseSpecificationImpl.statusCode(ResponseSpecificationImpl.groovy:143)
	at io.restassured.internal.ValidatableResponseOptionsImpl.statusCode(ValidatableResponseOptionsImpl.java:89)
	at org.acme.resteasy.ExampleResourceTest.testHelloEndpoint(ExampleResourceTest.java:22)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.test.junit.QuarkusTestExtension.runExtensionMethod(QuarkusTestExtension.java:1014)
	at io.quarkus.test.junit.QuarkusTestExtension.interceptTestMethod(QuarkusTestExtension.java:828)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	Suppressed: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1
		at org.hibernate.engine.internal.Collections.processDereferencedCollection(Collections.java:98)
		at org.hibernate.engine.internal.Collections.processUnreachableCollection(Collections.java:49)
		at org.hibernate.event.internal.AbstractFlushingEventListener.lambda$flushCollections$1(AbstractFlushingEventListener.java:271)
		at org.hibernate.engine.internal.StatefulPersistenceContext.forEachCollectionEntry(StatefulPersistenceContext.java:1114)
		at org.hibernate.event.internal.AbstractFlushingEventListener.flushCollections(AbstractFlushingEventListener.java:268)
		at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:91)
		at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:38)
		at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:127)
		at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1412)
		at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:485)
		at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2301)
		at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:1966)
		at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:439)
		at org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:336)
		at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47)
		at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37)
		at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:52)
		at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:351)
		at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:69)
		at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:138)
		at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1271)
		at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104)
		at io.quarkus.narayana.jta.runtime.NotifyingTransactionManager.commit(NotifyingTransactionManager.java:70)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:406)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:171)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
		at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
		at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
		at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
		at org.acme.resteasy.ExampleResource_Subclass.merge(Unknown Source)
		at java.base/java.lang.reflect.Method.invoke(Method.java:568)
		at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
		at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
		at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
		at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
		at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:356)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:70)
		at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
		at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
		at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
		at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
		at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
		at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
		at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
		at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
		at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:93)
		at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582)
		at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
		at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
		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/java.lang.Thread.run(Thread.java:833)
	Suppressed: org.jboss.resteasy.spi.UnhandledException: io.quarkus.arc.ArcUndeclaredThrowableException: Error invoking subclass method
		at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:107)
		at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:344)
		at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:205)
		at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:452)
		at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
		at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
		at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
		at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
		at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
		at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
		at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
		at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:93)
		at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582)
		at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
		at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
		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/java.lang.Thread.run(Thread.java:833)
	Caused by: io.quarkus.arc.ArcUndeclaredThrowableException: Error invoking subclass method
		at org.acme.resteasy.ExampleResource_Subclass.merge(Unknown Source)
		at java.base/java.lang.reflect.Method.invoke(Method.java:568)
		at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
		at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
		at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
		at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
		at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:356)
		at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:70)
		at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
		... 15 more
	Caused by: jakarta.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
		at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1283)
		at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104)
		at io.quarkus.narayana.jta.runtime.NotifyingTransactionManager.commit(NotifyingTransactionManager.java:70)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:406)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:171)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
		at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
		at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
		at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
		at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
		... 28 more
	Caused by: [CIRCULAR REFERENCE: org.hibernate.HibernateException: A collection with cascade="all-delete-orphan" was no longer referenced by the owning entity instance: org.acme.resteasy.Parent.child1]

@yrodiere
Copy link
Member

Still present in Quarkus 3.12, reported upstream as https://hibernate.atlassian.net/browse/HHH-18389

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