Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FailureHandler重写无法实现回滚失败处理 #5231

Open
1 task
AHangC opened this issue Jan 5, 2023 · 18 comments
Open
1 task

FailureHandler重写无法实现回滚失败处理 #5231

AHangC opened this issue Jan 5, 2023 · 18 comments
Assignees
Labels
task: help-wanted Extra attention is needed type: bug Category issues or prs related to bug.

Comments

@AHangC
Copy link

AHangC commented Jan 5, 2023

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

Ⅰ. Issue Description

单机模拟镜像不一致导致回滚失败处理问题。TM端捕获的异常是feign远程调用出的错(不过不就是分支事务处理失败所以触发回滚吗),导致捕获的异常状态始终是 RollbackDone就结束了,不会走自实现的FailureHandler。此外好奇的是分支事务的处理不是直接响应给TC吗?

Ⅱ. Describe what happened

If there is an exception, please attach the exception trace:

Just paste your stack trace here!

Ⅲ. Describe what you expected to happen

Ⅳ. How to reproduce it (as minimally and precisely as possible)

  1. xxx
  2. xxx
  3. xxx

Ⅴ. Anything else we need to know?

Ⅵ. Environment:

  • JDK version : 11
  • Seata version: 1.6.0
  • OS : Win10
  • Others:
@funky-eyes
Copy link
Contributor

tc tm rm日志放上来

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

tm:

2023-01-05 14:58:19.706  INFO 21900 --- [nio-7100-exec-7] i.s.c.rpc.netty.TmNettyRemotingClient    : register TM success. client version:1.6.0, server version:1.6.0,channel:[id: 0x5b03a2fe, L:/192.168.2.59:55268 - R:/192.168.2.59:8091]
2023-01-05 14:58:19.706  INFO 21900 --- [nio-7100-exec-7] i.s.core.rpc.netty.NettyPoolableFactory  : register success, cost 3 ms, version:1.6.0,role:TMROLE,channel:[id: 0x5b03a2fe, L:/192.168.2.59:55268 - R:/192.168.2.59:8091]
2023-01-05 14:58:19.774  INFO 21900 --- [nio-7100-exec-7] i.seata.tm.api.DefaultGlobalTransaction  : Suspending current transaction, xid = 192.168.2.59:8091:1783771114275155996
2023-01-05 14:58:19.774  INFO 21900 --- [nio-7100-exec-7] i.seata.tm.api.DefaultGlobalTransaction  : [192.168.2.59:8091:1783771114275155996] rollback status: Rollbacked
2023-01-05 14:58:19.785 ERROR 21900 --- [nio-7100-exec-7] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is feign.FeignException$InternalServerError: [500] during [GET] to [http://at-account/account/debit?userId=1&money=1000] [AccountFeignService#debit(String,int)]: [{"timestamp":"2023-01-05T06:58:19.690+00:00","status":500,"error":"Internal Server Error","message":"","path":"/account/debit"}]] with root cause

feign.FeignException$InternalServerError: [500] during [GET] to [http://at-account/account/debit?userId=1&money=1000] [AccountFeignService#debit(String,int)]: [{"timestamp":"2023-01-05T06:58:19.690+00:00","status":500,"error":"Internal Server Error","message":"","path":"/account/debit"}]
	at feign.FeignException.serverErrorStatus(FeignException.java:231) ~[feign-core-10.12.jar:na]
	at feign.FeignException.errorStatus(FeignException.java:180) ~[feign-core-10.12.jar:na]

RM:

2023-01-05 14:58:19.681 ERROR 25540 --- [nio-7200-exec-6] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: 余额不足] with root cause

java.lang.RuntimeException: 余额不足
	at cn.zh.account.service.impl.AccountServiceImpl.checkBalance(AccountServiceImpl.java:54) ~[classes/:na]
	at cn.zh.account.service.impl.AccountServiceImpl.debit(AccountServiceImpl.java:36) ~[classes/:na]

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

2023-01-05 14:58:19.751  INFO 13156 --- [h_RMROLE_1_7_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacking: 192.168.2.59:8091:1783771114275155996 1783771114275155998 jdbc:mysql://localhost:3306/seata-client
2023-01-05 14:58:19.767  INFO 13156 --- [h_RMROLE_1_7_24] i.s.r.d.undo.AbstractUndoLogManager      : xid 192.168.2.59:8091:1783771114275155996 branch 1783771114275155998, undo_log deleted with GlobalFinished
2023-01-05 14:58:19.767  INFO 13156 --- [h_RMROLE_1_7_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_Rollbacked
2023-01-05 15:00:10.419 ERROR 13156 --- [ctor_TMROLE_1_1] i.s.c.r.n.AbstractNettyRemotingClient    : 0318

@funky-eyes
Copy link
Contributor

你说的单机模拟镜像不一致导致回滚失败处理问题的日志在哪?rm回滚的好好的,哪来的脏写?回滚没失败不就是PhaseTwo_Rollbacked吗?

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

抱歉,发错了

RM:

[stacktrace]branchRollback failed. branchType:[AT], xid:[192.168.2.59:8091:8647257261886419694], branchId:[8647257261886419699], resourceId:[jdbc:mysql://localhost:3306/seata-client], applicationData:[null]. reason:[Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 192.168.2.59:8091:8647257261886419694 branchId = 8647257261886419699]

io.seata.core.exception.BranchTransactionException: Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 192.168.2.59:8091:8647257261886419694 branchId = 8647257261886419699
	at io.seata.rm.datasource.undo.AbstractUndoLogManager.undo(AbstractUndoLogManager.java:363) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.datasource.DataSourceManager.branchRollback(DataSourceManager.java:122) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:125) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:67) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:63) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.AbstractRMHandler.handle(AbstractRMHandler.java:63) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.DefaultRMHandler.handle(DefaultRMHandler.java:68) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.core.protocol.transaction.BranchRollbackRequest.handle(BranchRollbackRequest.java:35) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.AbstractRMHandler.onRequest(AbstractRMHandler.java:150) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.handleBranchRollback(RmBranchRollbackProcessor.java:63) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:58) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:281) ~[seata-all-1.6.0.jar:1.6.0]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-all-4.1.65.Final.jar:4.1.65.Final]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: io.seata.rm.datasource.undo.SQLUndoDirtyException: Has dirty records when undo.
	at io.seata.rm.datasource.undo.AbstractUndoExecutor.dataValidationAndGoOn(AbstractUndoExecutor.java:276) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.datasource.undo.AbstractUndoExecutor.executeOn(AbstractUndoExecutor.java:117) ~[seata-all-1.6.0.jar:1.6.0]
	at io.seata.rm.datasource.undo.AbstractUndoLogManager.undo(AbstractUndoLogManager.java:315) ~[seata-all-1.6.0.jar:1.6.0]
	... 16 common frames omitted

2023-01-05 15:43:32.530  INFO 21952 --- [h_RMROLE_1_7_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_RollbackFailed_Unretryable

@funky-eyes
Copy link
Contributor

那你把对应的15:43:32秒左右的tm,tc日志再发出来,把你的failurehandler的代码也发一下,你可以每个通知都打一行日志,看下到底进了是什么状态

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

那你把对应的15:43:32秒左右的tm,tc日志再发出来,把你的failurehandler的代码也发一下,你可以每个通知都打一行日志,看下到底进了是什么状态

我发个完整的
TM:本地的RM正常回滚

2023-01-05 17:40:34.818  INFO 7312 --- [nio-7100-exec-5] i.s.core.rpc.netty.NettyPoolableFactory  : register success, cost 3 ms, version:1.6.0,role:TMROLE,channel:[id: 0xb6862871, L:/192.168.2.59:51928 - R:/192.168.2.59:8091]
2023-01-05 17:40:34.828  INFO 7312 --- [h_RMROLE_1_5_24] i.s.c.r.p.c.RmBranchRollbackProcessor    : rm handle branch rollback process:xid=192.168.2.59:8091:6782767034448904884,branchId=6782767034448904892,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_order,applicationData=null
2023-01-05 17:40:34.828  INFO 7312 --- [h_RMROLE_1_5_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacking: 192.168.2.59:8091:6782767034448904884 6782767034448904892 jdbc:mysql://localhost:3306/seata_order
2023-01-05 17:40:34.836  INFO 7312 --- [h_RMROLE_1_5_24] i.s.r.d.undo.AbstractUndoLogManager      : xid 192.168.2.59:8091:6782767034448904884 branch 6782767034448904892, undo_log deleted with GlobalFinished
2023-01-05 17:40:34.837  INFO 7312 --- [h_RMROLE_1_5_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_Rollbacked
2023-01-05 17:40:34.866  INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction  : Suspending current transaction, xid = 192.168.2.59:8091:6782767034448904884
2023-01-05 17:40:34.866  INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction  : [192.168.2.59:8091:6782767034448904884] rollback status: RollbackFailed
2023-01-05 17:40:34.867 ERROR 7312 --- [nio-7100-exec-5] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: 发生了异常,分布式事物需要会滚] with root cause

java.lang.RuntimeException: 发生了异常,分布式事物需要会滚
	at cn.zh.order.service.impl.OrderServiceImpl.saveOrder(OrderServiceImpl.java:67) ~[classes/:na]
	....

这个就是进入的状态RollbackDone,然后直接抛出异常信息,不会走failureHandler

RM1:正常回滚

2023-01-05 17:40:34.841  INFO 22992 --- [h_RMROLE_1_3_24] i.s.c.r.p.c.RmBranchRollbackProcessor    : rm handle branch rollback process:xid=192.168.2.59:8091:6782767034448904884,branchId=6782767034448904890,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_account,applicationData={"autoCommit":false}
2023-01-05 17:40:34.842  INFO 22992 --- [h_RMROLE_1_3_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacking: 192.168.2.59:8091:6782767034448904884 6782767034448904890 jdbc:mysql://localhost:3306/seata_account
2023-01-05 17:40:34.849  INFO 22992 --- [h_RMROLE_1_3_24] i.s.r.d.undo.AbstractUndoLogManager      : xid 192.168.2.59:8091:6782767034448904884 branch 6782767034448904890, undo_log deleted with GlobalFinished
2023-01-05 17:40:34.849  INFO 22992 --- [h_RMROLE_1_3_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_Rollbacked

RM2:镜像不一致,回滚失败

2023-01-05 17:40:34.853  INFO 632 --- [h_RMROLE_1_3_24] i.s.c.r.p.c.RmBranchRollbackProcessor    : rm handle branch rollback process:xid=192.168.2.59:8091:6782767034448904884,branchId=6782767034448904888,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_client,applicationData=null
2023-01-05 17:40:34.854  INFO 632 --- [h_RMROLE_1_3_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacking: 192.168.2.59:8091:6782767034448904884 6782767034448904888 jdbc:mysql://localhost:3306/seata_client
2023-01-05 17:40:34.857  INFO 632 --- [h_RMROLE_1_3_24] i.s.r.d.undo.AbstractUndoExecutor        : Field not equals, name count, old value 78, new value 120
2023-01-05 17:40:34.862  INFO 632 --- [h_RMROLE_1_3_24] i.seata.rm.datasource.DataSourceManager  : branchRollback failed. branchType:[AT], xid:[192.168.2.59:8091:6782767034448904884], branchId:[6782767034448904888], resourceId:[jdbc:mysql://localhost:3306/seata_client], applicationData:[null]. reason:[Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 192.168.2.59:8091:6782767034448904884 branchId = 6782767034448904888]
2023-01-05 17:40:34.862  INFO 632 --- [h_RMROLE_1_3_24] io.seata.rm.AbstractRMHandler            : Branch Rollbacked result: PhaseTwo_RollbackFailed_Unretryable

TC:

2023-01-05 17:39:56.955  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : timeout=60000,transactionName=createOrder,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:39:56.959  INFO --- [  ServerHandlerThread_1_46_500] i.s.s.coordinator.DefaultCoordinator     : Begin new global transaction applicationId: at-order,transactionServiceGroup: default_tx_group, transactionName: createOrder,timeout:60000,xid:192.168.2.59:8091:6782767034448904884
2023-01-05 17:39:56.969  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : SeataMergeMessage xid=192.168.2.59:8091:6782767034448904884,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_order,lockKey=t_order:10
,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:39:56.972  INFO --- [  ServerHandlerThread_1_47_500] i.seata.server.coordinator.AbstractCore  : Register branch successfully, xid = 192.168.2.59:8091:6782767034448904884, branchId = 6782767034448904886, resourceId = jdbc:mysql://localhost:3306/seata_order ,lockKeys = t_order:10
2023-01-05 17:39:56.989  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : SeataMergeMessage xid=192.168.2.59:8091:6782767034448904884,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_client,lockKey=storage:1
,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:39:56.994  INFO --- [  ServerHandlerThread_1_48_500] i.seata.server.coordinator.AbstractCore  : Register branch successfully, xid = 192.168.2.59:8091:6782767034448904884, branchId = 6782767034448904888, resourceId = jdbc:mysql://localhost:3306/seata_client ,lockKeys = storage:1
2023-01-05 17:39:57.017  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : SeataMergeMessage xid=192.168.2.59:8091:6782767034448904884,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_account,lockKey=account:1
,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:39:57.020  INFO --- [  ServerHandlerThread_1_49_500] i.seata.server.coordinator.AbstractCore  : Register branch successfully, xid = 192.168.2.59:8091:6782767034448904884, branchId = 6782767034448904890, resourceId = jdbc:mysql://localhost:3306/seata_account ,lockKeys = account:1
2023-01-05 17:39:57.032  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : SeataMergeMessage xid=192.168.2.59:8091:6782767034448904884,branchType=AT,resourceId=jdbc:mysql://localhost:3306/seata_order,lockKey=t_order:10
,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:39:57.035  INFO --- [  ServerHandlerThread_1_50_500] i.seata.server.coordinator.AbstractCore  : Register branch successfully, xid = 192.168.2.59:8091:6782767034448904884, branchId = 6782767034448904892, resourceId = jdbc:mysql://localhost:3306/seata_order ,lockKeys = t_order:10
2023-01-05 17:40:11.966  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : channel:[id: 0x24d09c3a, L:/192.168.2.59:8091 - R:/192.168.2.59:51631] read idle.
2023-01-05 17:40:11.966  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : 192.168.2.59:51631 to server channel inactive.
2023-01-05 17:40:11.967  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : remove channel:[id: 0x24d09c3a, L:/192.168.2.59:8091 - R:/192.168.2.59:51631]context:RpcContext{applicationId='at-order', transactionServiceGroup='default_tx_group', clientId='at-order:192.168.2.59:51631', channel=[id: 0x24d09c3a, L:/192.168.2.59:8091 - R:/192.168.2.59:51631], resourceSets=null}
2023-01-05 17:40:11.969  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : closeChannelHandlerContext channel:[id: 0x24d09c3a, L:/192.168.2.59:8091 - R:/192.168.2.59:51631]
2023-01-05 17:40:11.969  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : 192.168.2.59:51631 to server channel inactive.
2023-01-05 17:40:11.970  INFO --- [  NettyServerNIOWorker_1_18_24] i.s.c.r.n.AbstractNettyRemotingServer    : remove channel:[id: 0x24d09c3a, L:/192.168.2.59:8091 ! R:/192.168.2.59:51631]context:RpcContext{applicationId='at-order', transactionServiceGroup='default_tx_group', clientId='at-order:192.168.2.59:51631', channel=[id: 0x24d09c3a, L:/192.168.2.59:8091 ! R:/192.168.2.59:51631], resourceSets=null}
2023-01-05 17:40:12.043  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : channel:[id: 0x05295cca, L:/192.168.2.59:8091 - R:/192.168.2.59:51635] read idle.
2023-01-05 17:40:12.043  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : 192.168.2.59:51635 to server channel inactive.
2023-01-05 17:40:12.045  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : remove channel:[id: 0x05295cca, L:/192.168.2.59:8091 - R:/192.168.2.59:51635]context:RpcContext{applicationId='at-order', transactionServiceGroup='default_tx_group', clientId='at-order:192.168.2.59:51635', channel=[id: 0x05295cca, L:/192.168.2.59:8091 - R:/192.168.2.59:51635], resourceSets=[]}
2023-01-05 17:40:12.046  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : closeChannelHandlerContext channel:[id: 0x05295cca, L:/192.168.2.59:8091 - R:/192.168.2.59:51635]
2023-01-05 17:40:12.046  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : 192.168.2.59:51635 to server channel inactive.
2023-01-05 17:40:12.047  INFO --- [  NettyServerNIOWorker_1_19_24] i.s.c.r.n.AbstractNettyRemotingServer    : remove channel:[id: 0x05295cca, L:/192.168.2.59:8091 ! R:/192.168.2.59:51635]context:RpcContext{applicationId='at-order', transactionServiceGroup='default_tx_group', clientId='at-order:192.168.2.59:51635', channel=[id: 0x05295cca, L:/192.168.2.59:8091 ! R:/192.168.2.59:51635], resourceSets=[]}
2023-01-05 17:40:19.228  INFO --- [   ServerHandlerThread_1_1_500] i.s.c.r.processor.server.RegRmProcessor  : RM register success,message:RegisterRMRequest{resourceIds='jdbc:mysql://localhost:3306/seata_order', applicationId='at-order', transactionServiceGroup='default_tx_group'},channel:[id: 0xc78ce292, L:/192.168.2.59:8091 - R:/192.168.2.59:51910],client version:1.6.0
2023-01-05 17:40:34.817  INFO --- [  NettyServerNIOWorker_1_23_24] i.s.c.r.processor.server.RegTmProcessor  : TM register success,message:RegisterTMRequest{applicationId='at-order', transactionServiceGroup='default_tx_group'},channel:[id: 0x122ff7f0, L:/192.168.2.59:8091 - R:/192.168.2.59:51928],client version:1.6.0
2023-01-05 17:40:34.820  INFO --- [          batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler         : xid=192.168.2.59:8091:6782767034448904884,extraData=null,clientIp:192.168.2.59,vgroup:default_tx_group
2023-01-05 17:40:34.825  INFO --- [   ServerHandlerThread_1_2_500] io.seata.core.rpc.netty.ChannelManager   : Choose [id: 0xc78ce292, L:/192.168.2.59:8091 - R:/192.168.2.59:51910] on the same IP[192.168.2.59] as alternative of at-order:192.168.2.59:51635
2023-01-05 17:40:34.840  INFO --- [   ServerHandlerThread_1_2_500] io.seata.server.coordinator.DefaultCore  : Rollback branch transaction successfully, xid = 192.168.2.59:8091:6782767034448904884 branchId = 6782767034448904892
2023-01-05 17:40:34.852  INFO --- [   ServerHandlerThread_1_2_500] io.seata.server.coordinator.DefaultCore  : Rollback branch transaction successfully, xid = 192.168.2.59:8091:6782767034448904884 branchId = 6782767034448904890
2023-01-05 17:40:34.864 ERROR --- [   ServerHandlerThread_1_2_500] io.seata.server.session.SessionHelper    : The Global session 192.168.2.59:8091:6782767034448904884 has changed the status to RollbackFailed, need to be handled it manually.
2023-01-05 17:40:34.865  INFO --- [   ServerHandlerThread_1_2_500] i.s.s.session.AbstractSessionManager     : xid:192.168.2.59:8091:6782767034448904884 fail end, transaction:GlobalSession{xid='192.168.2.59:8091:6782767034448904884', transactionId=6782767034448904884, status=RollbackFailed, applicationId='at-order', transactionServiceGroup='default_tx_group', transactionName='createOrder', timeout=60000, beginTime=1672911596956, applicationData='null', lazyLoadBranch=false, active=false, branchSessions=[BR:6782767034448904886/6782767034448904884, BR:6782767034448904888/6782767034448904884], globalSessionLock=io.seata.server.session.GlobalSession$GlobalSessionLock@6d6d7a53, lifecycleListeners=[io.seata.server.storage.db.session.DataBaseSessionManager@e101dd3]}
2023-01-05 17:40:34.865  INFO --- [   ServerHandlerThread_1_2_500] io.seata.server.coordinator.DefaultCore  : Rollback branch transaction fail and stop retry, xid = 192.168.2.59:8091:6782767034448904884 branchId = 6782767034448904888

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

FailureHandler代码:

@Configuration
@Slf4j
public class SeataFailureHandlerConfig {

    @Bean
    public FailureHandler failureHandler(){
        return new EmailSeataFailureHandler();
    }

    class EmailSeataFailureHandler extends DefaultFailureHandlerImpl {

        @Override
        public void onBeginFailure(GlobalTransaction tx, Throwable cause) {
            super.onBeginFailure(tx, cause);
            log.warn("邮件通知:分布式事物出现异常:[onBeginFailure],xid:[{}]", tx.getXid());
        }

        @Override
        public void onCommitFailure(GlobalTransaction tx, Throwable cause) {
            super.onCommitFailure(tx, cause);
            log.warn("邮件通知:分布式事物出现异常:[onCommitFailure],xid:[{}]", tx.getXid());
        }

        @Override
        public void onRollbackFailure(GlobalTransaction tx, Throwable originalException) {
            super.onRollbackFailure(tx, originalException);
            log.warn("邮件通知:分布式事物出现异常:[onRollbackFailure],xid:[{}]", tx.getXid());
        }
    ...
    }

@funky-eyes
Copy link
Contributor

已经有
2023-01-05 17:40:34.866 INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction : [192.168.2.59:8091:6782767034448904884] rollback status: RollbackFailed
的日志了,建议你debug GlobalTransactionalInterceptor的} catch (TransactionalExecutor.ExecutionException e) { 这行代码下面是怎么走的

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

已经有 2023-01-05 17:40:34.866 INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction : [192.168.2.59:8091:6782767034448904884] rollback status: RollbackFailed 的日志了,建议你debug GlobalTransactionalInterceptor的} catch (TransactionalExecutor.ExecutionException e) { 这行代码下面是怎么走的

image

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

已经有 2023-01-05 17:40:34.866 INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction : [192.168.2.59:8091:6782767034448904884] rollback status: RollbackFailed 的日志了,建议你debug GlobalTransactionalInterceptor的} catch (TransactionalExecutor.ExecutionException e) { 这行代码下面是怎么走的
image

@funky-eyes
Copy link
Contributor

已经有 2023-01-05 17:40:34.866 INFO 7312 --- [nio-7100-exec-5] i.seata.tm.api.DefaultGlobalTransaction : [192.168.2.59:8091:6782767034448904884] rollback status: RollbackFailed 的日志了,建议你debug GlobalTransactionalInterceptor的} catch (TransactionalExecutor.ExecutionException e) { 这行代码下面是怎么走的

image

我们看下这个问题

@funky-eyes
Copy link
Contributor

已确认问题存在,由于社区内部会议,讨论后认为脏数据不可能自动成功回滚,应该标记为failed人工介入处理,就改成failed了,而client侧忘记修改,只匹配了RollbackRetrying状态,所以走了done了

@funky-eyes funky-eyes added the task: help-wanted Extra attention is needed label Jan 5, 2023
@funky-eyes
Copy link
Contributor

funky-eyes commented Jan 5, 2023

问题涉及版本1.5-1.6.1

@AHangC
Copy link
Author

AHangC commented Jan 5, 2023

问题涉及版本1.5及以上

嗯嗯,我试了1.4.2是用的RollbackRetrying可以使用failurehandler。叨扰了,感谢及时回复

@funky-eyes
Copy link
Contributor

问题涉及版本1.5及以上

嗯嗯,我试了1.4.2是用的RollbackRetrying可以使用failurehandler。叨扰了,感谢及时回复

没事没事,多亏你详细的描述和反馈,否则不会这么快排查出原因,社区也要靠广大用户及时反馈问题

@ZhangShiYeChina
Copy link
Contributor

修复认领

@AHangC AHangC closed this as completed Jan 6, 2023
@funky-eyes funky-eyes reopened this Jan 6, 2023
@funky-eyes funky-eyes added the type: bug Category issues or prs related to bug. label Jan 6, 2023
@funky-eyes
Copy link
Contributor

更正涉及版本为1.6.0-1.6.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
task: help-wanted Extra attention is needed type: bug Category issues or prs related to bug.
Projects
None yet
Development

No branches or pull requests

3 participants