[√] I have searched the issues of this repository and believe that this is not a duplicate.
Ⅰ. Issue Description
为了验证TransactionTemplate.java里红框多个操作在异常情况下的一致性:
1、第四步commitTransaction(tx);会往tc发送GlobalCommitRequest请求,在tc端返回GlobalCommitResponse之前,sleep了60s,模拟丢包的异常case;
2、运行转账场景的tcc demo,发现转账双方的账户余额被分别扣钱加钱了,说明转账成功,但是在发起方的逻辑中,得到的是一个异常,发起方无法知道当前的转账状态。
现象:
Ⅱ. Describe what happened
1、seata-server端日志:
2020-09-07 11:33:51.568 INFO --- [LoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage timeout=60000,transactionName=transfer(java.lang.String, java.lang.String, double)
,clientIp:127.0.0.1,vgroup:my_test_tx_group
2020-09-07 11:33:51.569 INFO --- [rThread_1_1_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: tcc-sample,transactionServiceGroup: my_test_tx_group, transactionName: transfer(java.lang.String, java.lang.String, double),timeout:60000,xid:192.168.20.94:8091:46197874383773696
2020-09-07 11:33:56.632 INFO --- [LoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=192.168.20.94:8091:46197874383773696,branchType=TCC,resourceId=firstTccAction,lockKey=null
,clientIp:127.0.0.1,vgroup:my_test_tx_group
2020-09-07 11:33:56.634 INFO --- [rThread_1_2_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 192.168.20.94:8091:46197874383773696, branchId = 46197895623729153, resourceId = firstTccAction ,lockKeys = null
2020-09-07 11:33:56.869 INFO --- [LoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=192.168.20.94:8091:46197874383773696,branchType=TCC,resourceId=secondTccAction,lockKey=null
,clientIp:127.0.0.1,vgroup:my_test_tx_group
2020-09-07 11:33:56.871 INFO --- [rThread_1_3_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 192.168.20.94:8091:46197874383773696, branchId = 46197896621973505, resourceId = secondTccAction ,lockKeys = null
2020-09-07 11:33:56.905 INFO --- [LoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=192.168.20.94:8091:46197874383773696,extraData=null
,clientIp:127.0.0.1,vgroup:my_test_tx_group
2020-09-07 11:33:56.946 INFO --- [rThread_1_4_500] io.seata.server.coordinator.DefaultCore : Committing global transaction is successfully done, xid = 192.168.20.94:8091:46197874383773696.
看源码可知,日志 “Committing global transaction is successfully done” 是整个事务成功提交后才会打印的。
2、发起方TransferApplication.java侧的日志:
2020-09-07 11:55:07.050 INFO --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Begin new global transaction [192.168.20.94:8091:46203224130445312]
prepareAdd account[C] amount[10.000000], dtx transaction id: 192.168.20.94:8091:46203224130445312.
transfer amount[10.0] from [A] to [C] finish.
2020-09-07 11:55:12.384 INFO --- [h_RMROLE_1_1_16] i.s.c.r.p.c.RmBranchCommitProcessor : rm client handle branch commit process:xid=192.168.20.94:8091:46203224130445312,branchId=46203245412343809,branchType=TCC,resourceId=firstTccAction,applicationData={"actionContext":{"amount":10.0,"action-start-time":1599450907062,"sys::prepare":"prepareMinus","accountNo":"A","sys::rollback":"rollback","sys::commit":"commit","host-name":"192.168.20.94","actionName":"firstTccAction"}}
2020-09-07 11:55:12.385 INFO --- [h_RMROLE_1_1_16] io.seata.rm.AbstractRMHandler : Branch committing: 192.168.20.94:8091:46203224130445312 46203245412343809 firstTccAction {"actionContext":{"amount":10.0,"action-start-time":1599450907062,"sys::prepare":"prepareMinus","accountNo":"A","sys::rollback":"rollback","sys::commit":"commit","host-name":"192.168.20.94","actionName":"firstTccAction"}}
minus account[A] amount[10.000000], dtx transaction id: 192.168.20.94:8091:46203224130445312.
2020-09-07 11:55:12.412 INFO --- [h_RMROLE_1_1_16] io.seata.rm.AbstractResourceManager : TCC resource commit result : true, xid: 192.168.20.94:8091:46203224130445312, branchId: 46203245412343809, resourceId: firstTccAction
2020-09-07 11:55:12.413 INFO --- [h_RMROLE_1_1_16] io.seata.rm.AbstractRMHandler : Branch commit result: PhaseTwo_Committed
2020-09-07 11:55:12.416 INFO --- [h_RMROLE_1_2_16] i.s.c.r.p.c.RmBranchCommitProcessor : rm client handle branch commit process:xid=192.168.20.94:8091:46203224130445312,branchId=46203246364450817,branchType=TCC,resourceId=secondTccAction,applicationData={"actionContext":{"amount":10.0,"action-start-time":1599450912346,"sys::prepare":"prepareAdd","accountNo":"C","sys::rollback":"rollback","sys::commit":"commit","host-name":"192.168.20.94","actionName":"secondTccAction"}}
2020-09-07 11:55:12.416 INFO --- [h_RMROLE_1_2_16] io.seata.rm.AbstractRMHandler : Branch committing: 192.168.20.94:8091:46203224130445312 46203246364450817 secondTccAction {"actionContext":{"amount":10.0,"action-start-time":1599450912346,"sys::prepare":"prepareAdd","accountNo":"C","sys::rollback":"rollback","sys::commit":"commit","host-name":"192.168.20.94","actionName":"secondTccAction"}}
add account[C] amount[10.000000], dtx transaction id: 192.168.20.94:8091:46203224130445312.
2020-09-07 11:55:12.420 INFO --- [h_RMROLE_1_2_16] io.seata.rm.AbstractResourceManager : TCC resource commit result : true, xid: 192.168.20.94:8091:46203224130445312, branchId: 46203246364450817, resourceId: secondTccAction
2020-09-07 11:55:12.420 INFO --- [h_RMROLE_1_2_16] io.seata.rm.AbstractRMHandler : Branch commit result: PhaseTwo_Committed
2020-09-07 11:55:22.051 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : channel [id: 0x1fc696cd, L:/127.0.0.1:52182 - R:/127.0.0.1:8091] read idle.
2020-09-07 11:55:22.052 INFO --- [ctor_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : will destroy channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 - R:/127.0.0.1:8091]
2020-09-07 11:55:22.053 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 - R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:22.054 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:22.054 INFO --- [ctor_TMROLE_1_1] i.s.c.r.netty.NettyClientChannelManager : return to pool, rm channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.054 INFO --- [ctor_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : channel valid false,channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : will destroy channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : channel inactive: [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : channel valid false,channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : will destroy channel:[id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:22.055 INFO --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient : ChannelHandlerContext(AbstractNettyRemotingClient$ClientHandler#0, [id: 0x1fc696cd, L:/127.0.0.1:52182 ! R:/127.0.0.1:8091]) will closed
2020-09-07 11:55:42.385 ERROR --- [ main] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30005 ms,ip:127.0.0.1:8091,request:xid=192.168.20.94:8091:46203224130445312,extraData=null
2020-09-07 11:55:42.386 ERROR --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global commit [192.168.20.94:8091:46203224130445312],Retry Countdown: 5, reason: RPC timeout
2020-09-07 11:55:42.386 INFO --- [Send_TMROLE_1_1] i.s.c.r.netty.NettyClientChannelManager : will connect to 127.0.0.1:8091
2020-09-07 11:55:42.386 INFO --- [Send_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : NettyPool create channel to transactionRole:TMROLE,address:127.0.0.1:8091,msg:< RegisterTMRequest{applicationId='tcc-sample', transactionServiceGroup='my_test_tx_group'} >
2020-09-07 11:55:42.389 INFO --- [Send_TMROLE_1_1] i.s.c.rpc.netty.TmNettyRemotingClient : register TM success. client version:1.3.0, server version:1.3.0,channel:[id: 0x7f797e1f, L:/127.0.0.1:52189 - R:/127.0.0.1:8091]
2020-09-07 11:55:42.389 INFO --- [Send_TMROLE_1_1] i.s.core.rpc.netty.NettyPoolableFactory : register success, cost 2 ms, version:1.3.0,role:TMROLE,channel:[id: 0x7f797e1f, L:/127.0.0.1:52189 - R:/127.0.0.1:8091]
2020-09-07 11:56:12.391 ERROR --- [ main] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30005 ms,ip:127.0.0.1:8091,request:xid=192.168.20.94:8091:46203224130445312,extraData=null
2020-09-07 11:56:12.391 ERROR --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global commit [192.168.20.94:8091:46203224130445312],Retry Countdown: 4, reason: RPC timeout
2020-09-07 11:56:12.430 INFO --- [ctor_TMROLE_1_1] i.s.c.r.p.c.ClientOnResponseProcessor : msg: 4 is not found in futures.
2020-09-07 11:56:42.396 INFO --- [ctor_TMROLE_1_1] i.s.c.r.p.c.ClientOnResponseProcessor : msg: 6 is not found in futures.
2020-09-07 11:56:42.396 ERROR --- [ main] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30005 ms,ip:127.0.0.1:8091,request:xid=192.168.20.94:8091:46203224130445312,extraData=null
2020-09-07 11:56:42.397 ERROR --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global commit [192.168.20.94:8091:46203224130445312],Retry Countdown: 3, reason: RPC timeout
2020-09-07 11:57:12.399 INFO --- [ctor_TMROLE_1_1] i.s.c.r.p.c.ClientOnResponseProcessor : msg: 11 is not found in futures.
2020-09-07 11:57:12.402 ERROR --- [ main] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30005 ms,ip:127.0.0.1:8091,request:xid=192.168.20.94:8091:46203224130445312,extraData=null
2020-09-07 11:57:12.403 ERROR --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global commit [192.168.20.94:8091:46203224130445312],Retry Countdown: 2, reason: RPC timeout
2020-09-07 11:57:42.405 INFO --- [ctor_TMROLE_1_1] i.s.c.r.p.c.ClientOnResponseProcessor : msg: 15 is not found in futures.
2020-09-07 11:57:42.406 ERROR --- [ main] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30003 ms,ip:127.0.0.1:8091,request:xid=192.168.20.94:8091:46203224130445312,extraData=null
2020-09-07 11:57:42.406 ERROR --- [ main] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global commit [192.168.20.94:8091:46203224130445312],Retry Countdown: 1, reason: RPC timeout
2020-09-07 11:57:42.411 WARN --- [ main] i.s.tm.api.DefaultFailureHandlerImpl : Failed to commit transaction[192.168.20.94:8091:46203224130445312]
==>
io.seata.core.exception.TransactionException: Failed to report global commit
at io.seata.tm.api.DefaultGlobalTransaction.commit(DefaultGlobalTransaction.java:133)
at io.seata.tm.api.TransactionalTemplate.commitTransaction(TransactionalTemplate.java:154)
at io.seata.tm.api.TransactionalTemplate.execute(TransactionalTemplate.java:114)
at io.seata.spring.annotation.GlobalTransactionalInterceptor.handleGlobalTransaction(GlobalTransactionalInterceptor.java:147)
at io.seata.spring.annotation.GlobalTransactionalInterceptor.invoke(GlobalTransactionalInterceptor.java:122)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
at io.seata.samples.tcc.transfer.activity.impl.TransferServiceImpl$$EnhancerBySpringCGLIB$$1a03b491.transfer()
at io.seata.samples.tcc.transfer.starter.TransferApplication.doTransfer(TransferApplication.java:99)
at io.seata.samples.tcc.transfer.starter.TransferApplication.doTransferSuccess(TransferApplication.java:63)
at io.seata.samples.tcc.transfer.starter.TransferApplication.main(TransferApplication.java:49)
Caused by: io.seata.core.exception.TmTransactionException: RPC timeout
at io.seata.tm.DefaultTransactionManager.syncCall(DefaultTransactionManager.java:97)
at io.seata.tm.DefaultTransactionManager.commit(DefaultTransactionManager.java:64)
at io.seata.tm.api.DefaultGlobalTransaction.commit(DefaultGlobalTransaction.java:127)
... 11 common frames omitted
Caused by: java.util.concurrent.TimeoutException: cost 30003 ms
at io.seata.core.protocol.MessageFuture.get(MessageFuture.java:62)
at io.seata.core.rpc.netty.AbstractNettyRemotingClient.sendSyncRequest(AbstractNettyRemotingClient.java:165)
at io.seata.tm.DefaultTransactionManager.syncCall(DefaultTransactionManager.java:95)
... 13 common frames omitted
<==
日志 “Branch commit result: PhaseTwo_Committed” 也说明所有的2个分支事务是正常提交的状态。
Ⅲ. Describe what you expected to happen
出现异常的情况下,发起方能知道事务的状态。
Ⅳ. How to reproduce it (as minimally and precisely as possible)
xxx
xxx
xxx
Ⅴ. Anything else we need to know?
Ⅵ. Environment:
JDK version : 1.8
OS : Mac OS
Others: