devbox
2023面试高手
这个屌丝很懒，什么也没留下！
关注作者
热门标签
热门文章
当前位置:   article > 正文

Spring 嵌套事务回滚的问题

作者：2023面试高手 | 2024-04-08 17:42:39

赞

踩

Spring 嵌套事务回滚的问题

目录

Spring 嵌套事务回滚的问题

问题描述

项目背景：

问题重现

1. Spring的声明事务

2. 事务的事件处理逻辑

3.实际业务Service层方法

4.Druid数据源的配置

5.测试执行

日志分析

分析问题产生的原因

总结

Spring 的事务代码分析

Spring 的事务传播类型总结

新的问题

方案1

方案2

Spring 嵌套事务回滚的问题

问题描述

线上的项目出现，Spring的事务回滚了，但仍触发了事务提交成功的事件。这就导致原先通过异步事件解藕的业务处理数据会不正确。例如业务更新成功后才发送通知消息的处理，会出现业务回滚了，仍触发了发送消息通知的处理。

项目背景：

Spring Boot 2.0.0 +  druid 1.1.9

问题重现

1. Spring的声明事务

事务的传播级别: PROPAGATION_NESTED

  1. @Configuration
  2. public class TxAnoConfig {
  3.   
  4.   
  5.    private static final int TX_METHOD_TIMEOUT = 3600;
  6.    private static final String AOP_POINTCUT_EXPRESSION = "execution (* com.abc.service..*.*(..)) ";
  7.     /*事务拦截类型*/
  8.     @Bean("txSource")
  9.     public TransactionAttributeSource transactionAttributeSource(){
  10.         NameMatchTransactionAttributeSource source = new NameMatchTransactionAttributeSource();
  11.  
  12.         /**
  13.          * REQUIRED--支持当前事务，如果当前没有事务，就新建一个事务。这是最常见的选择。 
  14.          * SUPPORTS--支持当前事务，如果当前没有事务，就以非事务方式执行。 
  15.          * MANDATORY--支持当前事务，如果当前没有事务，就抛出异常。 
  16.          * REQUIRES_NEW--新建事务，如果当前存在事务，把当前事务挂起。 
  17.          * NOT_SUPPORTED--以非事务方式执行操作，如果当前存在事务，就把当前事务挂起。 
  18.          * NEVER--以非事务方式执行，如果当前存在事务，则抛出异常。
  19.          * NESTED--如果当前存在事务，则在嵌套事务内执行。如果当前没有事务，则执行与PROPAGATION_REQUIRED类似的操作。
  20.          */
  21.         readOnlyTx.setPropagationBehavior(TransactionDefinition.PROPAGATION_SUPPORTS );
  22.         /*当前存在事务就使用当前事务，当前不存在事务就创建一个新的事务*/
  23.         //RuleBasedTransactionAttribute requiredTx = new RuleBasedTransactionAttribute();
  24.         //requiredTx.setRollbackRules(
  25.         //    Collections.singletonList(new RollbackRuleAttribute(Exception.class)));
  26.         //requiredTx.setPropagationBehavior(TransactionDefinition.PROPAGATION_REQUIRED);
  27.         RuleBasedTransactionAttribute nestedTx = new RuleBasedTransactionAttribute(TransactionDefinition.PROPAGATION_NESTED,
  28.             Collections.singletonList(new RollbackRuleAttribute(Exception.class)));
  29.         nestedTx.setTimeout(TX_METHOD_TIMEOUT);
  30.         Map<String, TransactionAttribute> txMap = new HashMap<>();
  31.         //定义哪些方法启动事务
  32.         txMap.put("add*", nestedTx);
  33.         txMap.put("save*", nestedTx);
  34.         txMap.put("insert*", nestedTx);
  35.         txMap.put("update*", nestedTx);
  36.         txMap.put("delete*", nestedTx);
  37.         txMap.put("create*", nestedTx);
  38.         
  39.         source.setNameMap( txMap );
  40.  
  41.         return source;
  42.     }
  43.  
  44.     /**切面拦截规则 参数会自动从容器中注入*/
  45.     @Bean
  46.     public AspectJExpressionPointcutAdvisor pointcutAdvisor(TransactionInterceptor txInterceptor){
  47.         AspectJExpressionPointcutAdvisor pointcutAdvisor = new AspectJExpressionPointcutAdvisor();
  48.         pointcutAdvisor.setAdvice(txInterceptor);
  49.         pointcutAdvisor.setExpression(AOP_POINTCUT_EXPRESSION);
  50.         return pointcutAdvisor;
  51.     }
  52.  
  53.     /*事务拦截器*/
  54.     @Bean("txInterceptor")
  55.     TransactionInterceptor getTransactionInterceptor(PlatformTransactionManager tx){
  56.         return new TransactionInterceptor(tx , transactionAttributeSource()) ;
  57.     }
  58. }
  59.

2. 事务的事件处理逻辑

  1. @Log4j2
  2. @Component
  3. @Transactional(propagation = Propagation.REQUIRES_NEW)
  4. public class TestListener {
  5.  
  6.     @Async
  7.     @TransactionalEventListener(phase= TransactionPhase.BEFORE_COMMIT)
  8.     public void beforeCommitEvent(TestEvent event){
  9.         log.info("测试事件-事务提交前事件:【{}】",event.getStr());
  10.     }
  11.  
  12.     @Async
  13.     @TransactionalEventListener(phase= TransactionPhase.AFTER_COMMIT)
  14.     public void afterCommitEvent(TestEvent event){
  15.         log.info("测试事件-事务提交成功事件:【{}】",event.getStr());
  16.     }
  17.  
  18.     @Async
  19.     @TransactionalEventListener(phase= TransactionPhase.AFTER_ROLLBACK)
  20.     public void afterRollbackEvent(TestEvent event){
  21.         log.info("测试事件-事务回滚之后事件:【{}】",event.getStr());
  22.     }
  23.  
  24.     @Async
  25.     @TransactionalEventListener(phase= TransactionPhase.AFTER_COMPLETION)
  26.     public void afterCompletionEvent(TestEvent event){
  27.         log.info("测试事件-事务完成之后事件:【{}】",event.getStr());
  28.     }
  29.  
  30. }

3.实际业务Service层方法

  1.  
  2. public void updateInfo(Integer id) {
  3.         SystemUserCommonResult user = new SystemUserCommonResult();
  4.         user.setId(0);
  5.         user.setName("系统");
  6.  
  7.         CommentInfoForm form = new CommentInfoForm();
  8.         form.setDataType(10);
  9.         form.setRelationId(5);
  10.         form.setContent("测试事务回滚01");
  11.  
  12.         LocalDateTime now = now();
  13.         CommentInfo record = new CommentInfo();
  14.         record.setContent(StringUtils.trimToEmpty(form.getContent()));
  15.         record.setDataType(form.getDataType());
  16.         record.setRelationId(form.getRelationId());
  17.         record.setCreateDate(now);
  18.         record.setCreatorId(user.getId());
  19.         record.setCreator(user.getName());
  20.         commentInfoMapper.insert(record);
  21.         //手动回滚事务
  22. 		TransactionAspectSupport.currentTransactionStatus().setRollbackOnly();
  23.  
  24.         //推送测试事件
  25.         applicationContext.publishEvent(new TestEvent(this,"测试事务回滚代码执行后"));
  26.  
  27.     }
  28.

4.Druid数据源的配置

启用Druid的Sping的监控

  1. #dataSource Pool configuration for DruidDataSource
  2. spring.datasource.url=jdbc:mysql://xxxxx
  3. spring.datasource.username=xxx
  4. spring.datasource.password=xxxxx
  5. spring.datasource.driver-class-name=com.mysql.jdbc.Driver
  6.  
  7. #连接池配置
  8. spring.datasource.druid.initialSize=5
  9. spring.datasource.druid.minIdle=5
  10. spring.datasource.druid.maxActive=20
  11. spring.datasource.druid.maxWait=60000
  12. spring.datasource.druid.timeBetweenEvictionRunsMillis=60000
  13. spring.datasource.druid.minEvictableIdleTimeMillis=300000
  14. spring.datasource.druid.validationQuery=SELECT 1 FROM DUAL
  15. spring.datasource.druid.testWhileIdle=true
  16. spring.datasource.druid.testOnBorrow=false
  17. spring.datasource.druid.testOnReturn=false
  18. spring.datasource.druid.poolPreparedStatements=true
  19. spring.datasource.druid.maxPoolPreparedStatementPerConnectionSize=20
  20. spring.datasource.druid.connectionProperties=druid.stat.mergeSql=true;druid.stat.slowSqlMillis=500
  21. spring.datasource.druid.useGlobalDataSourceStat=true
  22. ## 使用那些过滤器，支持stat，wall，log4j2等
  23. ### stat ： StatFilter 用于统计监控信息。
  24. ### wall ： wallfilter SQL防火墙。
  25. spring.datasource.druid.filters=stat,wall,log4j2
  26.  
  27. ## druid 监控  WebStatFilter配置，说明请参考Druid Wiki，配置_配置WebStatFilter
  28. spring.datasource.druid.web-stat-filter.enabled=true
  29. spring.datasource.druid.web-stat-filter.url-pattern=/*
  30. spring.datasource.druid.web-stat-filter.exclusions=*.js,*.gif,*.jpg,*.png,*.css,*.ico,/druid/*
  31.  
  32. ## druid 监控页面   StatViewServlet配置，说明请参考Druid Wiki，配置_StatViewServlet配置
  33. spring.datasource.druid.stat-view-servlet.enabled=true
  34. spring.datasource.druid.stat-view-servlet.url-pattern=/druid/*
  35. ##监控页面用户名和密码
  36. spring.datasource.druid.stat-view-servlet.login-username=xxxx
  37. spring.datasource.druid.stat-view-servlet.login-password=xxxx
  38. ##禁用HTML页面上的“Reset All”功能
  39. spring.datasource.druid.stat-view-servlet.reset-enable=true
  40. ##IP白名单 (没有配置或者为空，则允许所有访问)
  41. spring.datasource.druid.stat-view-servlet.allow=
  42. ##IP黑名单 (存在共同时，deny优先于allow)
  43. spring.datasource.druid.stat-view-servlet.deny=
  44. ## Spring监控配置，说明请参考Druid Github Wiki，配置_Druid和Spring关联监控配置
  45. ### Spring监控AOP切入点，如x.y.z.service.*,配置多个英文逗号分隔
  46. spring.datasource.druid.aop-patterns= com.abc.service.*
  47.

5.测试执行

修改Spring的日志的级别DEBUG，用于输出事务回滚的日志

控制台输出的日志

  1.  
  2. [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
  3. [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
  4. [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
  5. [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
  6. [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
  7. [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]
  8. [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
  9. [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
  10. [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]
  11. [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
  12. [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 ( ?, ?, ?, ?, ?, ?, ? ) 
  13. [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` (
  14.          
  15.     `id`, 
  16.     `data_type`, 
  17.     `relation_id`, 
  18.     `create_date`, 
  19.     `creator`, 
  20.     `creator_id`, 
  21.     `content`
  22.    
  23.     )
  24.     values (
  25.       ?, 
  26.       ?, 
  27.       ?, 
  28.       ?, 
  29.       ?, 
  30.       ?, 
  31.       ?
  32.     )
  33. [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), 系统(String), 0(Integer), java.io.StringReader@60487067(StringReader)
  34. [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, 系统, 0, java.io.StringReader@60487067]
  35. [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]
  36. [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` (
  37.          
  38.     `id`, 
  39.     `data_type`, 
  40.     `relation_id`, 
  41.     `create_date`, 
  42.     `creator`, 
  43.     `creator_id`, 
  44.     `content`
  45.    
  46.     )
  47.     values (
  48.       ?, 
  49.       ?, 
  50.       ?, 
  51.       ?, 
  52.       ?, 
  53.       ?, 
  54.       ?
  55.     )
  56. [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
  57. [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. 
  58. [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
  59. [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]
  60. [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
  61. [2021-10-27 13:32:55.759] [] [idle_connection_reaper] DEBUG: [o.a.h.i.c.PoolingHttpClientConnectionManager:428] - Closing expired connections
  62. [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
  63. [2021-10-27 13:32:56.252] [] [Connection evictor] DEBUG: [o.a.h.i.c.PoolingHttpClientConnectionManager:428] - Closing expired connections
  64. [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
  65. [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
  66. [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'
  67. [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'
  68. [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]
  69. [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]
  70. [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
  71. [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
  72. [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
  73. [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
  74. [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
  75. [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]
  76. [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; ''
  77. [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
  78. [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
  79. [2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} pool-connect
  80. [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
  81. [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
  82. [2021-10-27 13:32:56.543] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit false
  83. [2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] INFO : [c.e.l.TestListener:24] - 测试事件-事务提交前事件:【测试业务】
  84. [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
  85. [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]
  86. [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
  87. [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
  88. [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
  89. [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
  90. [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]
  91. [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]
  92. [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]
  93. [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]
  94. [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
  95. [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]
  96. [2021-10-27 13:32:56.566] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} commited
  97. [2021-10-27 13:32:56.566] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit true
  98. [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
  99. [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'
  100. [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]
  101. [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
  102. [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
  103. [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
  104. [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
  105. [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
  106. [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]
  107. [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; ''
  108. [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
  109. [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
  110. [2021-10-27 13:32:56.584] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] DEBUG: [d.s.Connection:132] - {conn-10003} pool-recycle
  111. [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
  112. [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
  113. [2021-10-27 13:32:56.589] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} pool-connect
  114. [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
  115. [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
  116. [2021-10-27 13:32:56.590] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} setAutoCommit false
  117. [2021-10-27 13:32:56.600] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] INFO : [c.e.l.TestListener:30] - 测试事件-事务提交成功事件:【测试业务】
  118. [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
  119. [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]
  120. [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
  121. [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
  122. [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
  123. [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
  124. [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'
  125. [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]
  126. [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
  127. [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
  128. [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
  129. [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
  130. [2021-10-27 13:32:56.610] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} commited
  131. [2021-10-27 13:32:56.611] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} setAutoCommit true
  132. [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
  133. [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]
  134. [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; ''
  135. [2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} pool-connect
  136. [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
  137. [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
  138. [2021-10-27 13:32:56.619] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit false
  139. [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
  140. [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
  141. [2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] INFO : [c.e.l.TestListener:42] - 测试事件-事务完成之后事件:【测试业务】
  142. [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
  143. [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]
  144. [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
  145. [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
  146. [2021-10-27 13:32:56.630] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] DEBUG: [d.s.Connection:132] - {conn-10002} pool-recycle
  147. [2021-10-27 13:32:56.637] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} commited
  148. [2021-10-27 13:32:56.637] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} setAutoCommit true
  149. [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
  150. [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
  151. [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
  152. [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
  153. [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
  154. [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
  155. [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
  156. [2021-10-27 13:32:56.655] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] DEBUG: [d.s.Connection:132] - {conn-10003} pool-recycle
  157. [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
  158. [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
  159. [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
  160. [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=成功, result=null, results=null, errors=null)] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@7220a594]
  161. [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
  162. [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
  163.

日志分析

从日志中可以看到事务的创建、回滚的以及触发事务事件的全部过程。

创建nested的顶层事务的日志

  1. [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
  2. [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
  3. [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
  4. [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
  5. [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

对应的调用链 org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction -> org.springframework.transaction.interceptor.TransactionAspectSupport#createTransactionIfNecessary -> org.springframework.transaction.support.AbstractPlatformTransactionManager#getTransaction -> org.springframework.transaction.support.AbstractPlatformTransactionManager#doBegin

具体的代码分析后面再补，这里就不展开。

创建nested的第二层事务的日志

  1. [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]
  2. [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

对应的调用链： org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction -> org.springframework.transaction.interceptor.TransactionAspectSupport#createTransactionIfNecessary -> org.springframework.transaction.support.AbstractPlatformTransactionManager#getTransaction -> org.springframework.transaction.support.AbstractPlatformTransactionManager#handleExistingTransaction

具体的代码分析后面再补，这里就不展开。

事务回滚的日志

  1. [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]
  2. [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
  3.  
  4. [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
  5. [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

对应的调用链：

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

具体的代码分析后面再补，这里就不展开。

事务事件触发日志

  1. [2021-10-27 13:32:56.557] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-1] INFO : [c.e.l.TestListener:24] - 测试事件-事务提交前事件:【测试业务】
  2. [2021-10-27 13:32:56.600] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-2] INFO : [c.e.l.TestListener:30] - 测试事件-事务提交成功事件:【测试业务】
  3. [2021-10-27 13:32:56.628] [d60c4bd9-5f42-4aff-bbb1-0f11e16890b5] [spring-async-3] INFO : [c.e.l.TestListener:42] - 测试事件-事务完成之后事件:【测试业务】

从日志中就能看出，调用业务方法时，创建了两个事件，回滚里其中一个，最终没有触发事务回滚事件，而是触发了事务提交成功事件。

通过分析源码和运行时的调用栈，发现问题的原因是业务方法被Sping的事务增强了两次，即同一个方法被包了两层Spring的事务。

示意图：

Alt text

实际的调用栈： 

 

Alt text

分析Spring的事务处理源码后发现，当出现这种情况时，对于PROPAGATION_NESTED 事务传播类型，如果里层事务是通过TransactionAspectSupport.currentTransactionStatus().setRollbackOnly() 手动回滚的，上一层和顶层事务是不会回滚的，回滚的只是执行了该代码的当前层的事务。更上层的事务仍会按照正常成功的事务提交。

分析问题产生的原因

通过分析调用栈发现问题的原因是Druid Spring 监控配置导致的重复增强的处理，这个问题之前在分析Spring Boot循环依赖的问题时也发现了，具体可以参考Spring Boot 2.0.0 升级到2.4.1 循环依赖问题的解决 ，原因是同一个原因，升级Druid的版本就可以了。这个应该是Druid的一个BUG。当然也可以通过不配置spring.datasource.druid.aop-patterns来禁用Druid的Sping监控来处理。

总结

Spring 的事务代码分析

事务增强的处理逻辑

org.springframework.transaction.interceptor.TransactionAspectSupport#invokeWithinTransaction

  1.  
  2. protected Object invokeWithinTransaction(Method method, @Nullable Class<?> targetClass,
  3. 			final InvocationCallback invocation) throws Throwable {
  4.  
  5. 		// If the transaction attribute is null, the method is non-transactional.
  6. 		TransactionAttributeSource tas = getTransactionAttributeSource();
  7. 		final TransactionAttribute txAttr = (tas != null ? tas.getTransactionAttribute(method, targetClass) : null);
  8. 		final PlatformTransactionManager tm = determineTransactionManager(txAttr);
  9. 		final String joinpointIdentification = methodIdentification(method, targetClass, txAttr);
  10.  
  11. 		if (txAttr == null || !(tm instanceof CallbackPreferringPlatformTransactionManager)) {
  12. 			// Standard transaction demarcation with getTransaction and commit/rollback calls.
  13. 			TransactionInfo txInfo = createTransactionIfNecessary(tm, txAttr, joinpointIdentification);
  14. 			Object retVal = null;
  15. 			try {
  16. 				// This is an around advice: Invoke the next interceptor in the chain.
  17. 				// This will normally result in a target object being invoked.
  18. 				retVal = invocation.proceedWithInvocation();
  19. 			}
  20. 			catch (Throwable ex) {
  21. 				// target invocation exception
  22. 				completeTransactionAfterThrowing(txInfo, ex);
  23. 				throw ex;
  24. 			}
  25. 			finally {
  26. 				cleanupTransactionInfo(txInfo);
  27. 			}
  28. 			commitTransactionAfterReturning(txInfo);
  29. 			return retVal;
  30. 		}
  31.  
  32. 		else {
  33. 			final ThrowableHolder throwableHolder = new ThrowableHolder();
  34.  
  35. 			// It's a CallbackPreferringPlatformTransactionManager: pass a TransactionCallback in.
  36. 			try {
  37. 				Object result = ((CallbackPreferringPlatformTransactionManager) tm).execute(txAttr, status -> {
  38. 					TransactionInfo txInfo = prepareTransactionInfo(tm, txAttr, joinpointIdentification, status);
  39. 					try {
  40. 						return invocation.proceedWithInvocation();
  41. 					}
  42. 					catch (Throwable ex) {
  43. 						if (txAttr.rollbackOn(ex)) {
  44. 							// A RuntimeException: will lead to a rollback.
  45. 							if (ex instanceof RuntimeException) {
  46. 								throw (RuntimeException) ex;
  47. 							}
  48. 							else {
  49. 								throw new ThrowableHolderException(ex);
  50. 							}
  51. 						}
  52. 						else {
  53. 							// A normal return value: will lead to a commit.
  54. 							throwableHolder.throwable = ex;
  55. 							return null;
  56. 						}
  57. 					}
  58. 					finally {
  59. 						cleanupTransactionInfo(txInfo);
  60. 					}
  61. 				});
  62.  
  63. 				// Check result state: It might indicate a Throwable to rethrow.
  64. 				if (throwableHolder.throwable != null) {
  65. 					throw throwableHolder.throwable;
  66. 				}
  67. 				return result;
  68. 			}
  69. 			catch (ThrowableHolderException ex) {
  70. 				throw ex.getCause();
  71. 			}
  72. 			catch (TransactionSystemException ex2) {
  73. 				if (throwableHolder.throwable != null) {
  74. 					logger.error("Application exception overridden by commit exception", throwableHolder.throwable);
  75. 					ex2.initApplicationException(throwableHolder.throwable);
  76. 				}
  77. 				throw ex2;
  78. 			}
  79. 			catch (Throwable ex2) {
  80. 				if (throwableHolder.throwable != null) {
  81. 					logger.error("Application exception overridden by commit exception", throwableHolder.throwable);
  82. 				}
  83. 				throw ex2;
  84. 			}
  85. 		}
  86. 	}

事务方法执行异常的处理

org.springframework.transaction.interceptor.TransactionAspectSupport#completeTransactionAfterThrowing

  1. protected void completeTransactionAfterThrowing(@Nullable TransactionInfo txInfo, Throwable ex) {
  2. 		if (txInfo != null && txInfo.getTransactionStatus() != null) {
  3. 			if (logger.isTraceEnabled()) {
  4. 				logger.trace("Completing transaction for [" + txInfo.getJoinpointIdentification() +
  5. 						"] after exception: " + ex);
  6. 			}
  7. 			//判断异常是否在事务配置的异常捕获范围内，是的话执行回滚操作
  8. 			if (txInfo.transactionAttribute != null && txInfo.transactionAttribute.rollbackOn(ex)) {
  9. 				try {
  10. 					txInfo.getTransactionManager().rollback(txInfo.getTransactionStatus());
  11. 				}
  12. 				catch (TransactionSystemException ex2) {
  13. 					logger.error("Application exception overridden by rollback exception", ex);
  14. 					ex2.initApplicationException(ex);
  15. 					throw ex2;
  16. 				}
  17. 				catch (RuntimeException | Error ex2) {
  18. 					logger.error("Application exception overridden by rollback exception", ex);
  19. 					throw ex2;
  20. 				}
  21. 			}
  22. 			//不是的话，执行提交操作
  23. 			else {
  24. 				// We don't roll back on this exception.
  25. 				// Will still roll back if TransactionStatus.isRollbackOnly() is true.
  26. 				try {
  27. 					txInfo.getTransactionManager().commit(txInfo.getTransactionStatus());
  28. 				}
  29. 				catch (TransactionSystemException ex2) {
  30. 					logger.error("Application exception overridden by commit exception", ex);
  31. 					ex2.initApplicationException(ex);
  32. 					throw ex2;
  33. 				}
  34. 				catch (RuntimeException | Error ex2) {
  35. 					logger.error("Application exception overridden by commit exception", ex);
  36. 					throw ex2;
  37. 				}
  38. 			}
  39. 		}
  40. 	}

判断事务是否回滚的处理逻辑

org.springframework.transaction.support.AbstractPlatformTransactionManager#commit

  1. 	public final void commit(TransactionStatus status) throws TransactionException {
  2. 		if (status.isCompleted()) {
  3. 			throw new IllegalTransactionStateException(
  4. 					"Transaction is already completed - do not call commit or rollback more than once per transaction");
  5. 		}
  6.  
  7. 		DefaultTransactionStatus defStatus = (DefaultTransactionStatus) status;
  8. 		// 判断是否手动设置了回滚，即调用了TransactionAspectSupport.currentTransactionStatus().setRollbackOnly()
  9. 		if (defStatus.isLocalRollbackOnly()) {
  10. 			if (defStatus.isDebug()) {
  11. 				logger.debug("Transactional code has requested rollback");
  12. 			}
  13. 			//手动回滚，不是意外的回滚
  14. 			processRollback(defStatus, false);
  15. 			return;
  16. 		}
  17. 		// 判断是否需要全局回滚，即整个事务触发异常了，或者手动设置了Connection的回滚标志
  18. 		if (!shouldCommitOnGlobalRollbackOnly() && defStatus.isGlobalRollbackOnly()) {
  19. 			if (defStatus.isDebug()) {
  20. 				logger.debug("Global transaction is marked as rollback-only but transactional code requested commit");
  21. 			}
  22. 			//全局的回滚为意外的回滚
  23. 			processRollback(defStatus, true);
  24. 			return;
  25. 		}
  26.  
  27. 		processCommit(defStatus);
  28. 	}

作死小技巧： 手动修改事务的isGlobalRollbackOnly 为true的方法（玩玩可以，别用在实际代码上）

  1. TransactionStatus transactionStatus = TransactionAspectSupport.currentTransactionStatus();
  2. if(transactionStatus instanceof DefaultTransactionStatus){
  3.     DefaultTransactionStatus defaultTransactionStatus = (DefaultTransactionStatus)transactionStatus;
  4.     Object object = defaultTransactionStatus.getTransaction();
  5.     if(object instanceof JdbcTransactionObjectSupport){
  6.         JdbcTransactionObjectSupport transactionObject = (JdbcTransactionObjectSupport) object;
  7.         transactionObject.getConnectionHolder().setRollbackOnly();
  8.     }
  9. }

回滚的处理逻辑

org.springframework.transaction.support.AbstractPlatformTransactionManager#processRollback

  1. private void processRollback(DefaultTransactionStatus status, boolean unexpected) {
  2. 		try {
  3. 		    
  4. 			boolean unexpectedRollback = unexpected;
  5.  
  6. 			try {
  7. 			    //触发事务完成前的事件
  8. 				triggerBeforeCompletion(status);
  9. 				
  10. 				//如果当前事务支持部分回滚，则执行部分回滚，即`nested`事务
  11. 				if (status.hasSavepoint()) {
  12. 					if (status.isDebug()) {
  13. 						logger.debug("Rolling back transaction to savepoint");
  14. 					}
  15. 					status.rollbackToHeldSavepoint();
  16. 				}
  17. 				// 当前事务是顶层事务的回滚
  18. 				else if (status.isNewTransaction()) {
  19. 					if (status.isDebug()) {
  20. 						logger.debug("Initiating transaction rollback");
  21. 					}
  22. 					doRollback(status);
  23. 				}
  24. 				else {
  25. 					//异常的事务回滚处理
  26. 					// Participating in larger transaction
  27. 					if (status.hasTransaction()) {
  28. 						if (status.isLocalRollbackOnly() || isGlobalRollbackOnParticipationFailure()) {
  29. 							if (status.isDebug()) {
  30. 								logger.debug("Participating transaction failed - marking existing transaction as rollback-only");
  31. 							}
  32. 							//设置全局回滚
  33. 							doSetRollbackOnly(status);
  34. 						}
  35. 						else {
  36. 							if (status.isDebug()) {
  37. 								logger.debug("Participating transaction failed - letting transaction originator decide on rollback");
  38. 							}
  39. 						}
  40. 					}
  41. 					else {
  42. 						logger.debug("Should roll back transaction but cannot - no transaction available");
  43. 					}
  44. 					// Unexpected rollback only matters here if we're asked to fail early
  45. 					if (!isFailEarlyOnGlobalRollbackOnly()) {
  46. 						unexpectedRollback = false;
  47. 					}
  48. 				}
  49. 			}
  50. 			catch (RuntimeException | Error ex) {
  51. 				triggerAfterCompletion(status, TransactionSynchronization.STATUS_UNKNOWN);
  52. 				throw ex;
  53. 			}
  54. 			//触发事务提交后的事件
  55. 			triggerAfterCompletion(status, TransactionSynchronization.STATUS_ROLLED_BACK);
  56.  
  57. 		
  58. 			// Raise UnexpectedRollbackException if we had a global rollback-only marker
  59. 			if (unexpectedRollback) {
  60. 				throw new UnexpectedRollbackException(
  61. 						"Transaction rolled back because it has been marked as rollback-only");
  62. 			}
  63. 		}
  64. 		finally {
  65. 			cleanupAfterCompletion(status);
  66. 		}
  67. 	}

Spring 的事务传播类型总结

PROPAGATION_NESTED

  • 1、共用一个事务，但每一层都有独立的保存点，可以独立提交事务的回滚。
  • 2、每层事务可以通过TransactionAspectSupport.currentTransactionStatus().setRollbackOnly() 独立设置是否回滚。当前层的回滚不会影响上层的回滚，但上层的回滚会影响下层的回滚。
  • 3、如果是通过抛出异常导致的回滚，这个会触发整个事务的回滚（Sping的事务处理中异常的回滚处理和手动回滚走的不同的处理逻辑）。
  • 4、如果下层回滚，最上层不回滚，则最终事务仍是作为正常提交成功的事务，仍会触发事务提交成功后的事件，并不会触发事务回滚的事件。即最终事务的状态由最顶层的事务决定。

PROPAGATION_REQUIRED

  • 1、共用一个事务，只能设置全局回滚或全局不回滚，不支持局部回滚。
  • 2、如果有多层，只要有任意一层设置了回滚，则它的上一层及最上层也必须设置回滚，否则会抛出Transaction rolled back because it has been marked as rollback-only异常。
  • 3、由于所有层都是统一的提交和回滚，因此不会出现部分提交的问题。

新的问题

如果要实现在事务中任意一层回滚了，整个事务全部回滚，在不修改业务逻辑的情况下，如何实现呢？

思路有以下几个：

方案1

修改所有的需要手动提交事务的业务方法，当需要手动回滚事务时，方法返回需要回滚事务。

优点

实现简单

缺点

需要修改所有相关的业务方法，并且需要占用业务方法的返回值。

方案2

用AOP方法对所有需要事务增强的方法再包一层，增加自定义的否全局回滚的标志，在调用完实际业务方法后，判断全局回滚标志是否开启，是的话，手动设置当前层回滚事务。 同时在所有需要手动回滚的事务方法里，在执行手动回滚事务时，同时修改该当前事务的自定义的全局回滚标志。

优点

实现困难，类似于分布式事务的处理逻辑，需要考虑多线程的问题。

缺点

不影响业务代码，只需对手动回滚业务的操作再封装一层即可。

后续抽空实现以下方案2，看看效果，目前先用方案1

声明：本文内容由网友自发贡献，不代表【wpsshop博客】立场，版权归原作者所有，本站不承担相应法律责任。如您发现有侵权的内容，请联系我们。转载请注明出处：https://www.wpsshop.cn/w/2023面试高手/article/detail/387174
推荐阅读
相关标签

Copyright © 2003-2013 www.wpsshop.cn 版权所有，并保留所有权利。

  

闽ICP备14008679号