记录一次退款bug的排查与总结

【Bug场景】

　　一个收费充电的系统中，由于有一些因为设备故障而导致用户没有放点成功但不能及时主动给用户退款的情况，所以会有一个定时任务，在每天的固定时间为这些订单主动发起一次退款。在查看退款情况时发现了一个很奇怪的现象，一笔订单本来应该在11-23日就退款给用户的，但到了12-16日还是没有成功退款给用户。
　　于是看了下当天定时任务的退款日志，找到了这笔发现，第三方回复的错误消息是退款金额已经超过原始订单金额。这就说明，这笔支付单应该已经退款成功了，而且最后发起的退款金额加上已退款的金额已经大于原始订单了。于是通过第三方支付系统的记录，查看到这笔订单的原始金额2元，已经支付成功，而退款金额是两笔0.75元的退款，都已经成功了。

【问题】

　　看到这里，情况基本清楚了，一个是退款重复发出了，本来应该是退一笔0.75元，但实际上退了两笔0.75元；第二个是这两笔退款在第三方系统的状态是成功的，但是为什么在自己系统里没有处理退款订单，原始交易订单的余额和状态，这说明要么第三方没有回调通知，要么第三方通知而我们内部的逻辑出现了问题。

【排查】

　　首先看这个退款订单为什么会重复。经查得到11-23原始支付订单一笔，而11-23退款订单有2笔，前后相差27秒。此时怀疑是消息队列发起退款调用重复了（退款请求是发送到消息队列之后，由消息队列的消费端处理对退款接口发起调用[标记1]）。然而看了消息队列重复的机制，是调用失败之后才会再次调用，而这里的请求成功、退款成功、数据库插入数据成功，并且两笔成功退款的退款编号都是不同的，说明不是队列重复，而是系统主动发起了两笔退款。
　　于是查看是否可能是系统发起的重复退款。结果发现，这个系统主动发起退款的方法，没有对业务的各种限制进行检查，而是把检查的需求写在了注释课调用说明上，寄希望于外部调用的方法进行限制[标记2]...

　　已经不知道为什么当时没有限制，可能是由于工期紧张，也可能是因为怕麻烦，但这样的设计就导致外部都要去实现这个检查和限制的逻辑。所以说，还是在设计的时候就要用最简单的办法把关键的流程记录下来，为后续查找问题和新需求设计方案快速的提供之前接口的设计细节，才能设计时不冲突，不别扭，查找bug时定位又准又快。就算是因为各种原因设计出了有问题的方案，有了历史设计，在后续进行新需求处理时，也能快速找到问题并更正[标记3]。
　　由于系统中调用这个接口的代码有五六处，而且11-23的日志已经丢失（只保留了15天）[标记4]所以无法判定是否真的是这里出现了问题，只能修改好代码后看以后的运行情况。真的要看下次是否会再次出现，只能在新增的检查逻辑处增加日志记录，并在发现问题后放到数据库里供日后验证了[标记5]。

　　重复调用退款查完，继续查看为什么第三方系统里是退款成功，但是自己的系统里像是没有回调的样子。没有日志，还是先假设第三方已经回调了自己的系统，然后看问题出在哪里。此时能知道的是已经退款成功了两笔0.75元，到第三笔0.75元时已经超过原有的2元，所以无法退款。而现有的两笔重复退款交易单的状态还是在等待回调。另外多次系统定时退款任务后，在12-16早晨生成了2笔新的第三方交易订单-退款，状态也是等待回调...
　　此时只能用现有的已知的信息去查数据库里的所有相关信息，然后放到一起对比，看看哪里会有异常信息，最后分析：

----------------------------------------------------------

--首先根据PC管理端找到出问题的订单，查看订单的具体情况，这里只保留与本次问题有关的关键字段信息：

SELECT * FROM `charge_order` WHERE `charge_order_number` ='20211123020000000791'

id: 2c92b4377d474e5b017d4aec680f2003
charge_order_number: 20211123020000000791

然后找到对应的支付订单，发现支付的2元是已完成的状态，说明付款相关的处理是没问题的。
----------------------------------------------------------
--从第三方系统上找到的退款成功记录倒查到本系统里这两笔交易订单记录：

SELECT * FROM `third_pay_order` WHERE `outer_pay_order_number` ='SYSTEM_REFUND-c9638ab4-7c30-4363-92d0-0df6c7de47fe' OR `outer_pay_order_number` ='SYSTEM_REFUND-f4e33bfd-5677-4220-8c12-8e1f6060bcd9'

id: 2c92b4377d07c3ab017d4bdeafab6097 create_time: 2021-11-23 16:17:04.922000
id: 2c92b4377d07c3ab017d4bdefbe2609a create_time: 2021-11-23 16:17:24.443000

表的内容查到之后，发现有些字段搞不清楚什么意思了[标记6]，只好翻看原有的代码与实体。

ThirdPayOrder thirdPayOrder = new ThirdPayOrder();
thirdPayOrder.setPayBusinessType(EnumConstants.PayBusinessType.REFUND_BALANCE_ORIGINAL);
thirdPayOrder.setInnerPayOrderNumber(getPaymentOrderInnerNumber()); //getPaymentOrderInnerNumber()调用内部编号服务
thirdPayOrder.setOuterPayOrderNumber(bizOrderNo);
thirdPayOrder.setPayChannel(originalPayOrder.getPayChannel());
thirdPayOrder.setThirdPayStatus(EnumConstants.ThirdPayStatus.REQUEST_SENT);
thirdPayOrder.setAmount(refundAmount);
ThirdPayOrder savedRefundPayOrder = thirdPayOrderFacade.save(thirdPayOrder);

这里又发现了问题，为了内部的各种业务联系，专门为实体设置了一个内部编号，但这个内部编号并没有被其它表使用，也就是这字段压根没任何作用[标记7]；而且生成这个编号用的是统一的内部编号服务，所以和商品订单编号长得很像，极容易造成误解[标记8]。
----------------------------------------------------------
--看退款记录的代码，看看退款订单和交易订单是怎么建立关系的
//退款订单建立

ChargeRefundOrder chargeRefundOrder = new ChargeRefundOrder();
chargeRefundOrder.setUserBillId(savedUserBill.getId());
chargeRefundOrder.setAmountOfRefund(refundAmount);
chargeRefundOrder.setChargeOrderId(chargeOrder.getId());
chargeRefundOrder.setPayOrderId(savedRefundPayOrder.getId());
chargeRefundOrder.setChargeRefundOrderNumber(getChargeRefundOrderNumber());
chargeRefundOrder.setUserId(chargeOrder.getUserId());
chargeRefundOrder.setSettlementStatus(EnumConstants.SettlementStatus.REFUNDING);

看代码，发现这里面可以根据pay_order_id查到本记录，也可以根据原始订单id查到本记录。
那直接用上面查到的交易订单的id，对应pay_order_id查找本记录：

SELECT * FROM `charge_refund_order` WHERE `pay_order_id` ='2c92b4377d07c3ab017d4bdeafab6097' or `pay_order_id` ='2c92b4377d07c3ab017d4bdefbe2609a'

没有结果....很奇怪，再看看原始订单id查询记录，发现了两笔订单，金额和时间都对上了，应该是当即就发起退款了，两条记录相隔了27秒：

SELECT * FROM `charge_refund_order` WHERE `charge_order_id` ='2c92b4377d474e5b017d4aec680f2003'：
create_time--charge_order_id--pay_order_id--user_bill_id
2021-11-23 16:17:09.937000 2c92b4377d474e5b017d4aec680f2003 2c92b4377d4c56df017dc0d1ae995743 2c92b4377d4bb193017d4bdec33105b0
2021-11-23 16:17:36.899000 2c92b4377d474e5b017d4aec680f2003 2c92b4377d4c56df017dc0d1af0c5744 2c92b4377d4bb193017d4bdf2c8205c6

那这里的pay_order_id又指向着谁呢？

SELECT * FROM `third_pay_order` WHERE `id` ='2c92b4377d4c56df017dc0d1ae995743' or `id` ='2c92b4377d4c56df017dc0d1af0c5744'
2c92b4377d4c56df017dc0d1ae995743 2021-12-16 09:18:26.965000 SYSTEM_REFUND-eeb75d50-6401-40fc-bb8d-a2d03a615e8b
2c92b4377d4c56df017dc0d1af0c5744 2021-12-16 09:18:27.079000 SYSTEM_REFUND-6833a312-2043-40d9-8dc4-96e32ffff07b

这是今天定时任务发起退款的记录！那为啥历史支付成功的交易订单找不到退款订单呢？
有一点是确定的，就是交易订单都是新增数据，而这个退款订单好像是通过变动交易订单的ID来进行处理的[标记9]。是有新的退款订单就会把之前的退款订单对应的pay_order_id冲掉吗？找到冲掉的原因，可能是主动发起退款的处理不对。

于是在工程上全局搜索了ChargeRefundOrder中setPayOrderId(String payOrderId)的所有调用方。

----------------------------------------------------------
--果然发现了发起退款的地方会把之前的记录给覆盖掉。

String bizOrderNo =
EnumConstants.TLBusinessGenericType.SYSTEM_REFUND + "-" + UUID.randomUUID().toString();
//第三方交易订单新建
ThirdPayOrder oldThirdPayOrder = thirdPayOrderHashMap.get(refund_pay_order_id);

ThirdPayOrder thirdPayOrder = new ThirdPayOrder();
thirdPayOrder.setPayBusinessType(EnumConstants.PayBusinessType.REFUND_BALANCE_ORIGINAL);
String paymentOrderInnerNumber = chargeRefundOrderService.getPaymentOrderInnerNumber();
thirdPayOrder.setInnerPayOrderNumber(paymentOrderInnerNumber); //这里又是一个无用的内部编号
thirdPayOrder.setOuterPayOrderNumber(bizOrderNo);
thirdPayOrder.setPayChannel(oldThirdPayOrder.getPayChannel());
thirdPayOrder.setThirdPayStatus(EnumConstants.ThirdPayStatus.REQUEST_SENT);
thirdPayOrder.setAmount(oldThirdPayOrder.getAmount());
ThirdPayOrder savedRefundPayOrder = thirdPayOrderFacade.save(thirdPayOrder);

UserBill userBill = userBillService.findUniqueBy(new String[]{"payBusinessType", "innerPayOrderNumber"},
new Object[]{EnumConstants.PayBusinessType.REFUND_BALANCE_ORIGINAL.toString(), oldThirdPayOrder.getInnerPayOrderNumber()});
userBill.setInnerPayOrderNumber(paymentOrderInnerNumber);
userBill.setOuterPayOrderNumber(bizOrderNo);
userBillService.save(userBill);

ChargeRefundOrder chargeRefundOrder = chargeRefundOrderService.findUniqueBy("payOrderId", refund_pay_order_id);
chargeRefundOrder.setPayOrderId(savedRefundPayOrder.getId());
chargeRefundOrderService.save(chargeRefundOrder);
... //后续组装参数，发起异步退款操作。

这里的问题主要是，新的退款订单会把之前的退款订单给覆盖掉，这样第三方系统回查的数据就找不到对应的退款订单了[标记9]。这样处理的问题在于，如果发生退款延迟，导致较早的退款订单第三方回调地很晚，而原始退款订单又被覆盖掉，那么此时第三方再次回调就无法匹配到原始退款订单了。至此，这个问题基本就清楚了。较早发出的退款订单，可能由于某种原因发生延迟，回调比较晚，而后来的定时任务又再次发起了退款，并用新的交易订单id覆盖了退款订单的关联pay_order_id，导致第三方回调的消息无法成功处理后续的逻辑。
----------------------------------------------------------
--再看看后续的回调处理逻辑：

通过这个outer_pay_order_number找到了ThirdPayOrder中的交易订单，各种检查无误后，最终调用一个dubbo接口处理后续逻辑。
通过outer_pay_order_number找到了UserBill //由于之前的处理逻辑将这个表里较早的字段覆盖掉了，所以此时已经匹配不上了。注意，前面的thirdPayOrder的outerNumber还在，只是匹配不上了。
而后通过UserBill来找退款订单ChargeRefundOrder，而后根据ChargeRefundOrder找到ChargeOrder，再进行各种参数的修改和状态更新。
-----------------------------------------------------------

【问题点与总结】

标记1：虽然这次查询出消息队列消费没有重复处理，但也提了个醒。依赖于消息队列消费者的接口，要做到幂等，防止重复调用接口的现象。
标记2：限制上，肯定是这个方法本身来做限定。当时没有在这里做的一个担心，还是因为怕锁的名称和其它的锁重复了。现在来想，一方面之前的业务关键流程没有写下来，怕加了锁会和其它的锁冲突，说到底还是花的时间不够或者是怕麻烦省略了这一步。对于这个如果是要做，考虑最好是能够在数据库层面使用乐观锁或者用唯一索引进行限制，这样代码就算偷懒，数据库层面还是会限制到。
标记3：规规矩矩的画流程图可能不现实，尤其是小项目又要赶时间的话。但是涉及到组件、锁以及复杂的流程逻辑，一定要把逻辑用一种简单易懂的办法沉淀下来，不论是日后复盘，还是查找问题，都会起到很大作用。
标记4：其实日志保留15天也基本可以的，但是有一点，对于可能出现问题的地方，需要设置报警消息。也就是说，出现了这个异常，一定是系统数据出现了什么问题，那要用一种能让自己最快知道的消息报警，比如邮件、短信，当然这个也要合理设置，动态调整，别整一些简单的问题天天发邮件，要么把问题改了，要么把这个级别低的邮件关掉，免得对这种告警不敏感，懒得看了。
标记5：这里只是一个思路，放到数据库可以方便后续的告警和展示。
标记6：要在使用的数据库中标注字段的含义，由于我们使用的是JPA会自动根据Entity去创建实例，所以实际的含义只有代码中才会有注释，在MySQL中没有注释，这个得有。
标记7：对于6的问题要处理，另外对于这种业务关联的表来说，要在每个相关的业务表里留下最核心的业务的id关系。比如，A表业务推生了B表，那么B表需要存一个A.id，而B表业务推生了C表，那么C表需要存A.id与B.id，除非在此过程中发现已无法关联到初始业务数据（比如已经将原始数据汇总或者分化开）。
标记8：内部的编号，如果不是特殊要求，最好是能够在编号中加一个用于区分各种业务的字母，如果是纯数字或者特殊标记也相同，那是极容易造成误解的，虽然看代码也能查到，但这是人为增加了维护成本。
标记9：这是设计缺陷，当初就没考虑周全。首先，重复生成订单必须要在数据库中用索引或者锁机制屏蔽掉，另外，如果真的有多笔退款交易订单去关联唯一成功的退款订单，也应该考虑哪笔订单回调成功了再去关联这个退款订单。总之，这里解决的办法很多，一旦选定实施就要记录流程，和其他环节通盘考虑。
另外，梳理过程中还有以下的问题：
1.项目中前前后后断续地做了几次支付、退款相关的需求，由于不连续，所以思路上很多时候都会另起炉灶，导致后续查问题的时候非常麻烦。要统一，要统一，把整个逻辑理得非常清楚，这种基础逻辑是需要讨论到每一个异常分支处理的思路的。定好策略，后续按照这个思路去设计就好
2.对于第三方对接的表，量比较多的时候要根据不同的业务拆分，不要把多种不同的业务放到一起，并不能方便查询，反而增加了表的增长速度；最好不要在这些业务表上层再搞一个平衡表，类似UserBill，表越多，这类业务的性能越差。原则应该是最小可用即可。如果真的在后续开发中用到这些业务数据，用单独的作业去生成一张业务需要的表比提前准备好这些东西要好得多。简单说，就是不要为了以后可能出现的需求提前做优化、做表和数据，因为未来不确定的东西太多了，万一没这个需求了呢。
3.第三方接口回调自己系统，自己系统访问第三方接口，都需要log表来存储消息，避免和第三方扯皮的时候找不到证据。

　　之前一直在寻找真实场景设计思路之类的书，以提高自身的系统设计、表结构设计水平。但实际上，不同的请求量级、可用资源导致这种设计是千变万化的，所以也不太可能找到能解决所有问题的银弹。但有一点，网上很多类似的博客，总结了一些系统的设计，尤其是提供了场景的，可以设身处地地思考，再和作者的思路进行对比。另外可以看看一些中间件的设计，不但能够让我们使用这些组件的水平更高，也能够从软件设计和解决问题的方面为我们提供思路。