Ⅰ. Issue Description 使用seata AT模式 seata-server.1.6.0 k8s集群环境 三个pod节点、 seata-client.1.6.0 k8s集群环境,三个pod节点, jdk1.8 mysql数据库
下面场景是偶发现象:
全局事务client端经历begin、commit、suspend三个阶段,但是在commit方法中commit status: Begin,。 client三个阶段日志如下:
2023-07-07 14:51:38.288 [XNIO-1 task-12] INFO i.s.tm.api.DefaultGlobalTransaction [begin][118] - Begin new global transaction [200.63.224.30:8091:2558447867817438215]
2023-07-07 14:51:40.762 [XNIO-1 task-12] INFO i.s.tm.api.DefaultGlobalTransaction [commit][153] - [200.63.224.30:8091:2558447867817438215] commit status: Begin
2023-07-07 14:51:40.762 [XNIO-1 task-12] INFO i.s.tm.api.DefaultGlobalTransaction [suspend][199] - Suspending current transaction, xid = 200.63.224.30:8091:2558447867817438215
DefaultGlobalTransaction.commit()方法如下: 从commit()方法实现可以看出commit status: 日志输出应该是除Begin以外的状态才是正常的。
server日志:
2023-07-07 14:51:38.287 INFO --- [verHandlerThread_1_29_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: goldnet-enterprise-client,transactionServiceGroup: my_prod_tx_group, transactionName: open(com.goldnet.opencirculation.dto.ClaimsOpenCirculationDTO),timeout:120000,xid:200.63.224.30:8091:2558447867817438215
2023-07-07 14:51:38.533 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,branchType=AT,resourceId=jdbc:mysql://:3306/goldnet_account,lockKey=goldnet_req_token:1_BZ58GH202307070010001;goldnet_credit_account:e2ecde31-4ec5-411a-9444-ecf5b45ee9d3;goldnet_credit_log:96882,clientIp:200.122.43.106,vgroup:my_prod_tx_group
2023-07-07 14:51:38.538 INFO --- [rverHandlerThread_1_5_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 200.63.224.30:8091:2558447867817438215, branchId = 9214768116882458759, resourceId = jdbc:mysql://:3306/goldnet_account ,lockKeys = goldnet_req_token:1_BZ58GH202307070010001;goldnet_credit_account:e2ecde31-4ec5-411a-9444-ecf5b45ee9d3;goldnet_credit_log:96882
2023-07-07 14:51:38.590 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,branchType=AT,resourceId=jdbc:mysql://:3306/goldnet_flow_design,lockKey=ACT_RU_IDENTITYLINK:b8c141b5-1c92-11ee-bb3e-0e285e0eabce,b8c141c6-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c2-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c4-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_TASK:b8c141c5-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c4-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c2-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_EXECUTION:b8c141b4-1c92-11ee-bb3e-0e285e0eabce;ACT_GE_BYTEARRAY:b8c141b9-1c92-11ee-bb3e-0e285e0eabce,b8c141bb-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c3-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_VARIABLE:b8c623c7-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_PROCINST:b8c141b4-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_VARINST:b8c141b6-1c92-11ee-bb3e-0e285e0eabce,b8c141b7-1c92-11ee-bb3e-0e285e0eabce,b8c141b8-1c92-11ee-bb3e-0e285e0eabce,b8c141ba-1c92-11ee-bb3e-0e285e0eabce,b8c141bc-1c92-11ee-bb3e-0e285e0eabce,b8c141bd-1c92-11ee-bb3e-0e285e0eabce,b8c141be-1c92-11ee-bb3e-0e285e0eabce,b8c141bf-1c92-11ee-bb3e-0e285e0eabce,b8c141c0-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c3-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_EXECUTION:b8c141c1-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_TASKINST:b8c141c5-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_IDENTITYLINK:b8c141b5-1c92-11ee-bb3e-0e285e0eabce,b8c141c6-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_VARIABLE:b8c141b6-1c92-11ee-bb3e-0e285e0eabce,b8c141b7-1c92-11ee-bb3e-0e285e0eabce,b8c141b8-1c92-11ee-bb3e-0e285e0eabce,b8c141ba-1c92-11ee-bb3e-0e285e0eabce,b8c141bc-1c92-11ee-bb3e-0e285e0eabce,b8c141bd-1c92-11ee-bb3e-0e285e0eabce,b8c141be-1c92-11ee-bb3e-0e285e0eabce,b8c141bf-1c92-11ee-bb3e-0e285e0eabce,b8c141c0-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_VARINST:b8c623c7-1c92-11ee-bb3e-0e285e0eabce,clientIp:200.131.174.104,vgroup:my_prod_tx_group
2023-07-07 14:51:38.604 INFO --- [verHandlerThread_1_41_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 200.63.224.30:8091:2558447867817438215, branchId = 9214768116882458761, resourceId = jdbc:mysql://:3306/goldnet_flow_design ,lockKeys = ACT_RU_IDENTITYLINK:b8c141b5-1c92-11ee-bb3e-0e285e0eabce,b8c141c6-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c2-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c4-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_TASK:b8c141c5-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c4-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c2-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_EXECUTION:b8c141b4-1c92-11ee-bb3e-0e285e0eabce;ACT_GE_BYTEARRAY:b8c141b9-1c92-11ee-bb3e-0e285e0eabce,b8c141bb-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_ACTINST:b8c141c3-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_VARIABLE:b8c623c7-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_PROCINST:b8c141b4-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_VARINST:b8c141b6-1c92-11ee-bb3e-0e285e0eabce,b8c141b7-1c92-11ee-bb3e-0e285e0eabce,b8c141b8-1c92-11ee-bb3e-0e285e0eabce,b8c141ba-1c92-11ee-bb3e-0e285e0eabce,b8c141bc-1c92-11ee-bb3e-0e285e0eabce,b8c141bd-1c92-11ee-bb3e-0e285e0eabce,b8c141be-1c92-11ee-bb3e-0e285e0eabce,b8c141bf-1c92-11ee-bb3e-0e285e0eabce,b8c141c0-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_ACTINST:b8c141c3-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_EXECUTION:b8c141c1-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_TASKINST:b8c141c5-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_IDENTITYLINK:b8c141b5-1c92-11ee-bb3e-0e285e0eabce,b8c141c6-1c92-11ee-bb3e-0e285e0eabce;ACT_RU_VARIABLE:b8c141b6-1c92-11ee-bb3e-0e285e0eabce,b8c141b7-1c92-11ee-bb3e-0e285e0eabce,b8c141b8-1c92-11ee-bb3e-0e285e0eabce,b8c141ba-1c92-11ee-bb3e-0e285e0eabce,b8c141bc-1c92-11ee-bb3e-0e285e0eabce,b8c141bd-1c92-11ee-bb3e-0e285e0eabce,b8c141be-1c92-11ee-bb3e-0e285e0eabce,b8c141bf-1c92-11ee-bb3e-0e285e0eabce,b8c141c0-1c92-11ee-bb3e-0e285e0eabce;ACT_HI_VARINST:b8c623c7-1c92-11ee-bb3e-0e285e0eabce
2023-07-07 14:51:40.212 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,branchType=AT,resourceId=jdbc:mysql://:3306/goldnet_msg_center,lockKey=goldnet_msg_callback_parameter:1439694,clientIp:200.16.141.112,vgroup:my_prod_tx_group
2023-07-07 14:51:40.216 INFO --- [verHandlerThread_1_46_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 200.63.224.30:8091:2558447867817438215, branchId = 2558447867817438246, resourceId = jdbc:mysql://:3306/goldnet_msg_center ,lockKeys = goldnet_msg_callback_parameter:1439694
2023-07-07 14:51:40.720 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,branchType=AT,resourceId=jdbc:mysql://:3306/goldnet_statement,lockKey=goldnet_claims_contract_signing:1677208745919307777,clientIp:200.170.145.89,vgroup:my_prod_tx_group
2023-07-07 14:51:40.724 INFO --- [verHandlerThread_1_34_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 200.63.224.30:8091:2558447867817438215, branchId = 9214768116882458794, resourceId = jdbc:mysql://:3306/goldnet_statement ,lockKeys = goldnet_claims_contract_signing:1677208745919307777
2023-07-07 14:51:40.742 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,branchType=AT,resourceId=jdbc:mysql://:3306/goldnet_claims,lockKey=goldnet_claims_log:1278605;goldnet_claims:1677208736618225666;goldnet_claims_extend:488250,clientIp:200.134.66.17,vgroup:my_prod_tx_group
2023-07-07 14:51:40.749 INFO --- [verHandlerThread_1_26_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 200.63.224.30:8091:2558447867817438215, branchId = 2558447867817438248, resourceId = jdbc:mysql://:3306/goldnet_claims ,lockKeys = goldnet_claims_log:1278605;goldnet_claims:1677208736618225666;goldnet_claims_extend:488250
2023-07-07 14:51:40.754 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : xid=200.63.224.30:8091:2558447867817438215,extraData=null,clientIp:200.171.13.174,vgroup:my_prod_tx_group
2023-07-07 14:51:40.760 ERROR --- [verHandlerThread_1_18_500] i.seata.server.lock.AbstractLockManager : unLock globalSession error, xid:200.63.224.30:8091:2558447867817438215 ==> io.seata.common.exception.StoreException: Deadlock found when trying to get lock; try restarting transaction at io.seata.server.storage.db.lock.LockStoreDataBaseDAO.unLock(LockStoreDataBaseDAO.java:256) at io.seata.server.storage.db.lock.DataBaseLocker.releaseLock(DataBaseLocker.java:104) at io.seata.server.storage.db.lock.DataBaseLockManager.releaseGlobalSessionLock(DataBaseLockManager.java:70) at io.seata.server.session.GlobalSession.clean(GlobalSession.java:258) at io.seata.server.session.GlobalSession.closeAndClean(GlobalSession.java:271) at io.seata.server.coordinator.DefaultCore.lambda$commit$0(DefaultCore.java:166) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:366) at io.seata.server.coordinator.DefaultCore.commit(DefaultCore.java:163) at io.seata.server.coordinator.DefaultCoordinator.doGlobalCommit(DefaultCoordinator.java:257) at io.seata.server.AbstractTCInboundHandler$2.execute(AbstractTCInboundHandler.java:95) at io.seata.server.AbstractTCInboundHandler$2.execute(AbstractTCInboundHandler.java:90) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:90) at io.seata.core.protocol.transaction.GlobalCommitRequest.handle(GlobalCommitRequest.java:34) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:521) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:213) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.process(ServerOnRequestProcessor.java:123) at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:281) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123) at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1098) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1046) at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1371) at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1031) at com.alibaba.druid.pool.DruidPooledPreparedStatement.executeUpdate(DruidPooledPreparedStatement.java:255) at io.seata.server.storage.db.lock.LockStoreDataBaseDAO.unLock(LockStoreDataBaseDAO.java:254) ... 22 common frames omitted <==
2023-07-07 14:51:40.760 ERROR --- [verHandlerThread_1_18_500] i.s.c.e.AbstractExceptionHandler : Catch TransactionException while do RPC, request: xid=200.63.224.30:8091:2558447867817438215,extraData=null ==> io.seata.core.exception.TransactionException: UnLock globalSession error, xid = 200.63.224.30:8091:2558447867817438215 at io.seata.server.session.GlobalSession.clean(GlobalSession.java:259) at io.seata.server.session.GlobalSession.closeAndClean(GlobalSession.java:271) at io.seata.server.coordinator.DefaultCore.lambda$commit$0(DefaultCore.java:166) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:366) at io.seata.server.coordinator.DefaultCore.commit(DefaultCore.java:163) at io.seata.server.coordinator.DefaultCoordinator.doGlobalCommit(DefaultCoordinator.java:257) at io.seata.server.AbstractTCInboundHandler$2.execute(AbstractTCInboundHandler.java:95) at io.seata.server.AbstractTCInboundHandler$2.execute(AbstractTCInboundHandler.java:90) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:90) at io.seata.core.protocol.transaction.GlobalCommitRequest.handle(GlobalCommitRequest.java:34) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:521) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:213) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.process(ServerOnRequestProcessor.java:123) at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:281) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) <==
2023-07-07 14:53:38.610 INFO --- [ TxTimeoutCheck_1_1] i.s.s.coordinator.DefaultCoordinator : Global transaction[200.63.224.30:8091:2558447867817438215] is timeout and will be rollback.
2023-07-07 14:53:39.612 INFO --- [ RetryRollbacking_1_1] io.seata.server.coordinator.DefaultCore : Rollback branch transaction successfully, xid = 200.63.224.30:8091:2558447867817438215 branchId = 2558447867817438248
2023-07-07 14:53:39.615 INFO --- [ RetryRollbacking_1_1] io.seata.server.coordinator.DefaultCore : Rollback branch transaction successfully, xid = 200.63.224.30:8091:2558447867817438215 branchId = 9214768116882458794