Behavior of Spring Framework managed EntityManager

Notice

I wrote this article and was originally published on Qiita on 21 September 2019.

---

Code work on is from my notice board example application (Spring Data JPA version).

Case 1: Transaction scope EntityManager, disable 'spring.jpa.open-in-view'

Modfiy src/main/resources/application.properties file to

debug=true
# treat as 'create-drop' if not set
spring.jpa.hibernate.ddl-auto=none
spring.thymeleaf.cache=false
spring.jpa.open-in-view=false
logging.level.org.springframework.transaction=trace
logging.level.org.springframework.orm=trace
logging.level.org.hibernate.internal=trace
logging.level.org.hibernate.resource=trace

Add info.saladlam.example.spring.noticeboard.controller.JpaTestController class

package info.saladlam.example.spring.noticeboard.controller;

import javax.persistence.EntityManager;
import javax.persistence.PersistenceContext;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.orm.jpa.EntityManagerProxy;
import org.springframework.stereotype.Controller;
import org.springframework.transaction.PlatformTransactionManager;
import org.springframework.transaction.support.TransactionTemplate;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.ResponseBody;

import info.saladlam.example.spring.noticeboard.entity.Message;

@Controller
@RequestMapping("/jpatest")
public class JpaTestController {

    private static final Logger log = LoggerFactory.getLogger(JpaTestController.class);

    @PersistenceContext
    //@PersistenceContext(type = PersistenceContextType.EXTENDED)
    private EntityManager entityManager;

    private final TransactionTemplate transactionTemplate;

    public JpaTestController(PlatformTransactionManager manager) {
        this.transactionTemplate = new TransactionTemplate(manager);
    }

    @GetMapping(value = "/", produces = "text/plain")
    @ResponseBody
    public String index() {
        log.info("Before first transaction");
        Message message = this.transactionTemplate.execute((status) -> {
            log.info("Actual EntityManager instance: {}",
                    ((EntityManagerProxy) this.entityManager).getTargetEntityManager().toString());

            Message m = this.entityManager.find(Message.class, 1l);
            m.setDescription("First modify.");
            return m;
        });
        log.info("After first transaction");

        message.setDescription("Second modify.");

        log.info("Before second transaction");
        this.transactionTemplate.execute((status) -> {
            log.info("Actual EntityManager instance: {}",
                    ((EntityManagerProxy) this.entityManager).getTargetEntityManager().toString());

            log.info("'message' managed by Entity Manager?: {}", this.entityManager.contains(message));

            Message m = this.entityManager.find(Message.class, 2l);
            return null;
        });
        log.info("After second transaction");

        return "OK";
    }

}

Start the application. Screenshot of http://localhost:8080/ before access http://localhost:8080/jpatest/

Log when access http://localhost:8080/jpatest/

2019-09-21 16:41:37.080 DEBUG 16436 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : GET "/jpatest/", parameters={}
2019-09-21 16:41:37.088 DEBUG 16436 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String info.saladlam.example.spring.noticeboard.controller.JpaTestController.index()
2019-09-21 16:41:37.088  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : Before first transaction
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Opened Session [10088174-d44e-44e2-8d6e-3c2c62381c82] at timestamp: 1569055297089
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1543431796PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7b77a319]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@2fa8feea] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@783cbad2] to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@3c9602d] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@3c9602d] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] bound to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.089  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(1543431796PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@3c9602d] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] bound to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep4: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs22: org.h2.result.LocalResultImpl@1191743e columns: 7 rows: 1 pos: -1]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs22: org.h2.result.LocalResultImpl@1191743e columns: 7 rows: 1 pos: 1]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs22: org.h2.result.LocalResultImpl@1191743e columns: 7 rows: 1 pos: 1]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep4: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep4: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 16:41:37.089 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1543431796PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 16:41:37.089 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep5: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep5: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep5: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@3c9602d] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] from thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@2fa8feea] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@783cbad2] from thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1543431796PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] after transaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Closing session [10088174-d44e-44e2-8d6e-3c2c62381c82]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : After first transaction
2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : Before second transaction
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Opened Session [df0add89-847f-41e8-9b79-8f3d3d7ff40b] at timestamp: 1569055297105
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(701122508PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@17be2ac4]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@1eed9806] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@783cbad2] to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@65e24830] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@65e24830] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] bound to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(701122508PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@65e24830] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] bound to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : 'message' managed by Entity Manager?: false
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@65e24830] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] bound to thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep6: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs23: org.h2.result.LocalResultImpl@7613e46f columns: 7 rows: 1 pos: -1]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs23: org.h2.result.LocalResultImpl@7613e46f columns: 7 rows: 1 pos: 1]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs23: org.h2.result.LocalResultImpl@7613e46f columns: 7 rows: 1 pos: 1]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep6: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep6: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(701122508PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#2]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@65e24830] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@43152b47] from thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@1eed9806] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@783cbad2] from thread [http-nio-8080-exec-3]
2019-09-21 16:41:37.105 DEBUG 16436 --- [nio-8080-exec-3] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(701122508PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#2]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] after transaction
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] org.hibernate.internal.SessionImpl       : Closing session [df0add89-847f-41e8-9b79-8f3d3d7ff40b]
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 16:41:37.105 TRACE 16436 --- [nio-8080-exec-3] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : After second transaction
2019-09-21 16:41:37.121 DEBUG 16436 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain;q=0.8', given [text/html, application/xhtml+xml, application/xml;q=0.9, */*;q=0.8] and supported [text/plain]
2019-09-21 16:41:37.121 DEBUG 16436 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Writing ["OK"]
2019-09-21 16:41:37.121 DEBUG 16436 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Screenshot of http://localhost:8080/ after access http://localhost:8080/jpatest/

Analysis

1. EntityManager is created when transaction start and is destroy when commit transaction. Two new EntityManager is created in two transaction
2. Only changes on 1st transaction persistent. In 2nd transaction

2019-09-21 16:41:37.105  INFO 16436 --- [nio-8080-exec-3] i.s.e.s.n.controller.JpaTestController   : 'message' managed by Entity Manager?: false

this shows entity message created in 1st transaction is in detached status, it means change on this entity instance will not update to database.

Case 2: Transaction scope EntityManager, enable 'spring.jpa.open-in-view'

Stop the application, modify on file src/main/resources/application.properties following entry

spring.jpa.open-in-view=true

Start the application, log when access http://localhost:8080/jpatest/

2019-09-21 17:08:52.156  INFO 17116 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-09-21 17:08:52.156  INFO 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-09-21 17:08:52.156 DEBUG 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2019-09-21 17:08:52.156 DEBUG 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected SessionLocaleResolver
2019-09-21 17:08:52.168 DEBUG 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2019-09-21 17:08:52.168  INFO 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 12 ms
2019-09-21 17:08:52.200 DEBUG 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/jpatest/", parameters={}
2019-09-21 17:08:52.200 DEBUG 17116 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String info.saladlam.example.spring.noticeboard.controller.JpaTestController.index()
2019-09-21 17:08:52.200 DEBUG 17116 --- [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2019-09-21 17:08:52.200 TRACE 17116 --- [nio-8080-exec-1] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 17:08:52.200 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Opened Session [dc1c9faf-79ad-49f9-a31e-c516c5da637f] at timestamp: 1569056932200
2019-09-21 17:08:52.200 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.215  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Before first transaction
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.215 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(570834671PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:08:52.215 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:08:52.215 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@af7e4af]
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@32d58096] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@6dc5d67d] to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.215  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(570834671PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:08:52.215 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.231 DEBUG 17116 --- [nio-8080-exec-1] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:08:52.231 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:08:52.231 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs21: org.h2.result.LocalResultImpl@a71ca63 columns: 7 rows: 1 pos: -1]
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs21: org.h2.result.LocalResultImpl@a71ca63 columns: 7 rows: 1 pos: 1]
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs21: org.h2.result.LocalResultImpl@a71ca63 columns: 7 rows: 1 pos: 1]
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:08:52.256 DEBUG 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:08:52.256 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:08:52.256 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(570834671PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:08:52.256 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:08:52.272 DEBUG 17116 --- [nio-8080-exec-1] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:08:52.272 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@32d58096] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@6dc5d67d] from thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2019-09-21 17:08:52.287  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : After first transaction
2019-09-21 17:08:52.287  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Before second transaction
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(570834671PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@45a54a4]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@1319ebbe] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@6dc5d67d] to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(570834671PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : 'message' managed by Entity Manager?: true
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] bound to thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs22: org.h2.result.LocalResultImpl@2dec801d columns: 7 rows: 1 pos: -1]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs22: org.h2.result.LocalResultImpl@2dec801d columns: 7 rows: 1 pos: 1]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs22: org.h2.result.LocalResultImpl@2dec801d columns: 7 rows: 1 pos: 1]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(570834671PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1], EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#2]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:08:52.287 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@1319ebbe] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@6dc5d67d] from thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.287 DEBUG 17116 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2019-09-21 17:08:52.287  INFO 17116 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : After second transaction
2019-09-21 17:08:52.303 DEBUG 17116 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain;q=0.8', given [text/html, application/xhtml+xml, application/xml;q=0.9, */*;q=0.8] and supported [text/plain]
2019-09-21 17:08:52.303 DEBUG 17116 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["OK"]
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@31740c01] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@61fc9e4b] from thread [http-nio-8080-exec-1]
2019-09-21 17:08:52.319 DEBUG 17116 --- [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Closing session [dc1c9faf-79ad-49f9-a31e-c516c5da637f]
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:08:52.319 TRACE 17116 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 17:08:52.319 DEBUG 17116 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Screenshot of http://localhost:8080/ after access http://localhost:8080/jpatest/

Analysis

1. EntityManager is created in org.springframework.orm.jpa.support.OpenEntityManagerInViewInterceptor before request pass to controller and is destroyed in same class after template engine finished drawing view.
2. No new EntityManager is created during controller processing. Although 2nd time modification on Entity message is in before 2nd transaction. since it is managed by EntityManager, so this change persistent on 2nd transaction.

Case 3: Extended scope EntityManager, disable 'spring.jpa.open-in-view'

Stop the application, modify on file src/main/resources/application.properties following entry

spring.jpa.open-in-view=false

Modify info.saladlam.example.spring.noticeboard.controller.JpaTestController class to

package info.saladlam.example.spring.noticeboard.controller;

import javax.persistence.EntityManager;
import javax.persistence.PersistenceContext;
import javax.persistence.PersistenceContextType;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.orm.jpa.EntityManagerProxy;
import org.springframework.stereotype.Controller;
import org.springframework.transaction.PlatformTransactionManager;
import org.springframework.transaction.support.TransactionTemplate;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.ResponseBody;

import info.saladlam.example.spring.noticeboard.entity.Message;

@Controller
@RequestMapping("/jpatest")
public class JpaTestController {

    private static final Logger log = LoggerFactory.getLogger(JpaTestController.class);

    //@PersistenceContext
    @PersistenceContext(type = PersistenceContextType.EXTENDED)
    private EntityManager entityManager;

    private final TransactionTemplate transactionTemplate;

    public JpaTestController(PlatformTransactionManager manager) {
        this.transactionTemplate = new TransactionTemplate(manager);
    }

    @GetMapping(value = "/", produces = "text/plain")
    @ResponseBody
    public String index() {
        log.info("Before first transaction");
        Message message = this.transactionTemplate.execute((status) -> {
            log.info("Actual EntityManager instance: {}",
                    ((EntityManagerProxy) this.entityManager).getTargetEntityManager().toString());

            Message m = this.entityManager.find(Message.class, 1l);
            m.setDescription("First modify.");
            return m;
        });
        log.info("After first transaction");

        message.setDescription("Second modify.");

        log.info("Before second transaction");
        this.transactionTemplate.execute((status) -> {
            log.info("Actual EntityManager instance: {}",
                    ((EntityManagerProxy) this.entityManager).getTargetEntityManager().toString());

            log.info("'message' managed by Entity Manager?: {}", this.entityManager.contains(message));

            Message m = this.entityManager.find(Message.class, 2l);
            return null;
        });
        log.info("After second transaction");

        return "OK";
    }

}

Start the application, log when access http://localhost:8080/jpatest/

2019-09-21 17:30:48.278  INFO 13928 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-09-21 17:30:48.279  INFO 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-09-21 17:30:48.279 DEBUG 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2019-09-21 17:30:48.279 DEBUG 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected SessionLocaleResolver
2019-09-21 17:30:48.287 DEBUG 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2019-09-21 17:30:48.288  INFO 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 9 ms
2019-09-21 17:30:48.314 DEBUG 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/jpatest/", parameters={}
2019-09-21 17:30:48.322 DEBUG 13928 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String info.saladlam.example.spring.noticeboard.controller.JpaTestController.index()
2019-09-21 17:30:48.329  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Before first transaction
2019-09-21 17:30:48.330 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:30:48.330 TRACE 13928 --- [nio-8080-exec-1] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 17:30:48.331 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Opened Session [d0f4f0ed-5bd2-4dfb-bde3-adf84784ecdd] at timestamp: 1569058248330
2019-09-21 17:30:48.331 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(674916300PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:30:48.339 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.339 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.339 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:30:48.341 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@1d150121]
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@490b49f0] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@ae72858] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@27cc8f3e] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1a6063f3] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:30:48.342  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(317038319PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.342 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:30:48.342 DEBUG 13928 --- [nio-8080-exec-1] r$ExtendedEntityManagerInvocationHandler : Starting resource-local transaction on application-managed EntityManager [SessionImpl(317038319PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:30:48.347 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@2fa531ea] for key [SessionImpl(317038319PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.348 DEBUG 13928 --- [nio-8080-exec-1] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:30:48.360 DEBUG 13928 --- [nio-8080-exec-1] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:30:48.360 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:30:48.364 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs21: org.h2.result.LocalResultImpl@44df9ff7 columns: 7 rows: 1 pos: -1]
2019-09-21 17:30:48.385 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs21: org.h2.result.LocalResultImpl@44df9ff7 columns: 7 rows: 1 pos: 1]
2019-09-21 17:30:48.385 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs21: org.h2.result.LocalResultImpl@44df9ff7 columns: 7 rows: 1 pos: 1]
2019-09-21 17:30:48.386 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:30:48.386 DEBUG 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:30:48.386 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:30:48.389 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:30:48.389 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:30:48.391 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@2fa531ea] for key [SessionImpl(317038319PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.392 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:30:48.392 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(674916300PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:30:48.392 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:30:48.392 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:30:48.392 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:30:48.393 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:30:48.393 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:30:48.394 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:30:48.395 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:30:48.395 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:30:48.395 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:30:48.415 DEBUG 13928 --- [nio-8080-exec-1] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:30:48.416 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:30:48.422 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:30:48.422 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:30:48.426 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:30:48.427 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@27cc8f3e] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1a6063f3] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@490b49f0] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@ae72858] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.428 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(674916300PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] after transaction
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Closing session [d0f4f0ed-5bd2-4dfb-bde3-adf84784ecdd]
2019-09-21 17:30:48.428 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.429 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 17:30:48.429 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.429 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 17:30:48.429  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : After first transaction
2019-09-21 17:30:48.429  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Before second transaction
2019-09-21 17:30:48.429 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:30:48.429 TRACE 13928 --- [nio-8080-exec-1] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Opened Session [efbe5e64-815a-4377-8f4a-6a993e0e5b0e] at timestamp: 1569058248429
2019-09-21 17:30:48.430 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(261726288PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:30:48.430 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@569b1bc3]
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@4dead27d] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@ae72858] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@f3370b0] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1a6063f3] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.430 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:30:48.431  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(317038319PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:30:48.431 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.431 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:30:48.431 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:30:48.431 DEBUG 13928 --- [nio-8080-exec-1] r$ExtendedEntityManagerInvocationHandler : Starting resource-local transaction on application-managed EntityManager [SessionImpl(317038319PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:30:48.431 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@c8f575a] for key [SessionImpl(317038319PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] to thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.431 DEBUG 13928 --- [nio-8080-exec-1] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:30:48.431  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : 'message' managed by Entity Manager?: true
2019-09-21 17:30:48.431 DEBUG 13928 --- [nio-8080-exec-1] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:30:48.431 DEBUG 13928 --- [nio-8080-exec-1] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs22: org.h2.result.LocalResultImpl@19265314 columns: 7 rows: 1 pos: -1]
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs22: org.h2.result.LocalResultImpl@19265314 columns: 7 rows: 1 pos: 1]
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs22: org.h2.result.LocalResultImpl@19265314 columns: 7 rows: 1 pos: 1]
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:30:48.432 DEBUG 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:30:48.432 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@c8f575a] for key [SessionImpl(317038319PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1], EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#2]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.433 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:30:48.433 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(261726288PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:30:48.433 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:30:48.434 DEBUG 13928 --- [nio-8080-exec-1] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:30:48.434 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:30:48.435 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:30:48.437 TRACE 13928 --- [nio-8080-exec-1] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@f3370b0] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1a6063f3] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.438 TRACE 13928 --- [nio-8080-exec-1] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@4dead27d] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@ae72858] from thread [http-nio-8080-exec-1]
2019-09-21 17:30:48.439 DEBUG 13928 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(261726288PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] after transaction
2019-09-21 17:30:48.439 TRACE 13928 --- [nio-8080-exec-1] org.hibernate.internal.SessionImpl       : Closing session [efbe5e64-815a-4377-8f4a-6a993e0e5b0e]
2019-09-21 17:30:48.439 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.439 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 17:30:48.440 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:30:48.440 TRACE 13928 --- [nio-8080-exec-1] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 17:30:48.440  INFO 13928 --- [nio-8080-exec-1] i.s.e.s.n.controller.JpaTestController   : After second transaction
2019-09-21 17:30:48.450 DEBUG 13928 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain;q=0.8', given [text/html, application/xhtml+xml, application/xml;q=0.9, */*;q=0.8] and supported [text/plain]
2019-09-21 17:30:48.648 DEBUG 13928 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["OK"]
2019-09-21 17:30:48.661 DEBUG 13928 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Screenshot of http://localhost:8080/ after access http://localhost:8080/jpatest/

Analysis

1. JPA operation on controller is through EntityManager SessionImpl(317038319. And within two transaction block, a new EntityManager is created, EntityManager SessionImpl(317038319 join to this transaction.
2. 2nd time modification on Entity message is successfully persistent to database.

Case 4: Extended scope EntityManager, enable 'spring.jpa.open-in-view'

Stop the application, modify on file src/main/resources/application.properties following entry

spring.jpa.open-in-view=true

Start the application, log when access http://localhost:8080/jpatest/

2019-09-21 17:55:20.064  INFO 14968 --- [nio-8080-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-09-21 17:55:20.064  INFO 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-09-21 17:55:20.076 DEBUG 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2019-09-21 17:55:20.076 DEBUG 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Detected SessionLocaleResolver
2019-09-21 17:55:20.078 DEBUG 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2019-09-21 17:55:20.078  INFO 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed initialization in 14 ms
2019-09-21 17:55:20.109 DEBUG 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : GET "/jpatest/", parameters={}
2019-09-21 17:55:20.109 DEBUG 14968 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String info.saladlam.example.spring.noticeboard.controller.JpaTestController.index()
2019-09-21 17:55:20.109 DEBUG 14968 --- [nio-8080-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2019-09-21 17:55:20.109 TRACE 14968 --- [nio-8080-exec-2] .i.SessionFactoryImpl$SessionBuilderImpl : Opening Hibernate Session.  tenant=null, owner=null
2019-09-21 17:55:20.109 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Opened Session [c5f1e98b-e0be-49f6-9fb9-bdb67f43c16b] at timestamp: 1569059720109
2019-09-21 17:55:20.109 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@4e541948] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1c9b9b00] to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.125  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : Before first transaction
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@4e541948] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1c9b9b00] bound to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.125 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(114991763PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:55:20.125 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:55:20.125 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@3549af50]
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@ca48bb2] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@3c912ac7] to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:55:20.125  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(881332062PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.125 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:55:20.140 DEBUG 14968 --- [nio-8080-exec-2] r$ExtendedEntityManagerInvocationHandler : Starting resource-local transaction on application-managed EntityManager [SessionImpl(881332062PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:55:20.140 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@7121383] for key [SessionImpl(881332062PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.140 DEBUG 14968 --- [nio-8080-exec-2] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:55:20.148 DEBUG 14968 --- [nio-8080-exec-2] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:55:20.148 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:55:20.148 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs21: org.h2.result.LocalResultImpl@4ae56ee9 columns: 7 rows: 1 pos: -1]
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs21: org.h2.result.LocalResultImpl@4ae56ee9 columns: 7 rows: 1 pos: 1]
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs21: org.h2.result.LocalResultImpl@4ae56ee9 columns: 7 rows: 1 pos: 1]
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:55:20.179 DEBUG 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep3: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 1}]
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@7121383] for key [SessionImpl(881332062PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] from thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.179 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:55:20.179 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(114991763PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:55:20.179 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:55:20.195 DEBUG 14968 --- [nio-8080-exec-2] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:55:20.195 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep4: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'First modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@ca48bb2] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@3c912ac7] from thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2019-09-21 17:55:20.211  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : After first transaction
2019-09-21 17:55:20.211  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : Before second transaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Retrieved value [org.springframework.orm.jpa.EntityManagerHolder@4e541948] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1c9b9b00] bound to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(114991763PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] for JPA transaction
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@291b0cfb]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@4875b815] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@3c912ac7] to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2019-09-21 17:55:20.211  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : Actual EntityManager instance: SessionImpl(881332062PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to begin transaction via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction begun via JDBC Connection.setAutoCommit(false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] r$ExtendedEntityManagerInvocationHandler : Starting resource-local transaction on application-managed EntityManager [SessionImpl(881332062PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@51938ddf] for key [SessionImpl(881332062PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] to thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:55:20.211  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : 'message' managed by Entity Manager?: true
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] r$ExtendedEntityManagerInvocationHandler : Joined local transaction
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] org.hibernate.SQL                        : select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=?]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering result set [rs22: org.h2.result.LocalResultImpl@7f3fb2f4 columns: 7 rows: 1 pos: -1]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing result set [rs22: org.h2.result.LocalResultImpl@7f3fb2f4 columns: 7 rows: 1 pos: 1]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing result set [rs22: org.h2.result.LocalResultImpl@7f3fb2f4 columns: 7 rows: 1 pos: 1]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep5: select message0_.id as id1_1_0_, message0_.approved_by as approved2_1_0_, message0_.approved_date as approved3_1_0_, message0_.description as descript4_1_0_, message0_.owner as owner5_1_0_, message0_.publish_date as publish_6_1_0_, message0_.remove_date as remove_d7_1_0_ from message message0_ where message0_.id=? {1: 2}]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCommit synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering beforeCompletion synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerSynchronization@51938ddf] for key [SessionImpl(881332062PersistenceContext[entityKeys=[EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#1], EntityKey[info.saladlam.example.spring.noticeboard.entity.Message#2]],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])] from thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(114991763PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=ExecutableList{size=0} updates=ExecutableList{size=0} deletions=ExecutableList{size=0} orphanRemovals=ExecutableList{size=0} collectionCreations=ExecutableList{size=0} collectionRemovals=ExecutableList{size=0} collectionUpdates=ExecutableList{size=0} collectionQueuedOps=ExecutableList{size=0} unresolvedInsertDependencies=null])]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCommit synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#beforeTransactionCompletion()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Automatically flushing session
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] org.hibernate.SQL                        : update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Registering statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=?]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Closing prepared statement [prep6: update message set approved_by=?, approved_date=?, description=?, owner=?, publish_date=?, remove_date=? where id=? {1: 'admin', 2: TIMESTAMP '2019-07-31 21:00:00', 3: 'Second modify.', 4: 'user1', 5: TIMESTAMP '2019-08-01 12:30:00', 6: NULL, 7: 1}]
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Preparing to commit transaction via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : Transaction committed via JDBC Connection.commit()
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Clearing transaction synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Triggering afterCompletion synchronization
2019-09-21 17:55:20.211 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.jdbc.datasource.ConnectionHolder@4875b815] for key [org.springframework.jdbc.datasource.embedded.EmbeddedDatabaseFactory$EmbeddedDataSourceProxy@3c912ac7] from thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.211 DEBUG 14968 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2019-09-21 17:55:20.211  INFO 14968 --- [nio-8080-exec-2] i.s.e.s.n.controller.JpaTestController   : After second transaction
2019-09-21 17:55:20.226 DEBUG 14968 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain;q=0.8', given [text/html, application/xhtml+xml, application/xml;q=0.9, */*;q=0.8] and supported [text/plain]
2019-09-21 17:55:20.226 DEBUG 14968 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Writing ["OK"]
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] .s.t.s.TransactionSynchronizationManager : Removed value [org.springframework.orm.jpa.EntityManagerHolder@4e541948] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@1c9b9b00] from thread [http-nio-8080-exec-2]
2019-09-21 17:55:20.242 DEBUG 14968 --- [nio-8080-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] org.hibernate.internal.SessionImpl       : Closing session [c5f1e98b-e0be-49f6-9fb9-bdb67f43c16b]
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.LogicalConnectionManagedImpl   : Closing logical connection
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.ResourceRegistryStandardImpl   : Releasing JDBC resources
2019-09-21 17:55:20.242 TRACE 14968 --- [nio-8080-exec-2] o.h.r.j.i.LogicalConnectionManagedImpl   : Logical connection closed
2019-09-21 17:55:20.242 DEBUG 14968 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Screenshot of http://localhost:8080/ after access http://localhost:8080/jpatest/

Analysis

The behavior is the same as case 2.