验证分布式事务问题及日志分析

下面结合实际的代码，验证 10.1.3 节中出现的分布式问题是否还存在。在验证前一定要确保所有服务都正常启动，并且服务实例与 Seata Server 之间的通信正常。

修改 OrderService.saveOrder() 方法，添加一行在执行时会出现异常的代码，如下所示：

@Transactional
@GlobalTransactional
public Boolean saveOrder(int cartId) {

    // 调用购物车服务-获取即将操作的 goods_id
    int goodsId = newBeeShopCartDemoService.getGoodsId(cartId);
    // 调用商品服务-减库存
    Boolean goodsResult = newBeeGoodsDemoService.deStock(goodsId);
    // 调用购物车服务-删除当前购物车数据
    Boolean cartResult = newBeeShopCartDemoService.deleteItem(cartId);
    // 执行下单逻辑
    if (goodsResult && cartResult) {
        // 向订单表中新增一条记录
        int orderResult = jdbcTemplate.update("insert into tb_order('cart_id') value ('" + cartId + "')");
        // 此处出现了异常
        int i=1/0;
        if (orderResult > 0) {
            return true;
        }
        return false;
    }
    return false;
}

之后重启订单服务并确认该服务与 Nacos Server 和 Seata Server 通信成功，再请求如下测试地址：

http://localhost:8167/order/saveOrder?cartId=10

此时的结果与 10.1.3 节中的结果相同，控制台中出现了异常信息，生成订单的接口没有返回成功的响应。控制台报出的异常信息如下：

java.lang.ArithmeticException: / by zero
    at ltd.order.cloud.newbee.service.OrderService.saveOrder(OrderService.java:51) ~[classes/:na]

数据库中的结果却不一样了，10.1.3 节中的结果是订单数据没有新增，但是购物车数据被删除了，商品库存也扣减成功了。而整合 Seata 后，一切数据正常，订单数据没有新增，购物车数据未被删除，商品库存也未扣减成功。

明明已经调用了删除购物车的接口和扣减商品库存的接口，为什么数据库中的商品数据和购物项数据没变呢？分别查看这两个服务实例的控制台输出日志，内容如下。

商品服务的控制台输出日志：

2023-05-26 18:07:56.872 INFO 31232 --- [ch_RMROLE_1_2_8]
i.s.c.r.p.c.RmBranchRollbackProcessor: rm handle branch rollback
process:xid=192.168.110.31:8092:6800691518082474159,branchId=68006915180
82474168,branchType=AT,resourceId=jdbc:mysql://127.0.0.1:3306/test_distr
ibution_goods_db,applicationData=null
2023-05-26 18:07:56.872 INFO 31232 --- [ch_RMROLE_1_2_8]
io.seata.rm.AbstractRMHandler: Branch Rollbacking:
192.168.110.31:8092:6800691518082474159 6800691518082474168
jdbc:mysql://127.0.0.1:3306/test_distribution_goods_db
2023-05-26 18:07:57.834 INFO 31232 --- [ch_RMROLE_1_2_8]
i.s.r.d.undo.AbstractUndoLogManager: xid
192.168.110.31:8092:6800691518082474159 branch 6800691518082474168,
undo log deleted with GlobalFinished
2023-05-26 18:07:57.986 INFO 31232 --- [ch_RMROLE_1_2_8]
io.seata.rm.AbstractRMHandler: Branch Rollbacked result:
PhaseTwo_Rollbacked

购物车服务的控制台输出日志：

2023-05-26 18:07:55.419 INFO 31246 --- [ch_RMROLE_1_2_8]
i.s.c.r.p.c.RmBranchRollbackProcessor: rm handle branch rollback
process:xid=192.168.110.31:8092:6800691518082474159,branchId=68006915180
82474172,branchType=AT,resourceId=jdbc:mysql://127.0.0.1:3306/test_distr
ibution_cart_db,applicationData=null
2023-05-26 18:07:55.419 INFO 31246 --- [ch_RMROLE_1_2_8]
io.seata.rm.AbstractRMHandler: Branch Rollbacking:
192.168.110.31:8092:6800691518082474159 6800691518082474172
jdbc:mysql://127.0.0.1:3306/test_distribution_cart_db
2023-05-26 18:07:56.379 INFO 31246 --- [ch_RMROLE_1_2_8]
i.s.r.d.undo.AbstractUndoLogManager: xid
192.168.110.31:8092:6800691518082474159 branch 6800691518082474172,
undo_log deleted with GlobalFinished
2023-05-26 18:07:56.545 INFO 31246 --- [ch_RMROLE_1_2_8]
io.seata.rm.AbstractRMHandler: Branch Rollbacked result: PhaseTwo Rollbacked

这两个微服务实例都在 Seata 组件的协调下完成了如下的关键步骤。

rm handle branch rollback process：RM 执行回滚流程。
Branch Rollbacking：分支事务正在回滚。
PhaseTwo_Rollbacked：分支事务回滚完成。

由于代码中出现了异常，因此导致全局事务没有执行成功，对应的分支事务都回滚了，并没有真正地执行落库操作。

查看 Seata Server 可以看到更为详细的日志信息，内容如下（笔者在日志中添加了一些中文注释）：

# 1.开启全局事务 xid:192.168.110.31:8092:6800691518082474159
# 2.开启扣减库存事务 branchId = 6800691518082474168

18:07:52.029 INFO --- [batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler: SeataMergeMessage xid=192.168.110.31:8092:6800691518082474159, branchType=AT, resourceId=jdbc:mysql://127.0.0.1:3306/test_distribution_goods_db, lockKey=tb_goods:202 5, clientIp:192.168.110.31, vgroup:test_save_order_group
18:07:53.117 INFO --- [verHandlerThread 1 48 500] i.seata.server.coordinator.AbstractCore: Register branch successfully, xid = 192.168.110.31:8092:6800691518082474159, branchId = 6800691518082474168, resourceId = jdbc:mysql://127.0.0.1:3306/test_distribution_goods_db, lockKeys = tb_goods:2025

# 3.开启删除购物项事务 branchId = 6800691518082474172

18:07:53.653 INFO --- [batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler: SeataMergeMessage xid=192.168.110.31:8092:6800691518082474159, branchType=AT, resourceId=jdbc:my sql://127.0.0.1:3306/test_distribution_cart_db, lockKey=tb_cart_item:10, clientIp:192.168.110.31, vgroup:test_save_order_group
18:07:53.837 INFO --- [verHandlerThread 1 49 500] i.seata.server.coordinator.AbstractCore: Register branch successfully, xid = 192.168.110.31:8092:6800691518082474159, branchId = 6800691518082474172, resourceId = jdbc:mysql://127.0.0.1:3306/test_distribution_cart_db, lockKeys = tb_cart_item:10
18:07:54.948 INFO --- [batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler: SeataMergeMessage xid=192.168.110.31:8092:6800691518082474159, extraData=null, clientIp:192. 168.110.31, vgroup:test_save_order_group

# 4.删除购物项的分支事务回滚成功
18:07:56.867 INFO --- [verHandlerThread_1_50_500] io.seata.server.
coordinator.DefaultCore: Rollback branch transaction successfully, xid =
192.168.110.31:8092:6800691518082474159 branchId = 6800691518082474172
# 5.扣减库存分支事务回滚成功

18:07:58.235 INFO --- [verHandlerThread_1_50_500]
io.seata.server.coordinator.DefaultCore: Rollback branch transaction
successfully, xid = 192.168.110.31:8092:6800691518082474159 branchId =
6800691518082474168
# 6.全局事务回滚成功

18:07:58.785 INFO --- [verHandlerThread_1_50_500] io.seata.server.
coordinator.DefaultCore: Rollback global transaction successfully, xid =
192.168.110.31:8092:6800691518082474159.

在日志中可以看到，saveOrder() 方法执行时会开启一个全局事务。在调用另外两个服务实例时会依次开启两个分支事务。由于 saveOrder() 方法中出现了异常，因此导致了全局事务的回滚操作。

接下来把那一行导致异常的代码删除，看一看一切正常的情况下 Seata 组件会做哪些操作。修改代码后重启订单服务并确认该服务与 Nacos Server 和 Seata Server 通信成功，再次请求如下测试地址：

http://localhost:8167/order/saveOrder?cartId=10

此时，没有出现异常信息，该接口返回的结果是 “true”。依次查看三个数据库中的表数据，订单表中新增了一条订单数据，id 为 10 的订单项数据被删除，id 为 2035 的商品库存也扣减成功。分别查看微服务实例的控制台输出日志，内容如下。

商品服务的控制台输出日志：

2023-05-26 18:39:05.685 INFO 31246 --- [ch_RMROLE_1_4_8]
i.s.c.r.p.c.RmBranchCommitProcessor: rm client handle branch commit
process:xid=192.168.110.31:8092:6800691518082474238,branchId=68006915180
82474245,branchType=AT,resourceId=jdbc:mysql://127.0.0.1:3306/test_distr
ibution_cart_db,applicationData=null
2023-05-26 18:39:05.708 INFO 31246 --- [ch_RMROLE_1_4_8]
io.seata.rm.AbstractRMHandler: Branch committing:
192.168.110.31:8092:6800691518082474238 6800691518082474245
jdbc:mysql://127.0.0.1:3306/test_distribution_cart_db null
2023-05-26 18:39:05.719 INFO 31246 --- [ch_RMROLE_1_4_8]
io.seata.rm.AbstractRMHandler: Branch commit result: PhaseTwo Committed

商品服务的控制台输出日志：

2023-05-26 18:39:05.685 INFO 31246 --- [ch_RMROLE_1_4_8]
i.s.c.r.p.c.RmBranchCommitProcessor: rm client handle branch commit
process:xid=192.168.110.31:8092:6800691518082474238,branchId=68006915180
82474245,branchType=AT,resourceId=jdbc:mysql://127.0.0.1:3306/test_distr
ibution_cart_db,applicationData=null
2023-05-26 18:39:05.708 INFO 31246 --- [ch_RMROLE_1_4_8]
io.seata.rm.AbstractRMHandler: Branch committing:
192.168.110.31:8092:6800691518082474238 6800691518082474245
jdbc:mysql://127.0.0.1:3306/test_distribution_cart_db null
2023-05-26 18:39:05.719 INFO 31246 --- [ch_RMROLE_1_4_8]
io.seata.rm.AbstractRMHandler: Branch commit result: PhaseTwo_Committed

这两个微服务实例都在 Seata 组件的协调下完成了如下的关键步骤。

rm client-handle branch commit process：RM 执行提交流程。
Branch committing：分支事务正在提交。
PhaseTwo_Committed：分支事务提交完成。

全局事务执行成功，所有的分支事务都执行了提交操作，数据库中的数据也就对应地被修改了。

查看 Seata Server 可以看到更为详细的日志信息，内容如下（笔者在日志中添加了一些中文注释）：

# 1.开启全局事务 xid:192.168.110.31:8092:6800691518082474238
18:38:57.806 INFO --- [batchLoggerPrint_1_1]
i.s.c.r.p.server.BatchLogHandler: SeataMergeMessage
timeout=60000,transactionName=saveOrder(int),clientIp:192.168.110.31,
vgroup:test_save_order_group
18:38:57.927 INFO --- [verHandlerThread_1_19_500]
i.s.s.coordinator.DefaultCoordinator: Begin new global transaction
applicationId: order-server,transactionServiceGroup: test_save_order_group,
transactionName:
saveOrder(int),timeout:60000,xid:192.168.110.31:8092:6800691518082474238

# 2.开启扣减库存的分支事务 branchId = 6800691518082474241
18:38:58.748 INFO --- [batchLoggerPrint_1_1]
i.s.c.r.p.server.BatchLogHandler: SeataMergeMessage
xid=192.168.110.31:8092:6800691518082474238,branchType=AT,resourceId=jdbc:mysql://127.0.0.1:3306/test_distribution_goods_db,lockKey=tb_goods:2025,clientIp:192.168.110.31,vgroup:test_save_order_group
18:38:59.710 INFO --- [verHandlerThread_1_20_500]
i.seata.server.coordinator.AbstractCore : Register branch successfully,
xid = 192.168.110.31:8092:6800691518082474238, branchId =
6800691518082474241, resourceId =
jdbc:mysql://127.0.0.1:3306/test_distribution_goods_db,lockKeys =
tb_goods:2025

# 3.开始删除购物项的分支事务 branchId = 6800691518082474245

18:39:00.655 INFO --- [batchLoggerPrint_1_1]
i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage
xid=192.168.110.31:8092:6800691518082474238,branchType=AT,resourceId=jdbc
:mysql://127.0.0.1:3306/test_distribution_cart_db,lockKey=tb_cart_item:
10,clientIp:192.168.110.31,vgroup:test_save_order_group
18:39:01.604 INFO --- [verHandlerThread_1_21_500]
i.seata.server.coordinator.AbstractCore : Register branch successfully,
xid = 192.168.110.31:8092:6800691518082474238, branchId =
6800691518082474245, resourceId =
jdbc:mysql://127.0.0.1:3306/test_distribution_cart_db,lockKeys =
tb_cart_item:10

# 4.开始新增订单的分支事务 branchId = 6800691518082474249

18:39:02.437 INFO --- [batchLoggerPrint_1_1]
i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage
xid=192.168.110.31:8092:6800691518082474238,branchType=AT,resourceId=jdbc
:mysql://127.0.0.1:3306/test_distribution_order_db,lockKey=tb_order:1
,clientIp:192.168.110.31,vgroup:test_save_order_group
18:39:03.542 INFO --- [verHandlerThread_1_22_500]
i.seata.server.coordinator.AbstractCore : Register branch successfully,
xid = 192.168.110.31:8092:6800691518082474238, branchId =
6800691518082474249, resourceId =
jdbc:mysql://127.0.0.1:3306/test_distribution_order_db,lockKeys = tb_order:1

# 5.全局事务提交成功

18:39:03.975 INFO --- [batchLoggerPrint_1_1]
i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage
xid=192.168.110.31:8092:6800691518082474238,extraData=null
,clientIp:192.168.110.31,vgroup:test_save_order_group
18:39:06.263 INFO --- [AsyncCommitting_1_1]
io.seata.server.coordinator.DefaultCore : Committing global transaction is
successfully done, xid = 192.168.110.31:8092:68006915180082474238.

本节演示了分布式事务正常提交和异常回滚的两种情况，使用 Seata AT 模式来处理分布式事务的方案就完整地实现了。