search

apache / incubator-seata

:fire: Seata is an easy-to-use, high-performance, open source distributed transaction solution.
https://seata.apache.org/
Apache License 2.0
25.22k stars 8.76k forks source link

多线程并发使用seata的问题 #6311

Open xbox1994 opened 7 months ago

xbox1994 commented 7 months ago

子线程使用RootContext.bind(xid);绑定了主线程的xid，能让报错时整体回滚。但碰到一个问题：

第一个线程修改一个字段，将数据从A改到B，第二个线程修改相同字段（因为是相同xid，可以获取到全局锁），将数据从B改到C，业务异常回滚，那么第一个线程会回滚失败，因为发现脏数据，此时全局锁就一直不会被释放，数据一直被锁住，业务无法继续下去。

请问下官方大佬，这种场景，除了在业务上避免并发修改相同数据外，还有什么好的解决方案呢？seata有机制可以避免吗？或者是我们用seata的方式不对？

funky-eyes commented 7 months ago

What version are you using?

xbox1994 commented 7 months ago

What version are you using?

1.7.0

funky-eyes commented 7 months ago

请给我看一下你的branch table的表结构 Please show me the table structure of your branch table

xbox1994 commented 7 months ago

请给我看一下你的branch table的表结构 Please show me the table structure of your branch table

https://github.com/apache/incubator-seata/blob/1.7.0/script/server/db/mysql.sql

与官方结构一样

funky-eyes commented 7 months ago

请给我看一下你的branch table的表结构 Please show me the table structure of your branch table

https://github.com/apache/incubator-seata/blob/1.7.0/script/server/db/mysql.sql

与官方结构一样

把你的结构截图或者导出来，空口无凭 Screenshot or export your structure

xbox1994 commented 7 months ago

不同线程在同一个事务内修改相同数据： image

第一个分支回滚失败： image

还查了数据库的binlog，05-11期间只有这两次update： image image

funky-eyes commented 7 months ago

请给我看一下你的branch table的表结构 Please show me the table structure of your branch table

https://github.com/apache/incubator-seata/blob/1.7.0/script/server/db/mysql.sql 与官方结构一样

把你的结构截图或者导出来，空口无凭 Screenshot or export your structure

screenshot-20240128-181141

talk me branch table structure ok？

xbox1994 commented 7 months ago

sorry for wrong table, this is branch table image image

CREATE TABLE branch_table ( branch_id bigint(20) NOT NULL, xid varchar(128) NOT NULL, transaction_id bigint(20) DEFAULT NULL, resource_group_id varchar(32) DEFAULT NULL, resource_id varchar(256) DEFAULT NULL, branch_type varchar(8) DEFAULT NULL, status tinyint(4) DEFAULT NULL, client_id varchar(64) DEFAULT NULL, application_data varchar(2000) DEFAULT NULL, gmt_create datetime(6) DEFAULT NULL, gmt_modified datetime(6) DEFAULT NULL, PRIMARY KEY (branch_id), KEY idx_xid (xid) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4

funky-eyes commented 7 months ago

如果你的server用的是1.7，并且gmt_create的精度为6，没有相同资源重入后因为回滚顺序不对导致的脏写问题。 If your server is using 1.7 and gmt_create has a precision of 6, there is no problem with dirty writes due to rollbacks in the wrong order after reentry of the same resource.

13333713052 commented 7 months ago

如果你的server用的是1.7，并且gmt_create的精度为6，没有相同资源重入后因为回滚顺序不对导致的脏写问题。 If your server is using 1.7 and gmt_create has a precision of 6, there is no problem with dirty writes due to rollbacks in the wrong order after reentry of the same resource.

我按照他这个使用了2.0版本的seata server和SDK，gmt_create精度也是6，同一数据连续修改两次，抛出异常后，回滚也遇到了这个问题

funky-eyes commented 7 months ago

如果你的server用的是1.7，并且gmt_create的精度为6，没有相同资源重入后因为回滚顺序不对导致的脏写问题。 If your server is using 1.7 and gmt_create has a precision of 6, there is no problem with dirty writes due to rollbacks in the wrong order after reentry of the same resource.

我按照他这个使用了2.0版本的seata server和SDK，gmt_create精度也是6，同一数据连续修改两次，抛出异常后，回滚也遇到了这个问题

自行官网查看升级手册的说明 Check the instructions of the upgrade manual on your own official website.

xbox1994 commented 7 months ago

不知道咋说，用了官方的例子，加了并发的代码，百分百复现 image image image image image

xbox1994 commented 7 months ago

如果你的server用的是1.7，并且gmt_create的精度为6，没有相同资源重入后因为回滚顺序不对导致的脏写问题。 If your server is using 1.7 and gmt_create has a precision of 6, there is no problem with dirty writes due to rollbacks in the wrong order after reentry of the same resource.

有没有可能回滚顺序是对的，但是正要回滚时的数据被其他线程修改了，就是其他线程没来得及停下来修改数据

funky-eyes commented 7 months ago

不知道咋说，用了官方的例子，加了并发的代码，百分百复现 image image image image image

把你的日志全部贴上来,server侧的

xbox1994 commented 7 months ago

20:17:40.946 INFO --- [tyServerNIOWorker_1_10_16] [rocessor.server.RegTmProcessor] [ onRegTmMessage] [] : TM register success,message:RegisterTMRequest{version='1.7.0', applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', extraData='ak=null digest=my_test_tx_group,10.167.51.1,1706703460680 timestamp=1706703460680 authVersion=V4 vgroup=my_test_tx_group ip=10.167.51.1 '},channel:[id: 0xf21c4daf, L:/127.0.0.1:8091 - R:/127.0.0.1:62086],client version:1.7.0 20:17:42.997 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalBeginRequest{transactionName='dubbo-demo-tx', timeout=300000}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.003 INFO --- [verHandlerThread_1_16_500] [coordinator.DefaultCoordinator] [ doGlobalBegin] [10.167.51.1:8091:3468256129648835463] : Begin new global transaction applicationId: dubbo-demo-app,transactionServiceGroup: my_test_tx_group, transactionName: dubbo-demo-tx,timeout:300000,xid:10.167.51.1:8091:3468256129648835463 20:17:43.009 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalBeginResponse{xid='10.167.51.1:8091:3468256129648835463', extraData='null', resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.336 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.360 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835465, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.365 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835465, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.395 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.412 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835467, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.413 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835467, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.446 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.456 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835469, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.456 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835469, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.576 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.586 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835471, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.586 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835471, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.618 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.628 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835473, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.629 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835473, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.642 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.653 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835475, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.654 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835475, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.711 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:277', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.717 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:276', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.717 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:278', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.720 INFO --- [nPool.commonPool-worker-7] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835479, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:276 20:17:43.722 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835477, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:277 20:17:43.723 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835479, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.728 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835481, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:278 20:17:43.729 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835477, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.729 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835481, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.775 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.782 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835483, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.782 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835483, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.794 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.804 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835485, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.804 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835485, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.810 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.819 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.823 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835487, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.826 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835487, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.833 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835489, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.834 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835489, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.857 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.868 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:279', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.873 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835491, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.875 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835491, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.879 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835493, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:279 20:17:43.881 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835493, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.888 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.903 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:280', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.920 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835495, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:43.921 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835495, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.933 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.940 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835498, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:280 20:17:43.941 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835498, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.956 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:281', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.956 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835500, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:43.962 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835500, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.983 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835502, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:281 20:17:43.985 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835502, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:43.995 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:4', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.001 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.011 INFO --- [nPool.commonPool-worker-3] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835504, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:4 20:17:44.012 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835504, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.014 INFO --- [nPool.commonPool-worker-9] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3468256129648835463] : Register branch successfully, xid = 10.167.51.1:8091:3468256129648835463, branchId = 3468256129648835506, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:6 20:17:44.018 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3468256129648835506, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.018 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalRollbackRequest{xid='10.167.51.1:8091:3468256129648835463', extraData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.042 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:282', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.045 ERROR --- [nPool.commonPool-worker-9] [ption.AbstractExceptionHandler] [eptionHandleTemplate] [10.167.51.1:8091:3468256129648835463] : Catch TransactionException while do RPC, request: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:282', applicationData='null'} ==> io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 10.167.51.1:8091:3468256129648835463 status = Rollbacking while expecting Begin at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:367) at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:103) at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:294) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:523) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.handleRequestsByMergedWarpMessage(ServerOnRequestProcessor.java:288) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.lambda$onRequestMessage$1(ServerOnRequestProcessor.java:178) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) <==

20:17:44.046 ERROR --- [nPool.commonPool-worker-3] [ption.AbstractExceptionHandler] [eptionHandleTemplate] [10.167.51.1:8091:3468256129648835463] : Catch TransactionException while do RPC, request: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'} ==> io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 10.167.51.1:8091:3468256129648835463 status = Rollbacking while expecting Begin at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:367) at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:103) at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:294) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:523) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.handleRequestsByMergedWarpMessage(ServerOnRequestProcessor.java:288) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.lambda$onRequestMessage$1(ServerOnRequestProcessor.java:178) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) <==

20:17:44.048 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3468256129648835463', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:6', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.053 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=0, resultCode=Failed, msg='TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3468256129648835463 status = Rollbacking while expecting Begin]'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.059 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=0, resultCode=Failed, msg='TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3468256129648835463 status = Rollbacking while expecting Begin]'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.077 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835506, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group Wed Jan 31 20:17:44 CST 2024 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification. 20:17:44.104 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835506 20:17:44.159 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835504, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.164 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835504 20:17:44.191 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835502, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.199 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835502 20:17:44.230 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835500, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.234 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835500 20:17:44.265 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835498, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.276 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835498 20:17:44.316 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835495, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.325 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835495 20:17:44.365 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835493, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.376 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835493 20:17:44.402 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835491, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.409 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835491 20:17:44.438 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835489, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.443 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835489 20:17:44.465 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835487, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.469 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835487 20:17:44.494 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835485, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.501 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835485 20:17:44.524 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835483, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.528 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835483 20:17:44.549 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835481, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.557 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835481 20:17:44.579 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835477, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.586 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835477 20:17:44.610 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835479, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.617 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835479 20:17:44.640 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835475, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.644 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835475 20:17:44.665 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835473, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.669 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835473 20:17:44.686 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835471, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.693 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835471 20:17:44.719 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835469, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.725 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835469 20:17:44.746 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835467, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.751 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835467 20:17:44.771 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835465, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.777 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835465 20:17:44.777 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [ doGlobalRollback] [10.167.51.1:8091:3468256129648835463] : Rollback global transaction successfully, xid = 10.167.51.1:8091:3468256129648835463. 20:17:44.778 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalRollbackResponse{globalStatus=Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.827 INFO --- [tyServerNIOWorker_1_10_16] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : 127.0.0.1:62086 to server channel inactive. 20:17:44.829 INFO --- [tyServerNIOWorker_1_10_16] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : remove channel:[id: 0xf21c4daf, L:/127.0.0.1:8091 ! R:/127.0.0.1:62086]context:RpcContext{applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', clientId='dubbo-demo-app:127.0.0.1:62086', channel=[id: 0xf21c4daf, L:/127.0.0.1:8091 ! R:/127.0.0.1:62086], resourceSets=null}

funky-eyes commented 7 months ago

order_tbl:276 这个数据只被注册了一次3468256129648835479分支,没有额外的分支,他回滚不了,说明没有分支跟他重入同一个数据.你可以尝试用xa模式,还是这个例子,如果没有出现回滚不了的问题.说明修改order_tbl:276这条数据的另有别的地方,没有加上globaltransactional注解导致的

xbox1994 commented 7 months ago

order_tbl:276 这个数据只被注册了一次3468256129648835479分支,没有额外的分支,他回滚不了,说明没有分支跟他重入同一个数据.你可以尝试用xa模式,还是这个例子,如果没有出现回滚不了的问题.说明修改order_tbl:276这条数据的另有别的地方,没有加上globaltransactional注解导致的

改成了XA，日志变了点，但回滚成功了

xbox1994 commented 7 months ago

order_tbl:276 这个数据只被注册了一次3468256129648835479分支,没有额外的分支,他回滚不了,说明没有分支跟他重入同一个数据.你可以尝试用xa模式,还是这个例子,如果没有出现回滚不了的问题.说明修改order_tbl:276这条数据的另有别的地方,没有加上globaltransactional注解导致的

回滚报错脏数据的不是order_tbl，是stock_tbl里的count字段，你看stock_tbl:4是不是重入了很多次 用的官方的incubator-seata-samples。。只改了BusinessServiceImpl里的purchase方法的逻辑，以及seata版本到1.7.0 image

funky-eyes commented 7 months ago

20:17:44.159 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835504, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.164 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835504 stock_tbl 也都是成功的,你给的日志哪里证明了因为脏数据无法回滚?我刚才看错了,以为上面的日志是回滚失败,在你给的日志中没找到回滚失败的信息

xbox1994 commented 7 months ago

看起来还是回滚顺序的问题，undo_log最后一条是93 -> 92。 image

但是抛异常的时候是94 -> 93 的undo_log image

funky-eyes commented 7 months ago

undolog相关的branchid自行去看下server日志就知道回滚顺序是怎么样了

xbox1994 commented 7 months ago

20:17:44.159 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835504, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.164 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835504 stock_tbl 也都是成功的,你给的日志哪里证明了因为脏数据无法回滚?我刚才看错了,以为上面的日志是回滚失败,在你给的日志中没找到回滚失败的信息

server端没有回滚失败的报错，并且提示回滚成功。但是RM端有报错回滚失败，下面，是我重试了，是另一次事务。

[INFO ] 2024-01-31 21:24:23,600 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: register consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,602 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: subscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,604 method:org.apache.dubbo.registry.multicast.MulticastRegistry.multicast(MulticastRegistry.java:226) [DUBBO] Send multicast message: register dubbo://10.167.51.1:20882/io.seata.samples.dubbo.service.StockService?anyhost=true&application=dubbo-demo-stock-service&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=41462&release=2.7.15&service.name=ServiceBean:/io.seata.samples.dubbo.service.StockService&side=provider&timeout=10000&timestamp=1706707009296 to /224.5.6.7:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,604 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: register dubbo://10.167.51.1:20882/io.seata.samples.dubbo.service.StockService?anyhost=true&application=dubbo-demo-stock-service&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=41462&release=2.7.15&service.name=ServiceBean:/io.seata.samples.dubbo.service.StockService&side=provider&timeout=10000&timestamp=1706707009296 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,633 method:org.apache.dubbo.remoting.transport.netty4.NettyServerHandler.channelActive(NettyServerHandler.java:76) [DUBBO] The connection of /10.167.51.1:50428 -> /10.167.51.1:20882 is established., dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:24,097 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,099 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,099 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,124 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383960, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,132 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,160 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383962, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,172 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,193 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383964, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,202 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,276 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,276 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,291 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,291 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,299 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383978, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,311 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,343 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383980, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,353 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,354 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,354 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,396 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383984, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,413 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,478 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,478 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,493 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,493 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,516 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383999, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,527 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [ERROR] 2024-01-31 21:24:24,566 method:io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:151) execute executeAutoCommitTrue error:io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:161) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252) at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230) at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:344) at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.lambda$executeAutoCommitTrue$2(AbstractDMLBaseExecutor.java:146) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:356) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor$LockRetryPolicy.execute(AbstractDMLBaseExecutor.java:188) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:144) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.doExecute(AbstractDMLBaseExecutor.java:83) at io.seata.rm.datasource.exec.BaseTransactionalExecutor.execute(BaseTransactionalExecutor.java:125) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:137) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:56) at io.seata.rm.datasource.PreparedStatementProxy.executeUpdate(PreparedStatementProxy.java:65) at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:927) at io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:51) at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java) at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47) at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:84) at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56) at org.apache.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56) at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55) at io.seata.integration.dubbo.alibaba.AlibabaDubboTransactionPropagationFilter.invoke(AlibabaDubboTransactionPropagationFilter.java:45) at com.alibaba.dubbo.rpc.Filter.invoke(Filter.java:29) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:77) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:46) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.seata.SeataTransactionPropagationProviderFilter.invoke(SeataTransactionPropagationProviderFilter.java:66) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:91) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:52) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:192) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:41) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:129) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:148) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:100) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:175) at org.apache.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51) at org.apache.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at org.apache.dubbo.common.threadlocal.InternalRunnable.run(InternalRunnable.java:41) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:70) at io.seata.rm.DefaultResourceManager.branchRegister(DefaultResourceManager.java:96) at io.seata.rm.datasource.ConnectionProxy.register(ConnectionProxy.java:273) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:250) ... 55 more [INFO ] 2024-01-31 21:24:24,701 method:io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:56) rm handle branch rollback process:BranchRollbackRequest{xid='10.167.51.1:8091:3153004174125383958', branchId=3153004174125383984, branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', applicationData='null'} [INFO ] 2024-01-31 21:24:24,704 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:123) Branch Rollbacking: 10.167.51.1:8091:3153004174125383958 3153004174125383984 jdbc:mysql://localhost:3306/seata [INFO ] 2024-01-31 21:24:24,716 method:io.seata.rm.datasource.undo.AbstractUndoExecutor.dataValidationAndGoOn(AbstractUndoExecutor.java:268) Field not equals, name count, old value 94, new value 93 [ERROR] 2024-01-31 21:24:27,072 method:io.seata.core.logger.StackTraceLogger.error(StackTraceLogger.java:63) branchRollback failed. branchType:[AT], xid:[10.167.51.1:8091:3153004174125383958], branchId:[3153004174125383984], resourceId:[jdbc:mysql://localhost:3306/seata], applicationData:[null]. reason:[Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 10.167.51.1:8091:3153004174125383958 branchId = 3153004174125383984] [INFO ] 2024-01-31 21:24:27,072 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:131) Branch Rollbacked result: PhaseTwo_RollbackFailed_Unretryable [ERROR] 2024-01-31 21:24:27,209 method:org.apache.dubbo.rpc.filter.ExceptionFilter.onResponse(ExceptionFilter.java:79) [DUBBO] Got unchecked and undeclared exception which called by 10.167.51.1. service: io.seata.samples.dubbo.service.StockService, method: deduct, exception: org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [update stock_tbl set count = count - ? where commodity_code = ?]; SQL state [null]; error code [0]; io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] ; nested exception is java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] , dubbo version: 2.7.15, current host: 10.167.51.1 org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [update stock_tbl set count = count - ? where commodity_code = ?]; SQL state [null]; error code [0]; io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] ; nested exception is java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:89) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1444) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:632) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:927) at io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:51) at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java) at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47) at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:84) at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56) at org.apache.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56) at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55) at io.seata.integration.dubbo.alibaba.AlibabaDubboTransactionPropagationFilter.invoke(AlibabaDubboTransactionPropagationFilter.java:45) at com.alibaba.dubbo.rpc.Filter.invoke(Filter.java:29) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:77) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:46) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.seata.SeataTransactionPropagationProviderFilter.invoke(SeataTransactionPropagationProviderFilter.java:66) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:91) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:52) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:192) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:41) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:129) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:148) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:100) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:175) at org.apache.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51) at org.apache.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at org.apache.dubbo.common.threadlocal.InternalRunnable.run(InternalRunnable.java:41) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:161) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252) at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230) at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:344) at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.lambda$executeAutoCommitTrue$2(AbstractDMLBaseExecutor.java:146) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:356) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor$LockRetryPolicy.execute(AbstractDMLBaseExecutor.java:188) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:144) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.doExecute(AbstractDMLBaseExecutor.java:83) at io.seata.rm.datasource.exec.BaseTransactionalExecutor.execute(BaseTransactionalExecutor.java:125) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:137) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:56) at io.seata.rm.datasource.PreparedStatementProxy.executeUpdate(PreparedStatementProxy.java:65) at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) ... 40 more Caused by: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:70) at io.seata.rm.DefaultResourceManager.branchRegister(DefaultResourceManager.java:96) at io.seata.rm.datasource.ConnectionProxy.register(ConnectionProxy.java:273) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:250) ... 55 more [INFO ] 2024-01-31 21:24:27,236 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,238 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,240 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,241 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unsubscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,244 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,246 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unsubscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [WARN ] 2024-01-31 21:24:27,255 method:org.apache.dubbo.remoting.transport.AbstractServer.disconnected(AbstractServer.java:174) [DUBBO] All clients has disconnected from /10.167.51.1:20882. You can graceful shutdown now., dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,256 method:org.apache.dubbo.remoting.transport.netty4.NettyServerHandler.channelInactive(NettyServerHandler.java:91) [DUBBO] The connection of /10.167.51.1:50428 -> /10.167.51.1:20882 is disconnected., dubbo version: 2.7.15, current host: 10.167.51.1

funky-eyes commented 7 months ago

1.tc数据库的字段是纳秒精度 2.本地事务存在相同资源的排他性,相同修改资源的branch不可能是同同时的,也就是第一点不可能是同一个纳秒注册额 3.tc回滚是按照倒叙回滚的

xbox1994 commented 7 months ago

又重试了下，这次server有回滚失败的日志了。。

21:26:05.443 INFO --- [ RetryRollbacking_1_1] [server.coordinator.DefaultCore] [ doGlobalRollback] [10.167.51.1:8091:3153004174125383883] : Rollback global transaction successfully, xid = 10.167.51.1:8091:3153004174125383883. 21:26:18.712 INFO --- [tyServerNIOWorker_1_14_16] [rocessor.server.RegTmProcessor] [ onRegTmMessage] [] : TM register success,message:RegisterTMRequest{version='1.7.0', applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', extraData='ak=null digest=my_test_tx_group,10.167.51.1,1706707578326 timestamp=1706707578326 authVersion=V4 vgroup=my_test_tx_group ip=10.167.51.1 '},channel:[id: 0xcdc934ea, L:/127.0.0.1:8091 - R:/127.0.0.1:50554],client version:1.7.0 21:26:20.713 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalBeginRequest{transactionName='dubbo-demo-tx', timeout=300000}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:20.720 INFO --- [verHandlerThread_1_27_500] [coordinator.DefaultCoordinator] [ doGlobalBegin] [10.167.51.1:8091:3153004174125384106] : Begin new global transaction applicationId: dubbo-demo-app,transactionServiceGroup: my_test_tx_group, transactionName: dubbo-demo-tx,timeout:300000,xid:10.167.51.1:8091:3153004174125384106 21:26:20.734 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalBeginResponse{xid='10.167.51.1:8091:3153004174125384106', extraData='null', resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.021 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.039 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384108, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.041 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384108, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.057 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.069 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384110, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.070 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384110, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.096 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.107 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384112, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.109 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384112, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.121 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.138 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384114, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.140 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384114, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.164 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.187 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384116, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.187 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384116, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.197 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:21', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.206 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.212 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384118, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:21 21:26:21.213 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384118, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.219 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384120, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.220 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:22', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.263 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384120, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.269 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384122, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:22 21:26:21.270 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384122, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.291 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.297 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:23', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.302 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384124, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.305 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384124, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.309 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384126, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:23 21:26:21.313 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384126, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.328 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.348 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384128, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.350 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384128, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.357 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.365 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.367 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384130, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.373 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384130, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.382 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384132, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.383 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384132, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.389 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.396 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:24', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.398 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384134, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.403 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384134, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.417 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384136, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:24 21:26:21.420 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384136, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.426 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.432 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:25', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.440 INFO --- [nPool.commonPool-worker-1] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384138, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = account_tbl:2 21:26:21.440 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384138, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.447 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalRollbackRequest{xid='10.167.51.1:8091:3153004174125384106', extraData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.450 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384140, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = order_tbl:25 21:26:21.453 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384140, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.460 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.472 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:26', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.475 INFO --- [nPool.commonPool-worker-5] [erver.coordinator.AbstractCore] [bda$branchRegister$0] [10.167.51.1:8091:3153004174125384106] : Register branch successfully, xid = 10.167.51.1:8091:3153004174125384106, branchId = 3153004174125384144, resourceId = jdbc:mysql://localhost:3306/seata ,lockKeys = stock_tbl:1 21:26:21.474 ERROR --- [nPool.commonPool-worker-1] [ption.AbstractExceptionHandler] [eptionHandleTemplate] [10.167.51.1:8091:3153004174125384106] : Catch TransactionException while do RPC, request: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='order_tbl:26', applicationData='null'} ==> io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:367) at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:103) at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:294) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:523) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.handleRequestsByMergedWarpMessage(ServerOnRequestProcessor.java:288) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.lambda$onRequestMessage$1(ServerOnRequestProcessor.java:178) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) <==

21:26:21.479 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=3153004174125384144, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.486 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=0, resultCode=Failed, msg='TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin]'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.498 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.518 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384140, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.531 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[merged]: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.532 INFO --- [verHandlerThread_1_46_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384140 21:26:21.575 ERROR --- [nPool.commonPool-worker-5] [ption.AbstractExceptionHandler] [eptionHandleTemplate] [10.167.51.1:8091:3153004174125384106] : Catch TransactionException while do RPC, request: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='account_tbl:2', applicationData='null'} ==> io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:367) at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:103) at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:294) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:523) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.handleRequestsByMergedWarpMessage(ServerOnRequestProcessor.java:288) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.lambda$onRequestMessage$1(ServerOnRequestProcessor.java:178) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) <==

21:26:21.575 ERROR --- [nPool.commonPool-worker-1] [ption.AbstractExceptionHandler] [eptionHandleTemplate] [10.167.51.1:8091:3153004174125384106] : Catch TransactionException while do RPC, request: BranchRegisterRequest{xid='10.167.51.1:8091:3153004174125384106', branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', lockKey='stock_tbl:1', applicationData='null'} ==> io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:191) at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:367) at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:103) at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:294) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:131) at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:523) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.handleRequestsByMergedWarpMessage(ServerOnRequestProcessor.java:288) at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.lambda$onRequestMessage$1(ServerOnRequestProcessor.java:178) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) <==

21:26:21.579 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=0, resultCode=Failed, msg='TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin]'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.586 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[merged]: BranchRegisterResponse{branchId=0, resultCode=Failed, msg='TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125384106 status = Rollbacking while expecting Begin]'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.599 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384138, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.632 INFO --- [verHandlerThread_1_46_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384138 21:26:21.690 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384136, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.697 INFO --- [verHandlerThread_1_46_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384136 21:26:21.722 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384134, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:21.727 INFO --- [verHandlerThread_1_46_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384134 21:26:24.695 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384132, branchStatus=PhaseTwo_RollbackFailed_Unretryable, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:24.700 ERROR --- [verHandlerThread_1_46_500] [a.server.session.SessionHelper] [ endRollbackFailed] [10.167.51.1:8091:3153004174125384106] : The Global session 10.167.51.1:8091:3153004174125384106 has changed the status to RollbackFailed, need to be handled it manually. 21:26:24.703 INFO --- [verHandlerThread_1_46_500] [session.AbstractSessionManager] [ onFailEnd] [10.167.51.1:8091:3153004174125384106] : xid:10.167.51.1:8091:3153004174125384106 fail end, transaction:GlobalSession{xid='10.167.51.1:8091:3153004174125384106', transactionId=3153004174125384106, status=RollbackFailed, applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', transactionName='dubbo-demo-tx', timeout=300000, beginTime=1706707580713, applicationData='null', lazyLoadBranch=false, active=false, branchSessions=[BR:3153004174125384108/3153004174125384106, BR:3153004174125384110/3153004174125384106, BR:3153004174125384112/3153004174125384106, BR:3153004174125384114/3153004174125384106, BR:3153004174125384116/3153004174125384106, BR:3153004174125384118/3153004174125384106, BR:3153004174125384120/3153004174125384106, BR:3153004174125384122/3153004174125384106, BR:3153004174125384124/3153004174125384106, BR:3153004174125384126/3153004174125384106, BR:3153004174125384128/3153004174125384106, BR:3153004174125384130/3153004174125384106, BR:3153004174125384132/3153004174125384106], globalSessionLock=io.seata.server.session.GlobalSession$GlobalSessionLock@2f9993d9, lifecycleListeners=[io.seata.server.storage.db.session.DataBaseSessionManager@578c20c7]} 21:26:24.705 ERROR --- [verHandlerThread_1_46_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction fail and stop retry, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384132 21:26:24.706 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : result msg[single]: GlobalRollbackResponse{globalStatus=RollbackFailed, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 21:26:24.755 INFO --- [tyServerNIOWorker_1_14_16] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : 127.0.0.1:50554 to server channel inactive. 21:26:24.755 INFO --- [tyServerNIOWorker_1_14_16] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : remove channel:[id: 0xcdc934ea, L:/127.0.0.1:8091 ! R:/127.0.0.1:50554]context:RpcContext{applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', clientId='dubbo-demo-app:127.0.0.1:50554', channel=[id: 0xcdc934ea, L:/127.0.0.1:8091 ! R:/127.0.0.1:50554], resourceSets=null}

funky-eyes commented 7 months ago

20:17:44.159 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3468256129648835463', branchId=3468256129648835504, branchStatus=PhaseTwo_Rollbacked, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 20:17:44.164 INFO --- [verHandlerThread_1_37_500] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3468256129648835463] : Rollback branch transaction successfully, xid = 10.167.51.1:8091:3468256129648835463 branchId = 3468256129648835504 stock_tbl 也都是成功的,你给的日志哪里证明了因为脏数据无法回滚?我刚才看错了,以为上面的日志是回滚失败,在你给的日志中没找到回滚失败的信息

server端没有回滚失败的报错，并且提示回滚成功。但是RM端有报错回滚失败，下面，是我重试了，是另一次事务。

[INFO ] 2024-01-31 21:24:23,600 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: register consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,602 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: subscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,604 method:org.apache.dubbo.registry.multicast.MulticastRegistry.multicast(MulticastRegistry.java:226) [DUBBO] Send multicast message: register dubbo://10.167.51.1:20882/io.seata.samples.dubbo.service.StockService?anyhost=true&application=dubbo-demo-stock-service&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=41462&release=2.7.15&service.name=ServiceBean:/io.seata.samples.dubbo.service.StockService&side=provider&timeout=10000&timestamp=1706707009296 to /224.5.6.7:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,604 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: register dubbo://10.167.51.1:20882/io.seata.samples.dubbo.service.StockService?anyhost=true&application=dubbo-demo-stock-service&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=41462&release=2.7.15&service.name=ServiceBean:/io.seata.samples.dubbo.service.StockService&side=provider&timeout=10000&timestamp=1706707009296 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:23,633 method:org.apache.dubbo.remoting.transport.netty4.NettyServerHandler.channelActive(NettyServerHandler.java:76) [DUBBO] The connection of /10.167.51.1:50428 -> /10.167.51.1:20882 is established., dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:24,097 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,098 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,099 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,099 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,124 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383960, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,132 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,160 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383962, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,172 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,193 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383964, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,202 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,276 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,276 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,291 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,291 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,299 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383978, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,311 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,343 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383980, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,353 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,354 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,354 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,396 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383984, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,413 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [INFO ] 2024-01-31 21:24:24,478 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,478 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,493 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:47) Stock Service Begin ... xid: 10.167.51.1:8091:3153004174125383958 [INFO ] 2024-01-31 21:24:24,493 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:48) Deducting inventory SQL: update stock_tbl set count = count - 1 where commodity_code = C00321 [INFO ] 2024-01-31 21:24:24,516 method:io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:73) branch register success, xid:10.167.51.1:8091:3153004174125383958, branchId:3153004174125383999, lockKeys:stock_tbl:1 [INFO ] 2024-01-31 21:24:24,527 method:io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:53) Stock Service End ... [ERROR] 2024-01-31 21:24:24,566 method:io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:151) execute executeAutoCommitTrue error:io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:161) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252) at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230) at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:344) at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.lambda$executeAutoCommitTrue$2(AbstractDMLBaseExecutor.java:146) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:356) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor$LockRetryPolicy.execute(AbstractDMLBaseExecutor.java:188) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:144) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.doExecute(AbstractDMLBaseExecutor.java:83) at io.seata.rm.datasource.exec.BaseTransactionalExecutor.execute(BaseTransactionalExecutor.java:125) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:137) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:56) at io.seata.rm.datasource.PreparedStatementProxy.executeUpdate(PreparedStatementProxy.java:65) at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:927) at io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:51) at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java) at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47) at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:84) at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56) at org.apache.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56) at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55) at io.seata.integration.dubbo.alibaba.AlibabaDubboTransactionPropagationFilter.invoke(AlibabaDubboTransactionPropagationFilter.java:45) at com.alibaba.dubbo.rpc.Filter.invoke(Filter.java:29) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:77) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:46) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.seata.SeataTransactionPropagationProviderFilter.invoke(SeataTransactionPropagationProviderFilter.java:66) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:91) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:52) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:192) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:41) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:129) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:148) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:100) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:175) at org.apache.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51) at org.apache.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at org.apache.dubbo.common.threadlocal.InternalRunnable.run(InternalRunnable.java:41) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:70) at io.seata.rm.DefaultResourceManager.branchRegister(DefaultResourceManager.java:96) at io.seata.rm.datasource.ConnectionProxy.register(ConnectionProxy.java:273) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:250) ... 55 more [INFO ] 2024-01-31 21:24:24,701 method:io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:56) rm handle branch rollback process:BranchRollbackRequest{xid='10.167.51.1:8091:3153004174125383958', branchId=3153004174125383984, branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', applicationData='null'} [INFO ] 2024-01-31 21:24:24,704 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:123) Branch Rollbacking: 10.167.51.1:8091:3153004174125383958 3153004174125383984 jdbc:mysql://localhost:3306/seata [INFO ] 2024-01-31 21:24:24,716 method:io.seata.rm.datasource.undo.AbstractUndoExecutor.dataValidationAndGoOn(AbstractUndoExecutor.java:268) Field not equals, name count, old value 94, new value 93 [ERROR] 2024-01-31 21:24:27,072 method:io.seata.core.logger.StackTraceLogger.error(StackTraceLogger.java:63) branchRollback failed. branchType:[AT], xid:[10.167.51.1:8091:3153004174125383958], branchId:[3153004174125383984], resourceId:[jdbc:mysql://localhost:3306/seata], applicationData:[null]. reason:[Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 10.167.51.1:8091:3153004174125383958 branchId = 3153004174125383984] [INFO ] 2024-01-31 21:24:27,072 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:131) Branch Rollbacked result: PhaseTwo_RollbackFailed_Unretryable [ERROR] 2024-01-31 21:24:27,209 method:org.apache.dubbo.rpc.filter.ExceptionFilter.onResponse(ExceptionFilter.java:79) [DUBBO] Got unchecked and undeclared exception which called by 10.167.51.1. service: io.seata.samples.dubbo.service.StockService, method: deduct, exception: org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [update stock_tbl set count = count - ? where commodity_code = ?]; SQL state [null]; error code [0]; io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] ; nested exception is java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] , dubbo version: 2.7.15, current host: 10.167.51.1 org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [update stock_tbl set count = count - ? where commodity_code = ?]; SQL state [null]; error code [0]; io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] ; nested exception is java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:89) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1444) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:632) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:927) at io.seata.samples.dubbo.service.impl.StockServiceImpl.deduct(StockServiceImpl.java:51) at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java) at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47) at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:84) at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56) at org.apache.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56) at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55) at io.seata.integration.dubbo.alibaba.AlibabaDubboTransactionPropagationFilter.invoke(AlibabaDubboTransactionPropagationFilter.java:45) at com.alibaba.dubbo.rpc.Filter.invoke(Filter.java:29) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:77) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:46) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.seata.SeataTransactionPropagationProviderFilter.invoke(SeataTransactionPropagationProviderFilter.java:66) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:91) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:52) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:192) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:41) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:129) at org.apache.dubbo.rpc.protocol.FilterNode.invoke(FilterNode.java:61) at org.apache.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:148) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:100) at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:175) at org.apache.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51) at org.apache.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at org.apache.dubbo.common.threadlocal.InternalRunnable.run(InternalRunnable.java:41) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: java.sql.SQLException: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:161) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252) at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230) at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:344) at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.lambda$executeAutoCommitTrue$2(AbstractDMLBaseExecutor.java:146) at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:356) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor$LockRetryPolicy.execute(AbstractDMLBaseExecutor.java:188) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:144) at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.doExecute(AbstractDMLBaseExecutor.java:83) at io.seata.rm.datasource.exec.BaseTransactionalExecutor.execute(BaseTransactionalExecutor.java:125) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:137) at io.seata.rm.datasource.exec.ExecuteTemplate.execute(ExecuteTemplate.java:56) at io.seata.rm.datasource.PreparedStatementProxy.executeUpdate(PreparedStatementProxy.java:65) at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) ... 40 more Caused by: io.seata.core.exception.RmTransactionException: branch register failed, xid: 10.167.51.1:8091:3153004174125383958, errMsg: TransactionException[Could not register branch into global session xid = 10.167.51.1:8091:3153004174125383958 status = Rollbacking while expecting Begin] at io.seata.rm.AbstractResourceManager.branchRegister(AbstractResourceManager.java:70) at io.seata.rm.DefaultResourceManager.branchRegister(DefaultResourceManager.java:96) at io.seata.rm.datasource.ConnectionProxy.register(ConnectionProxy.java:273) at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:250) ... 55 more [INFO ] 2024-01-31 21:24:27,236 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,238 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=consumers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,240 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,241 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unsubscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.OrderService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.OrderService&methods=create&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463003 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,244 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unregister consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,246 method:org.apache.dubbo.registry.multicast.MulticastRegistry.receive(MulticastRegistry.java:196) [DUBBO] Receive multicast message: unsubscribe consumer://10.167.51.1/io.seata.samples.dubbo.service.StockService?application=dubbo-demo-app&category=providers,configurators,routers&check=false&dubbo=2.0.2&init=false&interface=io.seata.samples.dubbo.service.StockService&methods=deduct,batchDeduct&pid=42022&qos.accept.foreign.ip=false&qos.enable=false&qos.port=33333&release=2.7.15&side=consumer&sticky=false&timestamp=1706707463590 from /10.167.51.1:1234, dubbo version: 2.7.15, current host: 10.167.51.1 [WARN ] 2024-01-31 21:24:27,255 method:org.apache.dubbo.remoting.transport.AbstractServer.disconnected(AbstractServer.java:174) [DUBBO] All clients has disconnected from /10.167.51.1:20882. You can graceful shutdown now., dubbo version: 2.7.15, current host: 10.167.51.1 [INFO ] 2024-01-31 21:24:27,256 method:org.apache.dubbo.remoting.transport.netty4.NettyServerHandler.channelInactive(NettyServerHandler.java:91) [DUBBO] The connection of /10.167.51.1:50428 -> /10.167.51.1:20882 is disconnected., dubbo version: 2.7.15, current host: 10.167.51.1

server端必定会输出回滚失败的日志 自行查看源码 https://github.com/apache/incubator-seata/blob/1.7.0/server/src/main/java/io/seata/server/coordinator/DefaultCore.java

    @Override
    public boolean doGlobalRollback(GlobalSession globalSession, boolean retrying) throws TransactionException {
        boolean success = true;
        // start rollback event
        MetricsPublisher.postSessionDoingEvent(globalSession, retrying);

        if (globalSession.isSaga()) {
            success = getCore(BranchType.SAGA).doGlobalRollback(globalSession, retrying);
        } else {
            Boolean result = SessionHelper.forEach(globalSession.getReverseSortedBranches(), branchSession -> {
                BranchStatus currentBranchStatus = branchSession.getStatus();
                if (currentBranchStatus == BranchStatus.PhaseOne_Failed) {
                    SessionHelper.removeBranch(globalSession, branchSession, !retrying);
                    return CONTINUE;
                }
                try {
                    BranchStatus branchStatus = branchRollback(globalSession, branchSession);
                    if (isXaerNotaTimeout(globalSession, branchStatus)) {
                        LOGGER.info("Rollback branch XAER_NOTA retry timeout, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                        branchStatus = BranchStatus.PhaseTwo_Rollbacked;
                    }
                    switch (branchStatus) {
                        case PhaseTwo_Rollbacked:
                            SessionHelper.removeBranch(globalSession, branchSession, !retrying);
                            LOGGER.info("Rollback branch transaction successfully, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                            return CONTINUE;
                        case PhaseTwo_RollbackFailed_Unretryable:
                            SessionHelper.endRollbackFailed(globalSession, retrying);
                            LOGGER.error("Rollback branch transaction fail and stop retry, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                            return false;
                        default:
                            LOGGER.error("Rollback branch transaction fail and will retry, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                            if (!retrying) {
                                globalSession.queueToRetryRollback();
                            }
                            return false;
                    }
                } catch (Exception ex) {
                    StackTraceLogger.error(LOGGER, ex,
                        "Rollback branch transaction exception, xid = {} branchId = {} exception = {}",
                        new String[] {globalSession.getXid(), String.valueOf(branchSession.getBranchId()), ex.getMessage()});
                    if (!retrying) {
                        globalSession.queueToRetryRollback();
                    }
                    throw new TransactionException(ex);
                }
            });
            // Return if the result is not null
            if (result != null) {
                return result;
            }
        }
xbox1994 commented 7 months ago

这样排查的效率太低了，要不加个钉钉我共享桌面给你，没空的话明天也行

funky-eyes commented 7 months ago

你数据明显被全局事务以外的事务给脏写了,xa不会是因为xa不需要globaltransactional也能防脏写,他是数据库级别的,把本地锁hold到二阶段了. 你自己看下 stock_tbl:1 的7个分支事务,一个都没有回滚成功,回滚顺序是对的,是你的事务里有别的globaltransactional覆盖的地方在更新,自己分析下代码吧,或者自行去读取binlog看看到底修改了几次对一下分支数量心里就有数了

funky-eyes commented 7 months ago

branchid为3153004174125384132的分支事务作为该pk的第一个回滚分支,遇到脏写后回滚失败,标识全局事务状态为failed,剩下的分支也没有回滚,自行分析下日志就知道了.还有提交issue的时候按格式,提交版本, 日志,堆栈,效率也不会就这么低了

xbox1994 commented 7 months ago

你数据明显被全局事务以外的事务给脏写了,xa不会是因为xa不需要globaltransactional也能防脏写,他是数据库级别的,把本地锁hold到二阶段了. 你自己看下 stock_tbl:1 的7个分支事务,一个都没有回滚成功,回滚顺序是对的,是你的事务里有别的globaltransactional覆盖的地方在更新,自己分析下代码吧,或者自行去读取binlog看看到底修改了几次对一下分支数量心里就有数了

行，谢谢指导，我明天研究研究再答复你

xbox1994 commented 7 months ago

branchid为3153004174125384132的分支事务作为该pk的第一个回滚分支,遇到脏写后回滚失败,标识全局事务状态为failed,剩下的分支也没有回滚,自行分析下日志就知道了.还有提交issue的时候按格式,提交版本, 日志,堆栈,效率也不会就这么低了

行，本来以为两句话能搞定，就没贴那么多日志了。以后一定注意

funky-eyes commented 7 months ago

最好能弄个独立的demo,这样也能通过代码看看蛛丝马迹,不过目前来看可能性最大的还是被全局事务以外的地方修改了一次. 还有个问题,为什么你的分支事务有时候在全局事务决议后才去注册?是不是那块你的客户端的future.get时,某些线程已经执行报错了,然后没有等待后续的线程执行完毕,就直接抛异常出去决议事务为回滚了?

xbox1994 commented 7 months ago

4132是开始回滚的分支，后面竟然还有一个分支注册成功了 image

xbox1994 commented 7 months ago

最好能弄个独立的demo,这样也能通过代码看看蛛丝马迹,不过目前来看可能性最大的还是被全局事务以外的地方修改了一次. 还有个问题,为什么你的分支事务有时候在全局事务决议后才去注册?是不是那块你的客户端的future.get时,某些线程已经执行报错了,然后没有等待后续的线程执行完毕,就直接抛异常出去决议事务为回滚了?

公司电脑不方便分享，代码就是下面这部分。我觉得肯定是多线程搞出来的问题，你说的有可能

@Override
    @GlobalTransactional(timeoutMills = 300000, name = "dubbo-demo-tx", rollbackFor = Exception.class)
    public void purchase(String userId, String commodityCode, int orderCount) {
        LOGGER.info("purchase begin ... xid: " + RootContext.getXID());

        ExecutorService executorService = Executors.newFixedThreadPool(3);
        List<Future<?>> submits = new ArrayList<>();
        String xid = RootContext.getXID();
        for (int i = 0; i < 8; i++) {
            int finalI = i;
            Callable<Boolean> r = () -> {
                RootContext.bind(xid);
                stockService.deduct(commodityCode, 1);
                // just test batch update
                //stockService.batchDeduct(commodityCode, orderCount);
                orderService.create(userId, commodityCode, 1);
                //throw new RuntimeException("random exception mock!");
                if (finalI == 3){
                    throw new RuntimeException("random exception mock!");
                }
                return true;
            };
            Future<?> submit = executorService.submit(r);
            submits.add(submit);
        }

        try {
            for (Future<?> submit : submits) {
                submit.get();
            }
        } catch (Exception e) {
            e.printStackTrace();
            throw new RuntimeException();
        } finally {
            executorService.shutdown();
        }
    }
funky-eyes commented 7 months ago

github的图片不太好打开,最好是发日志内容,至于有的失败有的成功,由于是多线程并行的,可能注册成功的request是早一点到的,注册失败的是稍晚了一些些,看下日志的打印时间 github picture is not very good to open, it is best to send the log content, as for the failure of some of the success, due to multi-threaded parallel, may be successful in registering the request is a little early to register the failure of some of the later some of the time to look at the log of the print time

xbox1994 commented 7 months ago

github的图片不太好打开,最好是发日志内容,至于有的失败有的成功,由于是多线程并行的,可能注册成功的request是早一点到的,注册失败的是稍晚了一些些,看下日志的打印时间 github picture is not very good to open, it is best to send the log content, as for the failure of some of the success, due to multi-threaded parallel, may be successful in registering the request is a little early to register the failure of some of the later some of the time to look at the log of the print time

刚图片的数据内容： INSERT INTO branch_table (branch_id, gmt_create, xid, transaction_id, resource_group_id, resource_id, branch_type, status, client_id, application_data, gmt_modified) VALUES (3153004174125384132, '2024-01-31 13:26:21.375072', '10.167.51.1:8091:3153004174125384106', 3153004174125384106, NULL, 'jdbc:mysql://localhost:3306/seata', 'AT', 0, 'dubbo-demo-stock-service:127.0.0.1:50305', NULL, '2024-01-31 13:26:21.375072'), (3153004174125384144, '2024-01-31 13:26:21.472082', '10.167.51.1:8091:3153004174125384106', 3153004174125384106, NULL, 'jdbc:mysql://localhost:3306/seata', 'AT', 0, 'dubbo-demo-stock-service:127.0.0.1:50305', NULL, '2024-01-31 13:26:21.472082');

funky-eyes commented 7 months ago

帮忙看下你库里3153004174125384144 的时间戳和3153004174125384132的时间戳,根据雪花id来看,3153004174125384132肯定是较早的,但是3153004174125384144 并没有触发回滚,我大概知道是什么原因了

xbox1994 commented 7 months ago

帮忙看下你库里3153004174125384144 的时间戳和3153004174125384132的时间戳,根据雪花id来看,3153004174125384132肯定是较早的,但是3153004174125384144 并没有触发回滚,我大概知道是什么原因了

3153004174125384132：2024-01-31 13:26:21.375072 3153004174125384144：2024-01-31 13:26:21.472082

funky-eyes commented 7 months ago

3153004174125384132 注册后,client决议了回滚,此时server整准备回滚事务,从数据中读到了3153004174125384132是最后一个分支,与此同时3153004174125384144正在进行分支注册,然后他注册成功了,因为此时3153004174125384106还没被修改为rollbaking,分支3153004174125384144注册成功,然后全局事务3153004174125384106进行回滚,他当前加载到的3153004174125384132是最后一个,实际上3153004174125384144才是最后一个. 为了证明我的猜想,请你去数据库将这个3153004174125384106的全局事务的status改为5,看看是否能回滚成功,这时候会触发重新回滚,此时读取的branch顺序就是有3153004174125384144的,而且会让3153004174125384144最为最新下发的分支

funky-eyes commented 7 months ago

这个应该是多线程导致server出现了线程安全的问题,因为在file和raft模式下,server会对globalsession进行加锁,这样增加分支事务等动作都是串行的,而在db和redis模式下,为了减少网络io和磁盘开销,并没有对globalsession进行加锁,所以如果决议回滚,跟分支事务同时发生,这种情况是有可能导致回滚顺序不正常,而终止了回滚的.

xbox1994 commented 7 months ago

3153004174125384106的全局事务的status改为5，branch table的哪行记录？全部记录？还是branch_id是3153004174125384132的还是3153004174125384144的

xbox1994 commented 7 months ago

这个应该是多线程导致server出现了线程安全的问题,因为在file和raft模式下,server会对globalsession进行加锁,这样增加分支事务等动作都是串行的,而在db和redis模式下,为了减少网络io和磁盘开销,并没有对globalsession进行加锁,所以如果决议回滚,跟分支事务同时发生,这种情况是有可能导致回滚顺序不正常,而终止了回滚的.

所以这个是seata的bug了？多线程并发改数据这种场景应该是正常的业务场景吧

funky-eyes commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

funky-eyes commented 7 months ago

这个应该是多线程导致server出现了线程安全的问题,因为在file和raft模式下,server会对globalsession进行加锁,这样增加分支事务等动作都是串行的,而在db和redis模式下,为了减少网络io和磁盘开销,并没有对globalsession进行加锁,所以如果决议回滚,跟分支事务同时发生,这种情况是有可能导致回滚顺序不正常,而终止了回滚的.

所以这个是seata的bug了？多线程并发改数据这种场景应该是正常的业务场景吧

算是,你验证完如果能回滚成功,基本上就确定了,现在只是根据你日志内容和描述理论推导的猜测.

xbox1994 commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

branch_table现在有14条数据，我每条数据的状态都改成5？我改完了，怎么触发呢，现在没有自动回滚

funky-eyes commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

branch_table现在有14条数据，我每条数据的状态都改成5？我改完了，怎么触发呢，现在没有自动回滚

server和client都启动了吗?不要改branchtable,改的是globaltable里的这个10.167.51.1:8091:3153004174125384106 的status

xbox1994 commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

branch_table现在有14条数据，我每条数据的状态都改成5？我改完了，怎么触发呢，现在没有自动回滚

server和client都启动了吗?不要改branchtable,改的是globaltable里的这个10.167.51.1:8091:3153004174125384106 的status

22:08:57.383 INFO --- [ RetryRollbacking_1_1] [.core.rpc.netty.ChannelManager] [ getChannel] [10.167.51.1:8091:3153004174125384106] : Choose [id: 0x5d196cb5, L:/127.0.0.1:8091 - R:/127.0.0.1:53152] on the same IP[127.0.0.1] as alternative of dubbo-demo-stock-service:127.0.0.1:50305 22:08:57.788 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: BranchRollbackResponse{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384144, branchStatus=PhaseTwo_RollbackFailed_Unretryable, resultCode=Success, msg='null'}, clientIp: 127.0.0.1, vgroup: my_test_tx_group 22:08:57.799 ERROR --- [ RetryRollbacking_1_1] [a.server.session.SessionHelper] [ endRollbackFailed] [10.167.51.1:8091:3153004174125384106] : The Global session 10.167.51.1:8091:3153004174125384106 has changed the status to RollbackFailed, need to be handled it manually. 22:08:57.803 INFO --- [ RetryRollbacking_1_1] [session.AbstractSessionManager] [ onFailEnd] [10.167.51.1:8091:3153004174125384106] : xid:10.167.51.1:8091:3153004174125384106 fail end, transaction:GlobalSession{xid='10.167.51.1:8091:3153004174125384106', transactionId=3153004174125384106, status=RollbackFailed, applicationId='dubbo-demo-app', transactionServiceGroup='my_test_tx_group', transactionName='dubbo-demo-tx', timeout=300000, beginTime=1706707580713, applicationData='null', lazyLoadBranch=true, active=true, branchSessions=[BR:3153004174125384108/3153004174125384106, BR:3153004174125384110/3153004174125384106, BR:3153004174125384112/3153004174125384106, BR:3153004174125384114/3153004174125384106, BR:3153004174125384116/3153004174125384106, BR:3153004174125384118/3153004174125384106, BR:3153004174125384120/3153004174125384106, BR:3153004174125384122/3153004174125384106, BR:3153004174125384124/3153004174125384106, BR:3153004174125384126/3153004174125384106, BR:3153004174125384128/3153004174125384106, BR:3153004174125384130/3153004174125384106, BR:3153004174125384132/3153004174125384106, BR:3153004174125384144/3153004174125384106], globalSessionLock=io.seata.server.session.GlobalSession$GlobalSessionLock@18c40e31, lifecycleListeners=[io.seata.server.storage.db.session.DataBaseSessionManager@578c20c7]} 22:08:57.810 ERROR --- [ RetryRollbacking_1_1] [server.coordinator.DefaultCore] [a$doGlobalRollback$3] [10.167.51.1:8091:3153004174125384106] : Rollback branch transaction fail and stop retry, xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384144

xbox1994 commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

branch_table现在有14条数据，我每条数据的状态都改成5？我改完了，怎么触发呢，现在没有自动回滚

server和client都启动了吗?不要改branchtable,改的是globaltable里的这个10.167.51.1:8091:3153004174125384106 的status

刚关了，，现在都启动了，状态也改了，现在报错，状态回到12了

funky-eyes commented 7 months ago

3153004174125384106

3153004174125384106是全局事务,也就是10.167.51.1:8091:3153004174125384106 这个xid

branch_table现在有14条数据，我每条数据的状态都改成5？我改完了，怎么触发呢，现在没有自动回滚

server和client都启动了吗?不要改branchtable,改的是globaltable里的这个10.167.51.1:8091:3153004174125384106 的status

刚关了，，现在都启动了，状态也改了，现在报错，状态回到12了

错误是什么?日志发出来看下?理论上重新回滚,按照时间戳应该是3153004174125384144先回滚了,之前是3153004174125384132,现在client的异常是什么?

xbox1994 commented 7 months ago

PhaseTwo_RollbackFailed_Unretryable

server的报错在上面，这里是client的异常：

Application is keep running ... [INFO ] 2024-01-31 22:08:57,400 method:io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:56) rm handle branch rollback process:BranchRollbackRequest{xid='10.167.51.1:8091:3153004174125384106', branchId=3153004174125384144, branchType=AT, resourceId='jdbc:mysql://localhost:3306/seata', applicationData='null'} [INFO ] 2024-01-31 22:08:57,408 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:123) Branch Rollbacking: 10.167.51.1:8091:3153004174125384106 3153004174125384144 jdbc:mysql://localhost:3306/seata [WARN ] 2024-01-31 22:08:57,434 method:io.seata.common.loader.EnhancedServiceLoader$InnerEnhancedServiceLoader.loadFile(EnhancedServiceLoader.java:545) Load [io.seata.rm.datasource.undo.parser.ProtostuffUndoLogParser] class fail: io/protostuff/runtime/IdStrategy [ERROR] 2024-01-31 22:08:57,735 method:io.seata.core.logger.StackTraceLogger.error(StackTraceLogger.java:63) branchRollback failed. branchType:[AT], xid:[10.167.51.1:8091:3153004174125384106], branchId:[3153004174125384144], resourceId:[jdbc:mysql://localhost:3306/seata], applicationData:[null]. reason:[Branch session rollback failed because of dirty undo log, please delete the relevant undolog after manually calibrating the data. xid = 10.167.51.1:8091:3153004174125384106 branchId = 3153004174125384144] [INFO ] 2024-01-31 22:08:57,736 method:io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:131) Branch Rollbacked result: PhaseTwo_RollbackFailed_Unretryable

funky-eyes commented 7 months ago

现在回滚顺序对了,但是数据还是被脏写了,对比下undolog和当前的内容看下区别是什么?我记得client侧会打印不相同的字段列,你这里怎么没有?