记一次 MQ 消息流量异常放大原因分析

---

背景

  某天下午收到其他团队同学的反馈，在测试环境中我们系统业务功能出现异常，测试数据不符合预期。收到反馈之后根据提供的信息排查发现测试环境机器（单机2c4g）CPU被打满，导致我们的应用无法正常对外提供服务。CPU被打满的原因是什么呢？
  通过搜索日志发现同一笔订单支付MQ消息竟然处理了100W+次，而正常情况一笔订单支付MQ消息只会处理1次，难道是交易中台发送消息重复了？那也不至于同一笔订单处理一百多万次啊，带着这个疑问再次深入排查原因…

一、原因排查

1、查看系统日志

查看订单收到消息时的日志主体：

再根据 订单号 和 调用链ID（自主开发，代码执行整个链路上的所有日志打印出同一个ID标识，方便观察搜索整条链路的全量日志，分布式部署机器排查问题神器） 查询是否存在error日志？

这里可以确定代码是存在 NPE（NullPointerException） 的，所以代码肯定是有问题。我们看看相关代码：

这里可以看到代码判断逻辑确实有不严谨的地方，但是这个 NPE 为什么会导致消息执行这么多次呢？

2、定位根因

通过 NPE 日志的异常栈，找到方法调用入口处，仔细 review 代码，发现系统有一个定时任务自动修复订单状态的功能；

上游业务方（我方）存储订单数据状态与下游交易中台的订单状态做对比，如果业务方状态落后，则自动推进订单状态与交易中台保持一致；

下面贴代码以及原因：

参考资料：Canal 将 mysql binlog 同步到 MQ 消息队列中： Canal Kafka RocketMQ QuickStart

下面用流程图更直观看一下（问题代码走的是绿色线，出现了死循环）：

二、解决方案

1、加强判断逻辑，修复NPE问题；（比较简单，这里就不贴代码了）
2、解决binlog无限触发的问题，改动后流程图见下方，主要改动两个地方：
  1> 处理支付逻辑前，判断消息是否被处理过，幂等防止重复处理；
  2> 处理支付逻辑失败后不更新DB，等待下一次任务调度重新校对；

总结

  这个问题次因：支付消息处理中对用户信息获取逻辑不够严谨存在NPE；主因：检查订单状态自动修复功能中监听表mysql binlog消息，触发支付逻辑NPE导致再次触发binlog又继续触发NPE导致binlog消息死循环，进而引起同一笔订单大量处理支付逻辑；
  这段代码在线上运行很长时间了，本次是由有两个bug同时触发暴露出问题，如果没有这次发现，也许这两个代码逻辑漏洞在线上永远不会被发现，因此有好的问题代码发现机制也非常重要。
  静态代码质量分析工具 SonarQube 和 单元测试 能够很好的帮助我们主动发现代码问题、提高代码的质量、提高系统运行的稳定性。作为技术开发同学拥有NB的技术之外，能够合理利用 NB 的工具 也是一项非常重要的技能。