chenbihao opened a new issue, #6884: URL: https://github.com/apache/incubator-seata/issues/6884
<!-- Please do not use this issue template to report security vulnerabilities but refer to our [security policy](https://github.com/seata/seata/security/policy). --> - [x] I have searched the [issues](https://github.com/seata/seata/issues) of this repository and believe that this is not a duplicate. ### Ⅰ. Issue Description TCC模式遇到了奇怪的问题，提交重试超时后不会进入回滚流程？可以往哪个方向排查？ ### Ⅱ. Describe what happened 写了个使用TCC模式的 SpringCloud 2023 demo，demo是由一个触发的Controller调用本地bean的方法，业务操作是标记删除某条数据，并且为这个表加上了locked字段作为锁定资源，后面附上代码； 发现当commit阶段抛出异常时，无法按照预期流程进行（commit抛出异常应该是触发回滚？） #### 触发与调整经历 最开始，我是遇到了个空指针异常，是由context.getActionContext抛出来的，排查后发现把@BusinessActionContextParameter写在实现的方法上就解决了 然后我正常测试TCC的流程，往commit流程塞入异常抛出，发现抛出异常时，会无限重试，于是我调整了server配置： ```yml seata: server: max-commit-retry-timeout: 5000 max-rollback-retry-timeout: 8000 distributedLockExpireTime: 10000 ``` 然后继续尝试，后面发现每次调用的行为都很奇怪，清空seata server db 的表内容，重启相关服务，然后： - 第一次请求，debug断点看到，直接跑了Cancel回滚方法 - 第二次请求，debug断点看到，是跑了commit提交方法，经过几次重试后就 “提交重试超时失败”的状态了 - 一致循环下去  翻了些文章，看到了 【在 Seata1.5.1 版本中，增加了一张事务控制表，表名是 tcc_fence_log 来解决这个问题】 于是我建了这个表，并且加上注解属性：`useTCCFence = true,` ，也还是不行，重试超时后也不会进入回滚方法  可以看出我哪步操作有问题吗？或者可以往哪个方向排查？ 总结现象： - 当逻辑正常时，走完commit方法就正常结束了，这是预期中的 - 如果在try方法抛出异常，则不会走回滚 - 如果在commit方法抛出异常，则经过重试超时后，也不会走回滚 相关代码： controller: ```java @Slf4j @RestController @RequestMapping("/template") public class CouponTemplateController { @DeleteMapping("/deleteTemplateTCC") @GlobalTransactional(name = "coupon-template-serv", rollbackFor = Exception.class) public void deleteTemplateTCC(@RequestParam("id") Long id) { log.info("delete template TCC, id={}", id); couponTemplateService.deleteTemplateTCC(null,id); } } ``` TCC接口 ```java @LocalTCC public interface CouponTemplateServiceTCC extends CouponTemplateService { @TwoPhaseBusinessAction( name = "deleteTemplateTCC", useTCCFence = true, commitMethod = "deleteTemplateCommit", rollbackMethod = "deleteTemplateCancel" ) void deleteTemplateTCC(BusinessActionContext context, Long id); void deleteTemplateCommit(BusinessActionContext context); void deleteTemplateCancel(BusinessActionContext context); } ``` 接口的实现 ```java @Slf4j @Service public class CouponTemplateServiceImpl implements CouponTemplateServiceTCC { @Override @Transactional public void deleteTemplateTCC(BusinessActionContext context,@BusinessActionContextParameter(paramName = "id") Long id) { // 在 Try 阶段逻辑中，一般会先去预定操作资源 CouponTemplate filter = CouponTemplate.builder() .available(true) .locked(false) .id(id) .build(); CouponTemplate template = templateDao.findAll(Example.of(filter)) .stream().findFirst() .orElseThrow(() -> new RuntimeException("Template Not Found")); template.setLocked(true); templateDao.save(template); log.info("TCC Try"); } @Override @Transactional public void deleteTemplateCommit(BusinessActionContext context) { // Confirm 阶段执行的是主体业务逻辑，这里即删除优惠券 Long id = Long.parseLong(context.getActionContext("id").toString()); CouponTemplate template = templateDao.findById(id).get(); // 这里直接抛出异常 if (true) { throw new RuntimeException("Delete Template Failed"); } template.setLocked(false); template.setAvailable(false); templateDao.save(template); log.info("TCC committed"); } @Override @Transactional public void deleteTemplateCancel(BusinessActionContext context) { // 再次查询一次，避免空回滚 Long id = Long.parseLong(context.getActionContext("id").toString()); Optional<CouponTemplate> templateOption = templateDao.findById(id); if (templateOption.isPresent()) { CouponTemplate template = templateOption.get(); // 解锁 template.setLocked(false); templateDao.save(template); } log.info("TCC cancel"); } ``` try抛出异常时，不走回滚 的应用日志： ```java 2024-09-28T01:24:37.759+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] c.n.c.template.SentinelOriginParser : request org.apache.catalina.util.ParameterMap@4b21fdab, header=org.apache.tomcat.util.http.NamesEnumerator@45e60abf 2024-09-28T01:24:37.787+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] i.seata.tm.api.DefaultGlobalTransaction : Begin new global transaction [192.168.31.112:8091:6990156050348373295] 2024-09-28T01:24:37.787+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] c.n.c.t.c.CouponTemplateController : delete template TCC, id=6 2024-09-28T01:24:37.827+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] io.seata.rm.AbstractResourceManager : branch register success, xid:192.168.31.112:8091:6990156050348373295, branchId:6990156050348373300, lockKeys:null 2024-09-28T01:24:37.832+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] io.seata.rm.fence.SpringFenceHandler : Common fence prepare result: true. xid: 192.168.31.112:8091:6990156050348373295, branchId: 6990156050348373300 Hibernate: select ct1_0.id, ct1_0.available, ct1_0.type, ct1_0.created_time, ct1_0.description, ct1_0.locked, ct1_0.name, ct1_0.rule, ct1_0.shop_id from coupon_template ct1_0 where ct1_0.available=? and ct1_0.locked=? and ct1_0.id=? 2024-09-28T01:24:39.432+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] i.seata.tm.api.DefaultGlobalTransaction : transaction 192.168.31.112:8091:6990156050348373295 will be rollback 2024-09-28T01:24:39.469+08:00 INFO 7360 --- [coupon-template-serv] [h_RMROLE_1_3_32] i.s.c.r.p.c.RmBranchRollbackProcessor : rm handle branch rollback process:BranchRollbackRequest{xid='192.168.31.112:8091:6990156050348373295', branchId=6990156050348373300, branchType=TCC, resourceId='deleteTemplateTCC', applicationData='{"actionContext":{"action-start-time":1727457877787,"useTCCFence":true,"sys::prepare":"deleteTemplateTCC","sys::rollback":"deleteTemplateCancel","sys::commit":"deleteTemplateCommit","id":6,"host-name":"192.168.31.110","actionName":"deleteTemplateTCC"}}'} 2024-09-28T01:24:39.469+08:00 INFO 7360 --- [coupon-template-serv] [h_RMROLE_1_3_32] io.seata.rm.AbstractRMHandler : Branch Rollbacking: 192.168.31.112:8091:6990156050348373295 6990156050348373300 deleteTemplateTCC 2024-09-28T01:24:39.474+08:00 INFO 7360 --- [coupon-template-serv] [h_RMROLE_1_3_32] io.seata.rm.fence.SpringFenceHandler : Insert common fence record result: true. xid: 192.168.31.112:8091:6990156050348373295, branchId: 6990156050348373300 2024-09-28T01:24:39.509+08:00 INFO 7360 --- [coupon-template-serv] [h_RMROLE_1_3_32] io.seata.rm.AbstractResourceManager : TCC resource rollback result : true, xid: 192.168.31.112:8091:6990156050348373295, branchId: 6990156050348373300, resourceId: deleteTemplateTCC 2024-09-28T01:24:39.509+08:00 INFO 7360 --- [coupon-template-serv] [h_RMROLE_1_3_32] io.seata.rm.AbstractRMHandler : Branch Rollbacked result: PhaseTwo_Rollbacked 2024-09-28T01:24:39.531+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] i.seata.tm.api.DefaultGlobalTransaction : transaction end, xid = 192.168.31.112:8091:6990156050348373295 2024-09-28T01:24:39.532+08:00 INFO 7360 --- [coupon-template-serv] [io-20000-exec-4] i.seata.tm.api.DefaultGlobalTransaction : [192.168.31.112:8091:6990156050348373295] rollback status: Rollbacked 2024-09-28T01:24:39.532+08:00 ERROR 7360 --- [coupon-template-serv] [io-20000-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.RuntimeException: try to proceed invocation error] with root cause ``` server日志： ``` 01:24:39.521 INFO --- [verHandlerThread_1_15_500] [coordinator.DefaultCoordinator] [ doGlobalBegin] [192.168.31.112:8091:6990156050348373295] : Begin new global transaction applicationId: coupon-template-serv,transactionServiceGroup: my-seata-server-group, transactionName: coupon-template-serv,timeout:60000,xid:192.168.31.112:8091:6990156050348373295 01:24:39.523 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalBeginResponse{xid='192.168.31.112:8091:6990156050348373295', extraData='null', resultCode=Success, msg='null'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:24:39.532 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='192.168.31.112:8091:6990156050348373295', branchType=TCC, resourceId='deleteTemplateTCC', lockKey='null', applicationData='{"actionContext":{"action-start-time":1727457877787,"useTCCFence":true,"sys::prepare":"deleteTemplateTCC","sys::rollback":"deleteTemplateCancel","sys::commit":"deleteTemplateCommit","id":6,"host-name":"192.168.31.110","actionName":"deleteTemplateTCC"}}'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:24:39.560 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [192.168.31.112:8091:6990156050348373295] : Register branch successfully, xid = 192.168.31.112:8091:6990156050348373295, branchId = 6990156050348373300, resourceId = deleteTemplateTCC ,lockKeys = null 01:24:39.562 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=6990156050348373300, resultCode=Success, msg='null'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:24:41.171 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalRollbackRequest{xid='192.168.31.112:8091:6990156050348373295', extraData='null'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:24:41.248 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='192.168.31.112:8091:6990156050348373295', branchId=6990156050348373300, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:24:41.263 INFO --- [verHandlerThread_1_17_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [192.168.31.112:8091:6990156050348373295] : Rollback branch transaction successfully, xid = 192.168.31.112:8091:6990156050348373295 branchId = 6990156050348373300 01:24:41.265 INFO --- [verHandlerThread_1_17_500] [server.coordinator.DefaultCore] [ doGlobalRollback] [192.168.31.112:8091:6990156050348373295] : Rollback global transaction successfully, xid = 192.168.31.112:8091:6990156050348373295. 01:24:41.267 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalRollbackResponse{globalStatus=Rollbacked, resultCode=Success, msg='null'}, clientIp: 192.168.31.110, vgroup: my-seata-server-group 01:25:35.528 ERROR --- [nPool.commonPool-worker-1] [a.server.session.SessionHelper] [ endRollbackFailed] [192.168.31.112:8091:6990156050348373143] : The Global session 192.168.31.112:8091:6990156050348373143 has changed the status to RollbackRetryTimeout, need to be handled it manually. 01:25:35.529 INFO --- [nPool.commonPool-worker-1] [session.AbstractSessionManager] [ onFailEnd] [192.168.31.112:8091:6990156050348373143] : xid:192.168.31.112:8091:6990156050348373143 fail end, transaction:GlobalSession{xid='192.168.31.112:8091:6990156050348373143', transactionId=6990156050348373143, status=RollbackRetryTimeout, applicationId='coupon-template-serv', transactionServiceGroup='my-seata-server-group', transactionName='coupon-template-serv', timeout=60000, beginTime=1727457804775, applicationData='null', lazyLoadBranch=true, active=true, branchSessions=null, globalSessionLock=org.apache.seata.server.session.GlobalSession$GlobalSessionLock@73b39448, lifecycleListeners=[]} 01:26:00.537 ERROR --- [ RetryRollbacking_1_1] [a.server.session.SessionHelper] [ endRollbackFailed] [192.168.31.112:8091:6990156050348373193] : The Global session 192.168.31.112:8091:6990156050348373193 has changed the status to RollbackRetryTimeout, need to be handled it manually. 01:26:00.539 INFO --- [ RetryRollbacking_1_1] [session.AbstractSessionManager] [ onFailEnd] [192.168.31.112:8091:6990156050348373193] : xid:192.168.31.112:8091:6990156050348373193 fail end, transaction:GlobalSession{xid='192.168.31.112:8091:6990156050348373193', transactionId=6990156050348373193, status=RollbackRetryTimeout, applicationId='coupon-template-serv', transactionServiceGroup='my-seata-server-group', transactionName='coupon-template-serv', timeout=60000, beginTime=1727457829541, applicationData='null', lazyLoadBranch=true, active=true, branchSessions=null, globalSessionLock=org.apache.seata.server.session.GlobalSession$GlobalSessionLock@2d47f72d, lifecycleListeners=[]} 01:26:49.541 ERROR --- [ RetryRollbacking_1_1] [a.server.session.SessionHelper] [ endRollbackFailed] [192.168.31.112:8091:6990156050348373295] : The Global session 192.168.31.112:8091:6990156050348373295 has changed the status to RollbackRetryTimeout, need to be handled it manually. 01:26:49.542 INFO --- [ RetryRollbacking_1_1] [session.AbstractSessionManager] [ onFailEnd] [192.168.31.112:8091:6990156050348373295] : xid:192.168.31.112:8091:6990156050348373295 fail end, transaction:GlobalSession{xid='192.168.31.112:8091:6990156050348373295', transactionId=6990156050348373295, status=RollbackRetryTimeout, applicationId='coupon-template-serv', transactionServiceGroup='my-seata-server-group', transactionName='coupon-template-serv', timeout=60000, beginTime=1727457879498, applicationData='null', lazyLoadBranch=true, active=true, branchSessions=null, globalSessionLock=org.apache.seata.server.session.GlobalSession$GlobalSessionLock@47de468d, lifecycleListeners=[]} 01:27:40.871 INFO --- [ettyServerNIOWorker_1_7_8] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : 192.168.31.110:52110 to server channel inactive. 01:27:40.871 INFO --- [ettyServerNIOWorker_1_7_8] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : remove channel:[id: 0x4a02070a, L:/10.0.3.8:8091 ! R:/192.168.31.110:52110]context:RpcContext{applicationId='coupon-template-serv', transactionServiceGroup='my-seata-server-group', clientId='coupon-template-serv:192.168.31.110:52110', channel=[id: 0x4a02070a, L:/10.0.3.8:8091 ! R:/192.168.31.110:52110], resourceSets=null} ``` ### Ⅴ. Anything else we need to know? ### Ⅵ. Environment: - JDK version(e.g. `java -version`):17 - Seata client/server version: 2.1 - Database version: mysql8 - OS(e.g. `uname -a`): - Others: -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
