4javier
4javier

Reputation: 639

Hibernate not flushing entity update on transaction commit

This is the transactional service defining the method I use to create a UserCommit and explicitly persisting it (this part works), and in the meantime updating the lastCommit field of the already existent parent entity User. This update doesn't get flushed.

@Transactional
@Service
public class UserCommitService {

    @Autowired
    private UserService userService;
    @Autowired
    private UserCommitRepository ucRepo;

    public UserCommit createFrom(User user, Integer prodId, String ucType, String stage) {

        UserCommit uc = new UserCommit();
        uc.setUser(userService.findUserById(user.getId()));
        uc.getUser().addUserCommit(uc);
        uc.setTime(LocalDateTime.now());

        uc.getUser().setLastCommit(uc.getTime());

        ucRepo.save(uc);

        return uc;
    }

}

Here you can read the tracing log:

  1. User gets correctly selected from DB
  2. An inner transaction gets created for ucRepo.save (It's a CRUDRepo method, then I think it's normal) and userCommit gets correctly inserted into DB

EDIT

Why CrudRepository.save creates a new transaction instead of joining the existing one?

  1. Outer transaction gets resumed, but even if the entity show the updated field, it seems this gets ignored by dirty checking, because no insert is logged on commit.
2020-05-31 12:52:36.405 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@296e6024] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1826475] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:52:36.406 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(461939992<open>)] for JPA transaction
2020-05-31 12:52:36.406 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [petmenu.services.users.UserCommitService.createFrom]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-05-31 12:52:36.407 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@5ac66b8d]
2020-05-31 12:52:36.407 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@4905e3e7] for key [HikariDataSource (HikariPool-1)] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:52:36.407 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2020-05-31 12:52:36.407 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Getting transaction for [petmenu.services.users.UserCommitService.createFrom]
2020-05-31 12:53:24.212 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@296e6024] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1826475] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:53:24.217 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(461939992<open>)] for JPA transaction
2020-05-31 12:53:24.221 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.jdbc.datasource.ConnectionHolder@4905e3e7] for key [HikariDataSource (HikariPool-1)] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:53:24.228 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction
2020-05-31 12:53:24.232 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Getting transaction for [petmenu.services.users.UserService.findUserById]
2020-05-31 12:53:24.256 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findUserById]: This method is not transactional.
2020-05-31 12:53:24.265 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.EntityManagerFactoryUtils    : Opening JPA EntityManager
2020-05-31 12:53:24.271 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:53:24.279 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:53:24.288 DEBUG 7194 --- [.10-8080-exec-6] org.hibernate.SQL                        : select user0_.id as id1_0_, user0_.kc_id as kc_id2_0_, user0_.last_commit as last_com3_0_, user0_.name as name4_0_ from user user0_ where user0_.id=?
2020-05-31 12:53:24.298 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [6]
2020-05-31 12:53:24.309 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([id1_0_] : [INTEGER]) - [6]
2020-05-31 12:53:24.317 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([kc_id2_0_] : [VARCHAR]) - [80a3b4b1-00d1-4062-a7e5-1927b938c203]
2020-05-31 12:53:24.325 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([last_com3_0_] : [TIMESTAMP]) - [null]
2020-05-31 12:53:24.332 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name4_0_] : [VARCHAR]) - [user1]
2020-05-31 12:53:24.342 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Completing transaction for [petmenu.services.users.UserService.findUserById]
2020-05-31 12:55:07.918 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$DefaultCrudMethodMetadata@326a9afb] for key [public abstract java.lang.Object org.springframework.data.repository.CrudRepository.save(java.lang.Object)] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:07.957 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:07.961 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1373582834<open>)] for JPA transaction
2020-05-31 12:55:07.966 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:07.970 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2020-05-31 12:55:07.975 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-05-31 12:55:07.980 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(756005269<open>)] for JPA transaction
2020-05-31 12:55:07.987 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@6860e795]
2020-05-31 12:55:07.992 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@6374741f] for key [HikariDataSource (HikariPool-2)] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:07.998 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@4b2cad26] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:08.002 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2020-05-31 12:55:08.006 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2020-05-31 12:55:08.226 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@4b2cad26] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] bound to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:08.392 DEBUG 7194 --- [.10-8080-exec-6] org.hibernate.SQL                        : select nextval(hibernate_sequence)
2020-05-31 12:55:08.783 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2020-05-31 12:55:08.787 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2020-05-31 12:55:08.791 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2020-05-31 12:55:08.796 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2020-05-31 12:55:08.800 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(756005269<open>)]
2020-05-31 12:55:08.824 DEBUG 7194 --- [.10-8080-exec-6] org.hibernate.SQL                        : insert into user_commit (uctype, prod_id, stage, time, user, id) values (?, ?, ?, ?, ?, ?)
2020-05-31 12:55:08.832 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
2020-05-31 12:55:08.838 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [INTEGER] - [3]
2020-05-31 12:55:08.845 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [3] as [INTEGER] - [0]
2020-05-31 12:55:08.884 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [4] as [TIMESTAMP] - [2020-05-31T12:54:58.518530]
2020-05-31 12:55:08.922 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [5] as [INTEGER] - [6]
2020-05-31 12:55:08.929 TRACE 7194 --- [.10-8080-exec-6] o.h.type.descriptor.sql.BasicBinder      : binding parameter [6] as [INTEGER] - [3003]
2020-05-31 12:55:09.043 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2020-05-31 12:55:09.048 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2020-05-31 12:55:09.052 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2020-05-31 12:55:09.056 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@4b2cad26] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:09.062 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@6374741f] for key [HikariDataSource (HikariPool-2)] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:09.066 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(756005269<open>)] after transaction
2020-05-31 12:55:09.070 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Resuming suspended transaction after completion of inner transaction
2020-05-31 12:55:09.075 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2020-05-31 12:55:09.080 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] to thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:55:09.085 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$DefaultCrudMethodMetadata@326a9afb] for key [public abstract java.lang.Object org.springframework.data.repository.CrudRepository.save(java.lang.Object)] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:58:18.989 TRACE 7194 --- [.10-8080-exec-6] o.s.t.i.TransactionInterceptor           : Completing transaction for [petmenu.services.users.UserCommitService.createFrom]
2020-05-31 12:58:18.997 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2020-05-31 12:58:19.001 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2020-05-31 12:58:19.006 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@75c27c80] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@6c8672b9] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:58:19.071  INFO 7194 --- [.10-8080-exec-6] o.h.c.i.AbstractPersistentCollection     : HHH000496: Detaching an uninitialized collection with queued operations from a session: [petmenu.entities.users.User.userCommitList#6]
2020-05-31 12:58:19.075 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2020-05-31 12:58:19.081 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(461939992<open>)]
2020-05-31 12:58:19.095 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2020-05-31 12:58:19.099 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2020-05-31 12:58:19.104 TRACE 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2020-05-31 12:58:19.109 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@4905e3e7] for key [HikariDataSource (HikariPool-1)] from thread [http-nio-192.168.1.10-8080-exec-6]
2020-05-31 12:58:19.113 DEBUG 7194 --- [.10-8080-exec-6] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2020-05-31 12:59:07.063 TRACE 7194 --- [.10-8080-exec-6] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@296e6024] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1826475] from thread [http-nio-192.168.1.10-8080-exec-6]

EDIT2

I tried to remove the CrudRepository.save call, because it behaves strangely, creating a new transaction on its own, and seems responsible for previous one closing. The log becomes a little more logic, but still User.lastCommit new value doesn't get flushed.

2020-06-01 11:39:10.518 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@5f0cca8f] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@27bbe773] bound to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:10.518 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(2096513672<open>)] for JPA transaction
2020-06-01 11:39:10.518 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [petmenu.services.users.UserCommitService.createFrom]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-06-01 11:39:10.518 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@62cbdd03]
2020-06-01 11:39:10.519 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@4b988820] for key [HikariDataSource (HikariPool-1)] to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:10.519 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2020-06-01 11:39:10.519 TRACE 26420 --- [.10-8080-exec-2] o.s.t.i.TransactionInterceptor           : Getting transaction for [petmenu.services.users.UserCommitService.createFrom]
2020-06-01 11:39:16.678 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@5f0cca8f] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@27bbe773] bound to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:16.683 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(2096513672<open>)] for JPA transaction
2020-06-01 11:39:16.688 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.jdbc.datasource.ConnectionHolder@4b988820] for key [HikariDataSource (HikariPool-1)] bound to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:16.693 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction
2020-06-01 11:39:16.697 TRACE 26420 --- [.10-8080-exec-2] o.s.t.i.TransactionInterceptor           : Getting transaction for [petmenu.services.users.UserService.findUserById]
2020-06-01 11:39:16.720 TRACE 26420 --- [.10-8080-exec-2] o.s.t.i.TransactionInterceptor           : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findUserById]: This method is not transactional.
2020-06-01 11:39:16.727 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.EntityManagerFactoryUtils    : Opening JPA EntityManager
2020-06-01 11:39:16.733 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@ca14c2f] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@161c9468] to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:16.738 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@ca14c2f] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@161c9468] bound to thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:16.747 DEBUG 26420 --- [.10-8080-exec-2] org.hibernate.SQL                        : select user0_.id as id1_0_, user0_.kc_id as kc_id2_0_, user0_.last_commit as last_com3_0_, user0_.name as name4_0_ from user user0_ where user0_.id=?
2020-06-01 11:39:16.754 TRACE 26420 --- [.10-8080-exec-2] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [6]
2020-06-01 11:39:16.763 TRACE 26420 --- [.10-8080-exec-2] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([id1_0_] : [INTEGER]) - [6]
2020-06-01 11:39:16.772 TRACE 26420 --- [.10-8080-exec-2] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([kc_id2_0_] : [VARCHAR]) - [80a3b4b1-00d1-4062-a7e5-1927b938c203]
2020-06-01 11:39:16.779 TRACE 26420 --- [.10-8080-exec-2] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([last_com3_0_] : [TIMESTAMP]) - [null]
2020-06-01 11:39:16.787 TRACE 26420 --- [.10-8080-exec-2] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name4_0_] : [VARCHAR]) - [user1]
2020-06-01 11:39:16.795 TRACE 26420 --- [.10-8080-exec-2] o.s.t.i.TransactionInterceptor           : Completing transaction for [petmenu.services.users.UserService.findUserById]
2020-06-01 11:39:48.779 TRACE 26420 --- [.10-8080-exec-2] o.s.t.i.TransactionInterceptor           : Completing transaction for [petmenu.services.users.UserCommitService.createFrom]
2020-06-01 11:39:48.780 TRACE 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2020-06-01 11:39:48.780 TRACE 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2020-06-01 11:39:48.780 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@ca14c2f] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@161c9468] from thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:48.782  INFO 26420 --- [.10-8080-exec-2] o.h.c.i.AbstractPersistentCollection     : HHH000496: Detaching an uninitialized collection with queued operations from a session: [petmenu.entities.users.User.userCommitList#6]
2020-06-01 11:39:48.782 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2020-06-01 11:39:48.782 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(2096513672<open>)]
2020-06-01 11:39:48.787 TRACE 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2020-06-01 11:39:48.787 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2020-06-01 11:39:48.787 TRACE 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2020-06-01 11:39:48.787 TRACE 26420 --- [.10-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@4b988820] for key [HikariDataSource (HikariPool-1)] from thread [http-nio-192.168.1.10-8080-exec-2]
2020-06-01 11:39:48.787 DEBUG 26420 --- [.10-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction

Upvotes: 1

Views: 2943

Answers (1)

4javier
4javier

Reputation: 639

I spent just 4 days to realize the what the problem was. Awesome...(To be honest, I took advantage of all the stuff I had to read about JPA and Hibernate to get rid completely of OSIV).

When I defined my two datasources (Products and Users) configs, I annotated all the classes inside ProductsDataSourceConfiguration as @Primary, making them the default values when called without explicitly setting a name.
The problem was with PlatformTransactionManager in it, that was called as transaction manager for both my datasources, while actually being crafted just for Products one.
To solve the issue I had to specify the secondary transaction manager name on @Transactional annotation used on methods referring to secondary (Users) datasource:

@Transactional("usersTransactionManager")
@Service
public class UserCommitService {
...

Upvotes: 1

Related Questions