Spring nested transaction rollback

Posted by Adam on Wed, 27 Oct 2021 09:15:38 +0200

catalogue

Spring nested transaction rollback

Problem description

Project background:

Problem recurrence

1. Declaration transaction of spring

2. Event processing logic of transaction

3. Actual business Service layer method

4.Druid data source configuration

5. Test execution

Log analysis

Analyze the cause of the problem

summary

Transaction code analysis of Spring

Summary of transaction propagation types in Spring

New problems

Option 1

Option 2

Spring nested transaction rollback

Problem description

When an online project appears, the Spring transaction is rolled back, but the event of successful transaction submission is still triggered. This leads to incorrect business processing data originally decoupled through asynchronous events. For example, in the process of sending a notification message after the business update is successful, the business rollback still triggers the process of sending a message notification.

Project background:

Spring Boot 2.0.0 +  druid 1.1.9

Problem recurrence

1. Declaration transaction of spring

Propagation level of transaction:   PROPAGATION_NESTED

@Configuration
public class TxAnoConfig {
  
  
   private static final int TX_METHOD_TIMEOUT = 3600;
   private static final String AOP_POINTCUT_EXPRESSION = "execution (* com.abc.service..*.*(..)) ";
    /*Transaction interception type*/
    @Bean("txSource")
    public TransactionAttributeSource transactionAttributeSource(){
        NameMatchTransactionAttributeSource source = new NameMatchTransactionAttributeSource();

        /**
         * REQUIRED--The current transaction is supported. If there is no current transaction, a new transaction will be created. This is the most common choice. 
         * SUPPORTS--The current transaction is supported. If there is no current transaction, it will be executed in a non transactional manner. 
         * MANDATORY--Supports the current transaction. If there is no current transaction, an exception will be thrown. 
         * REQUIRES_NEW--Create a new transaction. If there is a current transaction, suspend the current transaction. 
         * NOT_SUPPORTED--The operation is performed in a non transactional manner. If there is a current transaction, the current transaction is suspended. 
         * NEVER--Execute in a non transactional manner. If a transaction currently exists, an exception will be thrown.
         * NESTED--If a transaction currently exists, it is executed within a nested transaction. If there is no current transaction, execute the same as the deployment_ Required similar operations.
         */
        readOnlyTx.setPropagationBehavior(TransactionDefinition.PROPAGATION_SUPPORTS );
        /*Use the current transaction if there is a current transaction, and create a new transaction if there is no current transaction*/
        //RuleBasedTransactionAttribute requiredTx = new RuleBasedTransactionAttribute();
        //requiredTx.setRollbackRules(
        //    Collections.singletonList(new RollbackRuleAttribute(Exception.class)));
        //requiredTx.setPropagationBehavior(TransactionDefinition.PROPAGATION_REQUIRED);
        RuleBasedTransactionAttribute nestedTx = new RuleBasedTransactionAttribute(TransactionDefinition.PROPAGATION_NESTED,
            Collections.singletonList(new RollbackRuleAttribute(Exception.class)));
        nestedTx.setTimeout(TX_METHOD_TIMEOUT);
        Map<String, TransactionAttribute> txMap = new HashMap<>();
        //Define which methods start a transaction
        txMap.put("add*", nestedTx);
        txMap.put("save*", nestedTx);
        txMap.put("insert*", nestedTx);
        txMap.put("update*", nestedTx);
        txMap.put("delete*", nestedTx);
        txMap.put("create*", nestedTx);
        
        source.setNameMap( txMap );
 
        return source;
    }
 
    /**The facet interception rule parameters are automatically injected from the container*/
    @Bean
    public AspectJExpressionPointcutAdvisor pointcutAdvisor(TransactionInterceptor txInterceptor){
        AspectJExpressionPointcutAdvisor pointcutAdvisor = new AspectJExpressionPointcutAdvisor();
        pointcutAdvisor.setAdvice(txInterceptor);
        pointcutAdvisor.setExpression(AOP_POINTCUT_EXPRESSION);
        return pointcutAdvisor;
    }
 
    /*Transaction interceptor*/
    @Bean("txInterceptor")
    TransactionInterceptor getTransactionInterceptor(PlatformTransactionManager tx){
        return new TransactionInterceptor(tx , transactionAttributeSource()) ;
    }
}

2. Event processing logic of transaction

@Log4j2
@Component
@Transactional(propagation = Propagation.REQUIRES_NEW)
public class TestListener {

    @Async
    @TransactionalEventListener(phase= TransactionPhase.BEFORE_COMMIT)
    public void beforeCommitEvent(TestEvent event){
        log.info("Test event-Events triggered before a transaction is committed:[{}]",event.getStr());
    }

    @Async
    @TransactionalEventListener(phase= TransactionPhase.AFTER_COMMIT)
    public void afterCommitEvent(TestEvent event){
        log.info("Test event-Event triggered when the transaction is submitted successfully:[{}]",event.getStr());
    }

    @Async
    @TransactionalEventListener(phase= TransactionPhase.AFTER_ROLLBACK)
    public void afterRollbackEvent(TestEvent event){
        log.info("Test event-Event after transaction rollback:[{}]",event.getStr());
    }

    @Async
    @TransactionalEventListener(phase= TransactionPhase.AFTER_COMPLETION)
    public void afterCompletionEvent(TestEvent event){
        log.info("Test event-Event triggered after the transaction completes:[{}]",event.getStr());
    }

}

3. Actual business Service layer method

public void updateInfo(Integer id) {
        SystemUserCommonResult user = new SystemUserCommonResult();
        user.setId(0);
        user.setName("system");

        CommentInfoForm form = new CommentInfoForm();
        form.setDataType(10);
        form.setRelationId(5);
        form.setContent("Test transaction rollback 01");

        LocalDateTime now = now();
        CommentInfo record = new CommentInfo();
        record.setContent(StringUtils.trimToEmpty(form.getContent()));
        record.setDataType(form.getDataType());
        record.setRelationId(form.getRelationId());
        record.setCreateDate(now);
        record.setCreatorId(user.getId());
        record.setCreator(user.getName());
        commentInfoMapper.insert(record);
        //Manually rollback transactions
		TransactionAspectSupport.currentTransactionStatus().setRollbackOnly();

        //Push test event
        applicationContext.publishEvent(new TestEvent(this,"After the test transaction rollback code is executed"));

    }

4.Druid data source configuration

Enable monitoring of Druid's spin

#dataSource Pool configuration for DruidDataSource
spring.datasource.url=jdbc:mysql://xxxxx
spring.datasource.username=xxx
spring.datasource.password=xxxxx
spring.datasource.driver-class-name=com.mysql.jdbc.Driver

#Connection pool configuration
spring.datasource.druid.initialSize=5
spring.datasource.druid.minIdle=5
spring.datasource.druid.maxActive=20
spring.datasource.druid.maxWait=60000
spring.datasource.druid.timeBetweenEvictionRunsMillis=60000
spring.datasource.druid.minEvictableIdleTimeMillis=300000
spring.datasource.druid.validationQuery=SELECT 1 FROM DUAL
spring.datasource.druid.testWhileIdle=true
spring.datasource.druid.testOnBorrow=false
spring.datasource.druid.testOnReturn=false
spring.datasource.druid.poolPreparedStatements=true
spring.datasource.druid.maxPoolPreparedStatementPerConnectionSize=20
spring.datasource.druid.connectionProperties=druid.stat.mergeSql=true;druid.stat.slowSqlMillis=500
spring.datasource.druid.useGlobalDataSourceStat=true
## Use those filters to support stat, wall, log4j2, etc
### stat: StatFilter is used to count monitoring information.
### wall: wallfilter SQL firewall.
spring.datasource.druid.filters=stat,wall,log4j2

## druid monitors the configuration of WebStatFilter. Please refer to Druid Wiki configuration for instructions_ Configure WebStatFilter
spring.datasource.druid.web-stat-filter.enabled=true
spring.datasource.druid.web-stat-filter.url-pattern=/*
spring.datasource.druid.web-stat-filter.exclusions=*.js,*.gif,*.jpg,*.png,*.css,*.ico,/druid/*

## Please refer to the Druid Wiki configuration for the configuration of StatViewServlet on druid monitoring page_ StatViewServlet configuration
spring.datasource.druid.stat-view-servlet.enabled=true
spring.datasource.druid.stat-view-servlet.url-pattern=/druid/*
##Monitoring page user name and password
spring.datasource.druid.stat-view-servlet.login-username=xxxx
spring.datasource.druid.stat-view-servlet.login-password=xxxx
##Disable the "Reset All" feature on HTML pages
spring.datasource.druid.stat-view-servlet.reset-enable=true
##IP white list (if it is not configured or empty, all access is allowed)
spring.datasource.druid.stat-view-servlet.allow=
##IP blacklist (deny takes precedence over allow when there is a common)
spring.datasource.druid.stat-view-servlet.deny=
## For Spring monitoring configuration, please refer to Druid Github Wiki configuration_ Druid and Spring are associated with monitoring configuration
### Spring monitors AOP pointcuts, such as x.y.z.service. *, and configures multiple English comma separated pointcuts
spring.datasource.druid.aop-patterns= com.abc.service.*

5. Test execution

Modify the log level DEBUG of Spring to output the log of transaction rollback

Log output from console

[2021-10-27 13:32:53.141] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:372] - Creating new transaction with name [com.abc.service.impl.TestServiceImpl.updateInfo]: PROPAGATION_NESTED,ISOLATION_DEFAULT,timeout_3600,-java.lang.Exception
[2021-10-27 13:32:53.162] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} pool-connect
[2021-10-27 13:32:53.163] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] for JDBC transaction
[2021-10-27 13:32:53.167] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] to manual commit
[2021-10-27 13:32:53.167] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} setAutoCommit false
[2021-10-27 13:32:53.184] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:447] - Creating nested transaction with name [com.abc.service.impl.TestServiceImpl.updateInfo]
[2021-10-27 13:32:53.213] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn 10005} setSavepoint-SAVEPOINT_1
[2021-10-27 13:32:53.239] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:97] - Creating a new SqlSession
[2021-10-27 13:32:53.247] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:128] - Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:53.255] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.t.SpringManagedTransaction:87] - JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] will be managed by Spring
[2021-10-27 13:32:53.260] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [c.e.m.d.C.insert:159] - ==>  Preparing: insert into `comment_info` ( `id`, `data_type`, `relation_id`, `create_date`, `creator`, `creator_id`, `content` ) values ( ?, ?, ?, ?, ?, ?, ? ) 
[2021-10-27 13:32:53.416] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Statement:137] - {conn-10005, pstmt-20000} created. insert into `comment_info` (
         
    `id`, 
    `data_type`, 
    `relation_id`, 
    `create_date`, 
    `creator`, 
    `creator_id`, 
    `content`
   
    )
    values (
      ?, 
      ?, 
      ?, 
      ?, 
      ?, 
      ?, 
      ?
    )
[2021-10-27 13:32:53.438] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [c.e.m.d.C.insert:159] - ==> Parameters: null, 10(Integer), 5(Integer), 2021-10-27 13:32:53.2346418(Timestamp), system(String), 0(Integer), java.io.StringReader@60487067(StringReader)
[2021-10-27 13:32:53.439] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Statement:137] - {conn-10005, pstmt-20000} Parameters : [null, 10, 5, 2021-10-27 13:32:53.2346418, system, 0, java.io.StringReader@60487067]
[2021-10-27 13:32:53.439] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Statement:137] - {conn-10005, pstmt-20000} Types : [INTEGER, INTEGER, INTEGER, TIMESTAMP, VARCHAR, INTEGER, OTHER]
[2021-10-27 13:32:53.463] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Statement:137] - {conn-10005, pstmt-20000} executed. 23.7545 millis. insert into `comment_info` (
         
    `id`, 
    `data_type`, 
    `relation_id`, 
    `create_date`, 
    `creator`, 
    `creator_id`, 
    `content`
   
    )
    values (
      ?, 
      ?, 
      ?, 
      ?, 
      ?, 
      ?, 
      ?
    )
[2021-10-27 13:32:53.464] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [c.e.m.d.C.insert:159] - <==    Updates: 1
[2021-10-27 13:32:53.464] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Statement:137] - {conn-10005, pstmt-20000} clearParameters. 
[2021-10-27 13:32:53.464] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [c.a.d.p.PreparedStatementPool:129] - {conn-10005, pstmt-20000} enter cache
[2021-10-27 13:32:53.465] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:186] - Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:53.466] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:700] - Transactional code has requested rollback
[2021-10-27 13:32:55.759] [] [idle_connection_reaper] DEBUG: [o.a.h.i.c.PoolingHttpClientConnectionManager:428] - Closing expired connections
[2021-10-27 13:32:55.759] [] [idle_connection_reaper] DEBUG: [o.a.h.i.c.PoolingHttpClientConnectionManager:421] - Closing connections idle longer than 60000 MILLISECONDS
[2021-10-27 13:32:56.252] [] [Connection evictor] DEBUG: [o.a.h.i.c.PoolingHttpClientConnectionManager:428] - Closing expired connections
[2021-10-27 13:32:56.486] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:830] - Rolling back transaction to savepoint
[2021-10-27 13:32:56.500] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn 10005} rollback -> SAVEPOINT_1
[2021-10-27 13:32:56.500] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.b.f.s.DefaultListableBeanFactory:255] - Returning cached instance of singleton bean 'testListener'
[2021-10-27 13:32:56.504] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.b.f.s.DefaultListableBeanFactory:255] - Returning cached instance of singleton bean 'transactionManager'
[2021-10-27 13:32:56.504] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:422] - Suspending current transaction, creating new transaction with name [com.abc.listener.TestListener.beforeCommitEvent]
[2021-10-27 13:32:56.504] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:251] - Transaction synchronization suspending SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:56.514] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-connect
[2021-10-27 13:32:56.515] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] for JDBC transaction
[2021-10-27 13:32:56.516] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] to manual commit
[2021-10-27 13:32:56.516] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit false
[2021-10-27 13:32:56.532] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.532] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6]
[2021-10-27 13:32:56.533] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:372] - Creating new transaction with name [com.abc.listener.TestListener.beforeCommitEvent]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT; ''
[2021-10-27 13:32:56.541] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} commited
[2021-10-27 13:32:56.541] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit true
[2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} pool-connect
[2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] for JDBC transaction
[2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] to manual commit
[2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit false
[2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] INFO : [c.e.l.TestListener:24] - Test event-Events triggered before a transaction is committed:[[test business]
[2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475]
[2021-10-27 13:32:56.559] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] after transaction
[2021-10-27 13:32:56.559] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-recycle
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:1011] - Resuming suspended transaction after completion of inner transaction
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:264] - Transaction synchronization resuming SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:284] - Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:310] - Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:315] - Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.560] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c]
[2021-10-27 13:32:56.566] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} commited
[2021-10-27 13:32:56.566] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit true
[2021-10-27 13:32:56.570] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} commited
[2021-10-27 13:32:56.570] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.b.f.s.DefaultListableBeanFactory:255] - Returning cached instance of singleton bean 'testListener'
[2021-10-27 13:32:56.570] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:422] - Suspending current transaction, creating new transaction with name [com.abc.listener.TestListener.afterCommitEvent]
[2021-10-27 13:32:56.570] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-connect
[2021-10-27 13:32:56.570] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] for JDBC transaction
[2021-10-27 13:32:56.571] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] to manual commit
[2021-10-27 13:32:56.571] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit false
[2021-10-27 13:32:56.581] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.581] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6]
[2021-10-27 13:32:56.581] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:372] - Creating new transaction with name [com.abc.listener.TestListener.afterCommitEvent]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT; ''
[2021-10-27 13:32:56.584] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] after transaction
[2021-10-27 13:32:56.584] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.584] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} pool-recycle
[2021-10-27 13:32:56.589] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} commited
[2021-10-27 13:32:56.589] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit true
[2021-10-27 13:32:56.589] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} pool-connect
[2021-10-27 13:32:56.590] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@2a2e613c] for JDBC transaction
[2021-10-27 13:32:56.590] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@2a2e613c] to manual commit
[2021-10-27 13:32:56.590] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} setAutoCommit false
[2021-10-27 13:32:56.600] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] INFO : [c.e.l.TestListener:30] - Test event-Event triggered when the transaction is submitted successfully:[[test business]
[2021-10-27 13:32:56.600] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.601] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@2a2e613c]
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] after transaction
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-recycle
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:1011] - Resuming suspended transaction after completion of inner transaction
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.b.f.s.DefaultListableBeanFactory:255] - Returning cached instance of singleton bean 'testListener'
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:422] - Suspending current transaction, creating new transaction with name [com.abc.listener.TestListener.afterCompletionEvent]
[2021-10-27 13:32:56.607] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-connect
[2021-10-27 13:32:56.608] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] for JDBC transaction
[2021-10-27 13:32:56.608] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] to manual commit
[2021-10-27 13:32:56.608] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit false
[2021-10-27 13:32:56.610] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} commited
[2021-10-27 13:32:56.611] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} setAutoCommit true
[2021-10-27 13:32:56.618] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.618] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6]
[2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:372] - Creating new transaction with name [com.abc.listener.TestListener.afterCompletionEvent]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT; ''
[2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} pool-connect
[2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] for JDBC transaction
[2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] to manual commit
[2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit false
[2021-10-27 13:32:56.627] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} commited
[2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} setAutoCommit true
[2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] INFO : [c.e.l.TestListener:42] - Test event-Event triggered after the transaction completes:[[test business]
[2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:743] - Initiating transaction commit
[2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:326] - Committing JDBC transaction on Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475]
[2021-10-27 13:32:56.629] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@2a2e613c] after transaction
[2021-10-27 13:32:56.629] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.630] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} pool-recycle
[2021-10-27 13:32:56.637] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} commited
[2021-10-27 13:32:56.637] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit true
[2021-10-27 13:32:56.646] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@277226d6] after transaction
[2021-10-27 13:32:56.646] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.646] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10004} pool-recycle
[2021-10-27 13:32:56.646] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:1011] - Resuming suspended transaction after completion of inner transaction
[2021-10-27 13:32:56.646] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} setAutoCommit true
[2021-10-27 13:32:56.655] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@1fa1e475] after transaction
[2021-10-27 13:32:56.655] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.655] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} pool-recycle
[2021-10-27 13:32:56.666] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:384] - Releasing JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] after transaction
[2021-10-27 13:32:56.666] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceUtils:340] - Returning JDBC Connection to DataSource
[2021-10-27 13:32:56.666] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} pool-recycle
[2021-10-27 13:32:56.726] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.w.s.m.m.a.HttpEntityMethodProcessor:277] - Written [ResponseResult(code=0, message=success, result=null, results=null, errors=null)] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@7220a594]
[2021-10-27 13:32:56.727] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.w.s.DispatcherServlet:1076] - Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
[2021-10-27 13:32:56.727] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.w.s.DispatcherServlet:1004] - Successfully completed request

Log analysis

From the log, you can see the whole process of transaction creation, rollback and triggering transaction events.

Create a log of nested top-level transactions

[2021-10-27 13:32:53.141] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:372] - Creating new transaction with name [com.abc.service.impl.TestServiceImpl.updateInfo]: PROPAGATION_NESTED,ISOLATION_DEFAULT,timeout_3600,-java.lang.Exception
[2021-10-27 13:32:53.162] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} pool-connect
[2021-10-27 13:32:53.163] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:264] - Acquired Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] for JDBC transaction
[2021-10-27 13:32:53.167] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:281] - Switching JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@f7c20c] to manual commit
[2021-10-27 13:32:53.167] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn-10005} setAutoCommit false

Corresponding call chain   org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction  ->  org.springframework.transaction.interceptor.TransactionAspectSupport#createTransactionIfNecessary  ->  org.springframework.transaction.support.AbstractPlatformTransactionManager#getTransaction  ->  org.springframework.transaction.support.AbstractPlatformTransactionManager#doBegin

The specific code analysis will be supplemented later, which will not be expanded here.

Create a log of nested layer 2 transactions

[2021-10-27 13:32:53.184] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:447] - Creating nested transaction with name [com.expertsplatform.service.impl.TestServiceImpl.updateInfo]
[2021-10-27 13:32:53.213] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn 10005} setSavepoint-SAVEPOINT_1

Corresponding call chain:   org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction  ->  org.springframework.transaction.interceptor.TransactionAspectSupport#createTransactionIfNecessary  ->  org.springframework.transaction.support.AbstractPlatformTransactionManager#getTransaction  ->  org.springframework.transaction.support.AbstractPlatformTransactionManager#handleExistingTransaction

The specific code analysis will be supplemented later, which will not be expanded here.

Log of transaction rollback

[2021-10-27 13:32:53.465] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.m.s.SqlSessionUtils:186] - Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4a08e603]
[2021-10-27 13:32:53.466] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:700] - Transactional code has requested rollback

[2021-10-27 13:32:56.486] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [o.s.j.d.DataSourceTransactionManager:830] - Rolling back transaction to savepoint
[2021-10-27 13:32:56.500] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [http-nio-80-exec-10] DEBUG: [d.s.Connection:132] - {conn 10005} rollback -> SAVEPOINT_1

Corresponding call chain:

org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction -> org.springframework.transaction.interceptor.TransactionAspectSupport#commitTransactionAfterReturning -> org.springframework.transaction.support.AbstractPlatformTransactionManager#commit -> org.springframework.transaction.support.AbstractPlatformTransactionManager#processRollback-> org.springframework.transaction.support.AbstractTransactionStatus#rollbackToHeldSavepoint

The specific code analysis will be supplemented later, which will not be expanded here.

Transaction event trigger log

[2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] INFO : [c.e.l.TestListener:24] - Test event-Events triggered before a transaction is committed:[[test business]
[2021-10-27 13:32:56.600] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] INFO : [c.e.l.TestListener:30] - Test event-Event triggered when the transaction is submitted successfully:[[test business]
[2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] INFO : [c.e.l.TestListener:42] - Test event-Event triggered after the transaction completes:[[test business]

It can be seen from the log that when calling a business method, two events are created, one of which is rolled back. In the end, the transaction rollback event is not triggered, but the transaction submission success event is triggered.

By analyzing the source code and runtime call stack, it is found that the reason for the problem is that the business method is enhanced twice by Spring transactions, that is, the same method is wrapped with two layers of Spring transactions.

Sketch Map:

Actual call stack:  

 

After analyzing the transaction source code of Spring, it is found that when this happens, for the promotion_ NESTED   Transaction propagation type, if the underlying transaction is through TransactionAspectSupport.currentTransactionStatus().setRollbackOnly()   For manual rollback, the upper layer and top-level transactions will not be rolled back, but only the transactions of the current layer in which the code is executed. Transactions at higher levels will still be committed as normally successful transactions.

Analyze the cause of the problem

By analyzing the call stack, it is found that the cause of the problem is Druid   Repeated enhanced processing caused by Spring monitoring configuration. This problem was also found when analyzing the Spring Boot loop dependency. For details, please refer to Spring Boot 2.0.0 to 2.4.1 circular dependency solution  ， The reason is the same. Just upgrade the Druid version. This should be a BUG of Druid. Of course, you can also disable the spring monitoring of Druid by not configuring spring.datasource.druid.aop-patterns.

summary

Transaction code analysis of Spring

Transaction enhanced processing logic

org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction

protected Object invokeWithinTransaction(Method method, @Nullable Class<?> targetClass,
			final InvocationCallback invocation) throws Throwable {

		// If the transaction attribute is null, the method is non-transactional.
		TransactionAttributeSource tas = getTransactionAttributeSource();
		final TransactionAttribute txAttr = (tas != null ? tas.getTransactionAttribute(method, targetClass) : null);
		final PlatformTransactionManager tm = determineTransactionManager(txAttr);
		final String joinpointIdentification = methodIdentification(method, targetClass, txAttr);

		if (txAttr == null || !(tm instanceof CallbackPreferringPlatformTransactionManager)) {
			// Standard transaction demarcation with getTransaction and commit/rollback calls.
			TransactionInfo txInfo = createTransactionIfNecessary(tm, txAttr, joinpointIdentification);
			Object retVal = null;
			try {
				// This is an around advice: Invoke the next interceptor in the chain.
				// This will normally result in a target object being invoked.
				retVal = invocation.proceedWithInvocation();
			}
			catch (Throwable ex) {
				// target invocation exception
				completeTransactionAfterThrowing(txInfo, ex);
				throw ex;
			}
			finally {
				cleanupTransactionInfo(txInfo);
			}
			commitTransactionAfterReturning(txInfo);
			return retVal;
		}

		else {
			final ThrowableHolder throwableHolder = new ThrowableHolder();

			// It's a CallbackPreferringPlatformTransactionManager: pass a TransactionCallback in.
			try {
				Object result = ((CallbackPreferringPlatformTransactionManager) tm).execute(txAttr, status -> {
					TransactionInfo txInfo = prepareTransactionInfo(tm, txAttr, joinpointIdentification, status);
					try {
						return invocation.proceedWithInvocation();
					}
					catch (Throwable ex) {
						if (txAttr.rollbackOn(ex)) {
							// A RuntimeException: will lead to a rollback.
							if (ex instanceof RuntimeException) {
								throw (RuntimeException) ex;
							}
							else {
								throw new ThrowableHolderException(ex);
							}
						}
						else {
							// A normal return value: will lead to a commit.
							throwableHolder.throwable = ex;
							return null;
						}
					}
					finally {
						cleanupTransactionInfo(txInfo);
					}
				});

				// Check result state: It might indicate a Throwable to rethrow.
				if (throwableHolder.throwable != null) {
					throw throwableHolder.throwable;
				}
				return result;
			}
			catch (ThrowableHolderException ex) {
				throw ex.getCause();
			}
			catch (TransactionSystemException ex2) {
				if (throwableHolder.throwable != null) {
					logger.error("Application exception overridden by commit exception", throwableHolder.throwable);
					ex2.initApplicationException(throwableHolder.throwable);
				}
				throw ex2;
			}
			catch (Throwable ex2) {
				if (throwableHolder.throwable != null) {
					logger.error("Application exception overridden by commit exception", throwableHolder.throwable);
				}
				throw ex2;
			}
		}
	}

Transaction method execution exception handling

org.springframework.transaction.interceptor.TransactionAspectSupport#completeTransactionAfterThrowing

protected void completeTransactionAfterThrowing(@Nullable TransactionInfo txInfo, Throwable ex) {
		if (txInfo != null && txInfo.getTransactionStatus() != null) {
			if (logger.isTraceEnabled()) {
				logger.trace("Completing transaction for [" + txInfo.getJoinpointIdentification() +
						"] after exception: " + ex);
			}
			//Judge whether the exception is within the exception capture range of the transaction configuration. If yes, execute the rollback operation
			if (txInfo.transactionAttribute != null && txInfo.transactionAttribute.rollbackOn(ex)) {
				try {
					txInfo.getTransactionManager().rollback(txInfo.getTransactionStatus());
				}
				catch (TransactionSystemException ex2) {
					logger.error("Application exception overridden by rollback exception", ex);
					ex2.initApplicationException(ex);
					throw ex2;
				}
				catch (RuntimeException | Error ex2) {
					logger.error("Application exception overridden by rollback exception", ex);
					throw ex2;
				}
			}
			//If not, perform the commit operation
			else {
				// We don't roll back on this exception.
				// Will still roll back if TransactionStatus.isRollbackOnly() is true.
				try {
					txInfo.getTransactionManager().commit(txInfo.getTransactionStatus());
				}
				catch (TransactionSystemException ex2) {
					logger.error("Application exception overridden by commit exception", ex);
					ex2.initApplicationException(ex);
					throw ex2;
				}
				catch (RuntimeException | Error ex2) {
					logger.error("Application exception overridden by commit exception", ex);
					throw ex2;
				}
			}
		}
	}

Processing logic to determine whether a transaction is rolled back

org.springframework.transaction.support.AbstractPlatformTransactionManager#commit

	public final void commit(TransactionStatus status) throws TransactionException {
		if (status.isCompleted()) {
			throw new IllegalTransactionStateException(
					"Transaction is already completed - do not call commit or rollback more than once per transaction");
		}

		DefaultTransactionStatus defStatus = (DefaultTransactionStatus) status;
		// Judge whether rollback is set manually, that is, TransactionAspectSupport.currentTransactionStatus().setRollbackOnly() is called
		if (defStatus.isLocalRollbackOnly()) {
			if (defStatus.isDebug()) {
				logger.debug("Transactional code has requested rollback");
			}
			//Manual rollback, not unexpected rollback
			processRollback(defStatus, false);
			return;
		}
		// Judge whether global rollback is required, that is, the whole transaction triggers an exception, or manually set the rollback flag of the Connection
		if (!shouldCommitOnGlobalRollbackOnly() && defStatus.isGlobalRollbackOnly()) {
			if (defStatus.isDebug()) {
				logger.debug("Global transaction is marked as rollback-only but transactional code requested commit");
			}
			//The global rollback is unexpected
			processRollback(defStatus, true);
			return;
		}

		processCommit(defStatus);
	}

Death tip: manually modify the isGlobalRollbackOnly of the transaction   Method that is true (can be used for fun, not for actual code)

TransactionStatus transactionStatus = TransactionAspectSupport.currentTransactionStatus();
if(transactionStatus instanceof DefaultTransactionStatus){
    DefaultTransactionStatus defaultTransactionStatus = (DefaultTransactionStatus)transactionStatus;
    Object object = defaultTransactionStatus.getTransaction();
    if(object instanceof JdbcTransactionObjectSupport){
        JdbcTransactionObjectSupport transactionObject = (JdbcTransactionObjectSupport) object;
        transactionObject.getConnectionHolder().setRollbackOnly();
    }
}

Rollback processing logic

org.springframework.transaction.support.AbstractPlatformTransactionManager#processRollback

private void processRollback(DefaultTransactionStatus status, boolean unexpected) {
		try {
		    
			boolean unexpectedRollback = unexpected;

			try {
			    //Event before triggering transaction completion
				triggerBeforeCompletion(status);
				
				//If the current transaction supports partial rollback, partial rollback is executed, that is, 'nested' transaction
				if (status.hasSavepoint()) {
					if (status.isDebug()) {
						logger.debug("Rolling back transaction to savepoint");
					}
					status.rollbackToHeldSavepoint();
				}
				// The current transaction is the rollback of the top-level transaction
				else if (status.isNewTransaction()) {
					if (status.isDebug()) {
						logger.debug("Initiating transaction rollback");
					}
					doRollback(status);
				}
				else {
					//Abnormal transaction rollback
					// Participating in larger transaction
					if (status.hasTransaction()) {
						if (status.isLocalRollbackOnly() || isGlobalRollbackOnParticipationFailure()) {
							if (status.isDebug()) {
								logger.debug("Participating transaction failed - marking existing transaction as rollback-only");
							}
							//Set global rollback
							doSetRollbackOnly(status);
						}
						else {
							if (status.isDebug()) {
								logger.debug("Participating transaction failed - letting transaction originator decide on rollback");
							}
						}
					}
					else {
						logger.debug("Should roll back transaction but cannot - no transaction available");
					}
					// Unexpected rollback only matters here if we're asked to fail early
					if (!isFailEarlyOnGlobalRollbackOnly()) {
						unexpectedRollback = false;
					}
				}
			}
			catch (RuntimeException | Error ex) {
				triggerAfterCompletion(status, TransactionSynchronization.STATUS_UNKNOWN);
				throw ex;
			}
			//Event triggered after transaction commit
			triggerAfterCompletion(status, TransactionSynchronization.STATUS_ROLLED_BACK);

		
			// Raise UnexpectedRollbackException if we had a global rollback-only marker
			if (unexpectedRollback) {
				throw new UnexpectedRollbackException(
						"Transaction rolled back because it has been marked as rollback-only");
			}
		}
		finally {
			cleanupAfterCompletion(status);
		}
	}

Summary of transaction propagation types in Spring

PROPAGATION_NESTED

  • 1. Share a transaction, but each layer has an independent savepoint, which can commit the rollback of the transaction independently.
  • 2. Transactions of each layer can be processed through TransactionAspectSupport.currentTransactionStatus().setRollbackOnly()   Set whether to roll back independently. The rollback of the current layer will not affect the rollback of the upper layer, but the rollback of the upper layer will affect the rollback of the lower layer.
  • 3. If the rollback is caused by throwing an exception, this will trigger the rollback of the whole transaction (the rollback processing of exceptions in the transaction processing of spin is different from the manual rollback processing logic).
  • 4. If the lower layer rolls back and the upper layer does not roll back, the final transaction is still a transaction that is successfully committed normally, and the event after successful transaction submission will still be triggered, and the event of transaction rollback will not be triggered. That is, the state of the final transaction is determined by the top-level transaction.

PROPAGATION_REQUIRED

  • 1. If a transaction is shared, only global rollback or global no rollback can be set, and local rollback is not supported.
  • 2. If there are multiple layers, as long as rollback is set for any layer, the upper layer and the uppermost layer must also set rollback, otherwise transaction rolled back because it has been marked as rollback only exception will be thrown.
  • 3. Since all layers are committed and rolled back uniformly, there will be no problem of partial commit.

New problems

If you want to roll back any layer of a transaction and the whole transaction is rolled back, how can you do it without modifying the business logic?

The ideas are as follows:

Option 1

Modify all business methods that need to manually commit transactions. When a transaction needs to be manually rolled back, the method returns the transaction that needs to be rolled back.

advantage

Simple implementation

shortcoming

All relevant business methods need to be modified, and the return value of the business method needs to be occupied.

Option 2

Use the AOP method to package all methods that need transaction enhancement, and add a custom flag of no global rollback. After calling the actual business method, judge whether the global rollback flag is on. If yes, manually set the current layer to rollback transactions. At the same time, in all transaction methods that require manual rollback, the user-defined global rollback flag of the current transaction is modified when the manual rollback transaction is executed.

advantage

It is difficult to implement, which is similar to the processing logic of distributed transactions. Multithreading needs to be considered.

shortcoming

It does not affect the business code. You only need to encapsulate the operation of manually rolling back the business.

In the follow-up, take time to implement the following scheme 2 to see the effect. At present, use scheme 1 first

Topics: Java Spring Spring Boot

Hot Topics

©2024 Programmer Think