java事物 commit失败,BUG - TCC 二阶段 commit 超时异常,发起方无法感知事务状态

[√] I have searched the issues of this repository and believe that this is not a duplicate.

Ⅰ. Issue Description

b7feee8c52af6768af9759d9d12c2697.png

为了验证TransactionTemplate.java里红框多个操作在异常情况下的一致性:

1、第四步commitTransaction(tx);会往tc发送GlobalCommitRequest请求,在tc端返回GlobalCommitResponse之前,sleep了60s,模拟丢包的异常case;

9eb1ebe7cfd16517b638b314dc04dd39.png

2、运行转账场景的tcc demo,发现转账双方的账户余额被分别扣钱加钱了,说明转账成功,但是在发起方的逻辑中,得到的是一个异常,发起方无法知道当前的转账状态。

7c57d7374c6f36b37c963960c3b0283c.png

现象:

Ⅱ. 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:

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值