记一次诡异的线上异常赋值排查：代码没错，结果不对
这篇文章主要是记录和分享一次线上故障排查的经历 —— 可以说是目前为止我遇到过的最抓狂的排查之一。明明代码看上去没有任何问题，我也反复检查过每一处逻辑，理论上它就不应该出错，但实际执行的结果却始终不符合预期。一边怀疑人生，一边硬着头皮往下查，折磨，真的折磨……背景
在我们的一套比较老的高可用系统中，有一张用于记录订单信息的数据表。其中有一个标识字段（以下称为 flag），该字段会在经过一系列处理后被赋予不同的标识值，供后续业务逻辑使用。
我把与此次问题相关的一段赋值逻辑简化如下：
[*]如果订单包含多个明细且包含多个sku（品类 > 1），则 flag 标记为 2；
[*]否则标记为 1。
赋值代码if (orderSize == 1 && orderDetails.size() > 1 && skus > 1) {
return 2; // flag = 2
}
if (orderSize == 1) {
return 1; // flag = 1
}
按预期，凡是订单同时满足“多明细”和“多品类”两个条件时，flag 字段就应被赋值为 2。事实上，这个小功能也确实在线上稳定运行有3个多月了。
然而，近期客户反馈了一个异常工单：部分同时满足“多明细”和“多品类”的订单，其标识字段存在不一致的情况，有的标记为 2，有的却标记为 1。
这不是一个阻断性故障，也不是一个核心功能模块，但也一定程度给后续业务处理带来了麻烦，至少在问题解决之前，都是由线上实施实时监测并手动在数据库中去修改这个标识字段的值的……
排查分析
1、代码逻辑分析
我的第一反应是判断逻辑是否写错了，反复审核了代码，然后去仿真上验证，结果当然也没有复现。
详细询问后，得知客户已运营的多个仓库中，只有一个仓库出现了这样的异常现象，其他的都是正常运行，且所有仓库运营的 tag 都是一样的。
2、binlog分析
我确认代码没有问题，又一个第一反应，就是去看下落表的时候是不是正常的，有可能这又是一起值被更新覆盖的事故。
截取一段时间内的 binlog 后，我发现了一个诡异的现象：
[*]所有新增（insert）记录的 flag 字段值都是 1；
[*]而那些最终标识字段值符合预期的单据，其实是在insert 之后紧接着来了一次 update，将其更新为 2；
[*]更奇怪的是，insert 操作总是发生在 A 服务器，update 则总是来自 B 服务器；
[*]如果某次 update 应用行为发生在 A 服务，那 flag 字段值就始终为1，从没有变成预期的 2；
虽然我们的系统里有些定时任务会做一些兜底处理，但 flag 本该在 insert 的时候就写入正确值，为什么会在 B 服务器才被补刀？这显然是有问题的。
然后我又拉下来客户称没有问题的其他几个运营仓库的binlog 做对比，发现它们是没有问题的，insert 的时候 flag 字段值就是 2，没有发生额外的 update。
难道是这个仓库 A、B 两台服务器的代码不一样？
于是我写了一个 groovy 脚本，分别在 A 服务器 和 B 服务器 上执行此业务方法，并且传入相同的订单数据，发现返回值：
A 服务器： 返回 2；
B 服务器： 返回 2；
同时也从两台服务器上拉下了核心的业务jar包，对比后也确实是一样的。
更诡异了……
3、缓存&并发分析
不是代码问题，也不是部署包不一致，我又猜，会不会是并发或者缓存问题导致的，因为 insert 时的数据是独立赋值的，而 update 时的数据来源于数据库。
说不定 A 服务器有缓存，导致 insert 的时候使用的是旧值而不是新值。
但是翻了相关的上下文业务代码后，发现这里并没有使用任何 本地缓存 或者 redis。
我琢磨，唯一可能的并发点，可能就是代码中通过 parallelStream 来处理的订单明细，方法中有对同一个 order 连用了两次并行流操作，可能会影响对 skus 的计算？我之前听大哥们复盘的时候提过，有大哥因为在 CompleteFuture 里用了并行流，结果踩了并发安全的坑……
我真的反复看了很多遍代码（唉，历史遗留问题太多，我们的代码复杂度堪比徒步翻山），很确定这块儿就是个串行业务，没有异步，也没有多线程，按理说不应该是并发问题。
排查到这里，我总觉得可能是环境问题了。按以往的经验，这种代码没毛病、又只有它这独个仓库有问题，重启一下 A 服务器的 tomcat 解决所有！但我也不敢真的这样建议……敬畏生产环境是基本修养！
4、类加载分析
经过以上排查后，我也整不出新思路了，然后小组里讨论了一下，有同事提到，会不会是 A 服务器的类加载有问题？
当时我对类加载机制还没有太多实战经验，完全没往这处儿想，但越琢磨越觉得有戏。虽然我之前已经从服务器上拉取了对应的 jar 包并仔细检查里面的代码，但万一 tomcat 实际运行的并不是 jar 包中的那份代码呢？
于是我们立刻用 Arthas 对线上环境做分析，分别在 A、B 两台服务器用 jad 命令反编译目标类，果然，在 A 服务器的 JVM 中根本没有这段新加的 flag 的赋值代码！
这时，我突然想起，之前我的确在两台服务器上都跑过 groovy 脚本，如果 A 服务器的 JVM 中压根儿没有这段赋值代码，那为什么脚本还能输出一个正确结果？
……
很快我就想明白了，我们的服务部署在 tomcat 上，一共包含 3 个 war 包。简单来说，insert 操作发生在 war 包1中，update 操作发生在 war 包2中，而我测试用的 groovy 脚本是在 war包2 所属的应用上执行的，也就是说，当时脚本跑得没问题，其实是因为正好在有关逻辑的那一边执行的，而我一时忘记了这点……
解决
当我们排查到 JVM 中并没有那段关键的业务逻辑代码时，基本就可以收工了。后面就是通知实施切换 master ，然后删除 tomcat 下的 work/webapp 目录 和 temp 目录，然后重启。
至于为啥会出现这种“灵异事件”，我们猜可能是 class 被缓存了、tomcat 没重新加载，又或者有大哥悄悄热更新了某台服务器……
后记
这次问题看起来只是一个简单的字段值异常，结果越查越离谱，面对这个结果我也挺意外的。虽然最终写出来的排查过程看起来就这么些字儿，但是期间经历了对 binlog 的分析、对代码一遍又一遍的“灵魂拷问”、在分布式服务器之间来回查验，最后借助 Arthas 逐层深入……折磨，真的折磨……
最后，也感谢这一通“折腾”，我也算实打实地体会到了 JVM 类加载与热部署的相关机制，对 Java 的类加载行为有了进一步的认知。Arthas 的命令，比如 jad、sc、mc、redefine 等也被我练的“炉火纯青”了……
过程虽然令人抓狂，好在结局还不错。
来源：程序园用户自行投稿发布，如果侵权，请联系站长删除
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！
页:
[1]