订货单多次出库案例一:幂等缺失

订货单多次出库

一个订货单 DH-241119-003055 购买商品葱油饼 2个
CK-241030-003012 在 2024-10-30 15:28:45.843 时出库葱油饼 2个
CK-241030-003261 在 2024-10-30 15:49:26.679 时出库葱油饼 2个

1.同一个订货单 DH-241119-003055 出现多次出库(订货2个出库4个)
2.两个出库单相隔21分钟, 更不应该出现多次出库的情况

1.收到反馈问题时, 已经无法查看生产日志 (生产日志只保留7天)
2.系统有 operation_record 操作记录表, 会记录某人某时操作动作, 包括请求出入参

排查思路: 查看订货单的出库动作和出库单动作
订货单 DH-241119-003055 的主键 = 551039313966915584 , 根据以下SQL查询订货单在 2024-10-30 15:20:00 到 2024-10-30 15:50:00 被操作的记录

          
SELECT  in_body, out_body, service_name, module_name, method, remark, create_time, update_time, trace_id
FROM operation_record
WHERE
    user_name = 'wuzhengyu' -- 操作人
    AND create_time >= '2024-10-30 15:20:00' -- 开始时间
    AND create_time <= '2024-10-30 15:50:00' -- 结束时间
    AND in_body LIKE '%551039313966915584%'  -- 订货单ID作为入参
ORDER BY create_time DESC

查询结果如下

从操作记录来看
1.两个出库单确实间隔21分钟前后出库
2.除了这两个出库单之外,在这之前,还有多次出库动作

继续查询订货单所有出库动作

          
SELECT  in_body, out_body, service_name, module_name, method, remark, create_time, update_time, trace_id
FROM operation_record
WHERE
    user_name = 'wuzhengyu' -- 操作人
    AND remark = '出库' -- 出库动作
    AND create_time >= '2024-10-30 15:20:00' -- 开始时间
    AND create_time <= '2024-10-30 15:50:00' -- 结束时间
    AND in_body LIKE '%551039313966915584%'  -- 订货单ID作为入参
ORDER BY create_time DESC

出库异常信息如下

          
"com.example.wisp.order.mapper.StoreCustomerOrderDetailsMapper.updateById (batch index #1) failed. Cause: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction\n; Lock wait timeout exceeded; try restarting transaction; nested exception is java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction"

由于出库异常,才会多次操作出库动作

问题一: 出库单 CK-241030-002918 已经成功, 为何出库单 CK-241030-003012 还能再次出库?
答: 出库单 CK-241030-003012 的操作时间[2024-10-30 15:28:45.843, 2024-10-30 15:29:05.574] 和出库单 CK-241030-002918 的操作时间[2024-10-30 15:27:49.738, 2024-10-30 15:29:05.528] 有重叠. 因为数据库的事务隔离级别是RC, 在出库单 CK-241030-002918 的事务还未提交之前, 出库单 CK-241030-003012 的事务也在进行中. 造成同一个订货单并发的出库2次, 并且程序层面未对出库操作进行并发控制即未采用分布式锁.

问题二: 出库单 CK-241030-002918 为什么没有在系统上出现?
答: 出库单 CK-241030-002918 被删除了

          
SELECT  in_body, out_body, service_name, module_name, method, remark, create_time, update_time, trace_id
FROM operation_record
WHERE
    user_name = 'wuzhengyu' -- 操作人
    AND create_time >= '2024-10-30 15:28:44' -- 开始时间
    AND create_time <= '2024-10-30 15:49:27' -- 结束时间
ORDER BY create_time DESC

问题三: 出库单 CK-241030-003261 为什么还能出库成功?
答: 因为出库单 CK-241030-002918 被删除时,订货单上的出库痕迹也会被删除, 相当于订货单从未出库.

问题四: 为何之前出库会出现出库异常?
根据出库异常信息 Lock wait timeout exceeded 可知,当时出现了MySQL锁等待. 因为那个时间段一批订货单的商品单价数据不对, 使用 Python 脚本批量更新订货单明细, 出现了长事务, 长时间持有订货单明细的行锁, 导致那个时间段内的出库单出库失败.
出库单 CK-241030-003012 的操作时间[2024-10-30 15:28:45.843, 2024-10-30 15:29:05.574] 操作时长 = 20秒
出库单 CK-241030-002918 的操作时间[2024-10-30 15:27:49.738, 2024-10-30 15:29:05.528] 操作时长 = 76秒
根据两个出库单的 update_time 值相等可知, 长事务结束时间是 2024-10-30 15:29:05, 长事务结束, 行锁释放, 两个出库单同时完成.

一图概之

1.出库操作采用分布式锁
2.及时发现系统中存在的长事务,并避免