One-To-Many Association occasionally not fetching actual data

[Anton_Ram]

We are using 7.4.1.Final with mapping One-To-Many association like this:

@Entity
class LegalStatementEntity: UserAssignableBusinessEntity  {
    @OneToMany(mappedBy = "target", cascade = [CascadeType.ALL], orphanRemoval = true)
    override val userAssignments: MutableSet<LegalStatementUserAssignment> = mutableSetOf()
}

@Entity
class LegalStatementUserAssignment(
    @ManyToOne(fetch = FetchType.LAZY, optional = false)
    override val target: LegalStatementEntity
)

During concurrency kafka test code:

val entity = entityManager.find(event.entityId)
val assigns = entity.userAssignments

mostly produce 2 sql requests:

2026-07-27T09:37:00.396249107Z [    kafka-ext-9] d.c.a.b.p.a.CascadeAssignService         : Found changing child key LegalStatementId(uuid=019fa2ef-4256-76cd-a1f4-fdc8a51db84f)

2026-07-27T09:37:00.397046853Z [    kafka-ext-9] o.h.SQL  : select lse1_0.id from legal_statement lse1_0 where lse1_0.id=? and lse1_0.version=? for share of lse1_0

2026-07-27T09:37:00.397243074Z [    kafka-ext-9] o.h.SQL : select ua1_0.target_id,ua1_0.id,ua1_0.when_created,ua1_0.when_modified,ua1_0.basis,ua1_0.user_id,ua1_0.version from legal_statement_user_assignment ua1_0 where ua1_0.target_id=?

2026-07-27T09:37:00.402285972Z [    kafka-ext-9] d.c.a.b.p.a.CascadeAssignService         : Found assigns:{MAIN/exectask/legalstatement=[UserEntity@7decaced]} of:LegalStatementId(uuid=019fa2ef-4256-76cd-a1f4-fdc8a51db84f)

But always 5-7% of messages makes only one request so receiving association collection is invalid:

2026-07-27T09:36:59.557779777Z  [    kafka-ext-9] d.c.a.b.p.a.CascadeAssignService         : Found changing child key for LegalStatementId(uuid=019fa2ef-4248-7542-bcf6-2d78a3a92170)

2026-07-27T09:36:59.55816336Z   [    kafka-ext-9] o.h.SQL : select lse1_0.id from lcm.legal_statement lse1_0 where lse1_0.id=? and lse1_0.version=? for share of lse1_0

2026-07-27T09:36:59.559004384Z  [    kafka-ext-9] d.c.a.b.p.a.CascadeAssignService         : Found assigns:{} of:LegalStatementId(uuid=019fa2ef-4248-7542-bcf6-2d78a3a92170) to copy

Where is second request ? How can i force to read actual data when use association field ?

[beikov]

I don’t know what your code is doing with the entities, but the query for initialization is only executed when the collection is accessed i.e. if you call a method on it. Maybe some of your code does not touch the collection?

[Anton_Ram]

Log message “Found assigns:{}” definitely shows that association was called
And definitely association was changed above in another transaction successfully(creation time in database is before than log message with accessing to field)

[beikov]

Do you have caching configured for the entity and collection? Since you’re saying it’s concurrency related, do you know for sure that you’re not misinterpreting the log messages, because they are interleaved? Maybe that thread that doesn’t load the collection fails with an exception before loading the collection?

I don’t know what to tell you, but unless you can provide more details or share a reproducer based on test case template, I can’t really help you. There are too many unknowns.

[Anton_Ram]

No caching is used. Business log “Found assigns” is unique for project and called after finding entity and accessing to field to check current collection state like this:

val entity = entityManager.find<LegalStatement>(eventId)
log.info { "Found assigns: ${entity.userAssignments}" }

This issue was created based on ‘org.hibernate.SQL’ logs and inconsistent state in db after test, not on interpretation business log’s.
Test is concurrent transactional consuming bunch of messages from kafka with create\update\filling collections actions with cascade updating collections between parent-child. Issue is spontaneous and can’t be easy debugged. Reproducing with test case template will be problematic.

I’ll really try to give more information
Here is schematic interaction with specific entity and his association from threads while concurrent processing messages:

And hibernate trace logs for kafka-ext-13 thread when there isn’t any fetching association with user assignments from db :

2026-07-31T11:49:30.276Z DEBUG 1 --- [   kafka-ext-13] d.c.a.b.p.a.CascadeAssignService         : Found changing child key new:LegalStatementId(uuid=019fb802-0cb4-72b6-90a9-845195c41ca6) old:null for ExecTaskId(uuid=019fb802-0b3e-752b-9b3c-cafb003e6093)
2026-07-31T11:49:30.277Z DEBUG 1 --- [   kafka-ext-13] o.h.SQL                                  : select * from exec_task ete1_0 where ete1_0.id=? and ete1_0.version=? for share of ete1_0
2026-07-31T11:49:30.278Z DEBUG 1 --- [   kafka-ext-13] d.c.a.b.p.a.CascadeAssignService         : Found assigns:{} of:ExecTaskId(uuid=019fb802-0b3e-752b-9b3c-cafb003e6093) to copy to LegalStatementId(uuid=019fb802-0cb4-72b6-90a9-845195c41ca6)
2026-07-31T11:49:30.278Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060012: Processing flush-time cascades
2026-07-31T11:49:30.278Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060023: Ignoring persistent instance [dev.backend.legalstatement.LegalStatementUserAssignment with id '45883']
2026-07-31T11:49:30.278Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060023: Ignoring persistent instance [dev.backend.exectask.ExecTaskUserAssignment with id '46398']
2026-07-31T11:49:30.278Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060013: Dirty checking collections
2026-07-31T11:49:30.278Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060014: Flushing entities and processing referenced collections
2026-07-31T11:49:30.279Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060063: Found dirty properties [[dev.backend.exectask.ExecTaskEntity with id '019fb802-0b3e-752b-9b3c-cafb003e6093']] ([data, whenDeactivated])
2026-07-31T11:49:30.279Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060062: Updating entity [dev.backend.exectask.ExecTaskEntity with id '019fb802-0b3e-752b-9b3c-cafb003e6093']
2026-07-31T11:49:30.279Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060015: Processing unreferenced collections
2026-07-31T11:49:30.279Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060016: Scheduling collection removes, (re)creates, and updates
2026-07-31T11:49:30.279Z DEBUG 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060071: Flushed: 0 insertions, 1 updates, 0 deletions to 23 objects
2026-07-31T11:49:30.279Z DEBUG 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060072: Flushed: 0 (re)creations, 0 updates, 0 removals to 8 collections
2026-07-31T11:49:30.279Z TRACE 1 --- [   kafka-ext-13] o.h.o.event                              : HHH90060038: Need to execute flush

selecting from exec_task with id “019fb802-0b3e-752b-9b3c-cafb003e6093” is first in this transaction

Below mostly happens correct behavior:

2026-07-31T11:49:33.653Z DEBUG 1 --- [    kafka-ext-6] d.c.a.b.p.a.CascadeAssignService         : Found changing child key new:DebtId(uuid=019fb802-1b45-73ca-8d06-8885fd1ff269) old:null for LegalStatementId(uuid=019fb801-f5a5-76af-ae07-e6d31de56189)
2026-07-31T11:49:33.653Z DEBUG 1 --- [    kafka-ext-6] o.h.SQL                                  : select * from legal_statement lse1_0 where lse1_0.id=? and lse1_0.version=? for share of lse1_0
2026-07-31T11:49:33.656Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060033: Initializing collection [dev.backend.legalstatement.LegalStatementEntity.userAssignments with owner id '019fb801-f5a5-76af-ae07-e6d31de56189']
2026-07-31T11:49:33.656Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060035: Collection not cached
2026-07-31T11:49:33.656Z DEBUG 1 --- [    kafka-ext-6] o.h.SQL                                  : select * from legal_statement_user_assignment ua1_0 where ua1_0.target_id=?
2026-07-31T11:49:33.658Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060008: Loading entity [dev.backend.user.UserEntity with id '019a77fa-2949-7563-858b-844634cd45f7']
2026-07-31T11:49:33.658Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060050: Creating new proxy for entity
2026-07-31T11:49:33.658Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060036: Collection initialized
2026-07-31T11:49:33.658Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060051: Searching caches for entity [dev.backend.user.UserEntity with id '019a77fa-2949-7563-858b-844634cd45f7']
2026-07-31T11:49:33.659Z TRACE 1 --- [    kafka-ext-6] o.h.o.event                              : HHH90060053: Entity not found in any cache, loading from datastore [dev.backend.user.UserEntity with id '019a77fa-2949-7563-858b-844634cd45f7']
2026-07-31T11:49:33.660Z DEBUG 1 --- [    kafka-ext-6] o.h.SQL                                  : select * from users ue1_0 where ue1_0.id=?
2026-07-31T11:49:33.663Z DEBUG 1 --- [    kafka-ext-6] d.c.a.b.p.a.CascadeAssignService         : Found assigns:{MAIN/exectask/legalstatement=[dev.backend.user.UserEntity@3008db30]} of:LegalStatementId(uuid=019fb801-f5a5-76af-ae07-e6d31de56189) to copy to DebtId(uuid=019fb802-1b45-73ca-8d06-8885fd1ff269)

There is expected messages from hibernate “Collection not cached” and “Collection initialized”

So turning on the trace logs didn’t help clarify the situation. In problem logs before “2026-07-31T11:49:30.276Z” thread kafka-ext-13 contains only logs for another polled messages with another exec task entites. Both threads processed packages successfully without errors
PS: we are using java 25 with enabled VT

[beikov]

Are you sharing the same Session or entities with multiple threads (even virtual threads)? Printing this log in a different thread (even virtual) would also be sharing the Session, since lazy loading accesses the it.

In this log that you posted last, the first log shows only a select from the exec_task table, but the original logs were about legal_statement. Are you sure that you’re looking for the right thing in the logs?

[Anton_Ram]

Remove and rewrite this message as further investigation shows that i was wrong about
“selecting from exec_task with id “019fb802-0b3e-752b-9b3c-cafb003e6093” is first in this transaction” was wrong. I suppose happens this concurrent situation:

1. Both threads start working
2. Thread1 read owner entity
3. Thread2 read owner with update lock
4. Thread2 change owner association
5. Thread2 commit transaction successfully
6. Thread1 start process owner entity and execute share lock to read association

After this in logs only sql with “select owner for share”. Am I right in assuming that at this point Hibernate decides not to reread the collection from the database?

Updated: to answer about different tables in logs. Every entity (exec_task or legal_statement or another) mapped same way and have userAssignments association. From test to test issue is happening on different entities not on same

[beikov]

The scenario is still very confusing to me and you didn’t answer if EntityManager/Session as well as all the entity objects are isolated to a single thread. From what you wrote in your last message, it could be that if your JDBC connection is configured to use REPEATABLE_READ or SERIALIZABLE transaction isolation level, that you might not see the data that was committed by the transaction of Thread 2, since the transaction of Thread 1 started before Thread 2 committed.

@Anton_Ram

After this in logs only sql with “select owner for share”. Am I right in assuming that at this point Hibernate decides not to reread the collection from the database?

I don’t know what this means, but the fact that you’re implying “re-read” tells me that you’re either sharing entity instances across threads or that you loaded the collection in Thread 1 before Thread 2 committed. Of course, Hibernate ORM will not reload a collection if it is already materialized in memory. How could it know that the database state changed? You have to ask Hibernate ORM to refresh the data by calling e.g. Session#refresh on that owner instance and mark the userAssignments collection as Cascade.REFRESH if you know that a different thread altered data meanwhile. The very common alternative is to use either optimistic or pessimistic locking to ensure you work with the latest database state. In this particular case, you would have to use a read lock i.e. PESSIMISTIC_READ when reading the owner entity in Thread 1, or if Thread 1 also updates the owner entity, add a @Version field to make use of optimistic locking. You can read in the documentation about the various ways to protect against such data races: Hibernate ORM User Guide

[Anton_Ram]

Yes it is possible that multiple thread will read same entity from db and we already got locking for them if one of the thread decide to change association collection. Share lock before get data from ownerEntity.userAssignments and update lock if we adding\removing from collection.
Each thread processing messages one by one, so within one thread messages in the log go sequentially

“How could it know that the database state changed?”
By trace and debug hibernate logs

[    kafka-ext-8] o.h.SQL                                  : select * from exec_task ete1_0 where ete1_0.id=? and ete1_0.version=? for no key update of ete1_0
[    kafka-ext-8] o.h.o.event                              : HHH90060058: Persisting [dev.backend.exectask.ExecTaskUserAssignment with null id]
[    kafka-ext-8] o.h.SQL                                  : insert into exec_task_user_assignment (when_created,when_modified,basis,target_id,user_id,version) values (?,?,?,?,?,?)

Is this reason to say that changes into exec_task_user_assignment was flushed and after kafka-ext-8 will finish processing polled messages successfully and commit transaction, this changes will be available to another threads ?

“I don’t know what this means”

Yes we can reread entity several times during processing and it will produce one request to db and others will hit session cache as i suppose . But after calling:

entityManager.lock(entity, LockModeType.PESSIMISTIC_READ)

hibernate always forcedly call:

[   kafka-ext-13] o.h.SQL                                  : select * from exec_task ete1_0 where ete1_0.id=? and ete1_0.version=? for share of ete1_0

to lock row. It turns out entity was reread, but association not ? And this happens very rarely, mostly calling lock on entity leads to a request not only to the owning entity but also to its association (as showed in example logs above)
Of course, we can put a lock on the owning entity at the very beginning, but for concurrent processing of a large number of messages, this will greatly reduce the throughput.

[beikov]

It will not necessarily reduce the throughput, because there can be multiple transactions with a PESSIMISTIC_READ lock, but only one transaction with a PESSIMISTIC_WRITE lock. Obviously, if you plan on changing an entity, you should acquire the PESSIMISTIC_WRITE lock, so that no other reader can read stale state. If your transactions are long, which they shouldn’t be, then you can acquire the read lock later along with a refresh to reduce the lock holding time.

@Anton_Ram

It turns out entity was reread, but association not ?

The entity is not re-read if it is already part of the persistence context, also see the documentation of the EntityManager#find operation. If you want the entity data to be up-to-date, you will have to invoke entityManager.refresh(entity, LockModeType.PESSIMISTIC_READ, Collections.emptyMap()) and annotate the userAssignments with @OneToMany(cascade = REFRESH) like I already pointed out.

It seems like you are not really understanding how the entity lifecycle works, so I would suggest you re-read the documentation about the basics of JPA and Hibernate ORM.

[Anton_Ram]

Thanks for advices !