记录一次mybatis源码bug引发的拖库问题

震惊！！因 mybatis 引用的 OGNL 中存在一个 bug，导致拖库查询了 6300W 条数据！！！

零：我们被一条 sql 拖库了！！！

最近，我们的服务总有一两台机器在发布的时不到 20s，内存直接打满，FGC 十几次都无法清空内存。而出现该问题时，只要漂移和重建该现象就会消失。
这个问题困扰着我良久良久，不断地翻阅代码、查看日志，可是怎么也找不到原因。于是我决定在线上发生故障的时候迅速 dump 内存，以下是我 dump 内存时的结果：

OMG，额的亲娘内，为什么一个线程池能直接消耗近 5 G内存，我们 OC 总共也才 6G，这不是要我的老命吗？我赶紧跟踪线程，看看是何妖魔在作怪！！！

我去，竟然一个查询语句查出来了 6000W 的数据，是谁！！是哪个 S* 写的全表查询语句，我要逮到他，准让他吃800大板！！！我要看看是什么查询在作怪！！！

此处涉及隐私信息，因此不展示图片

emmm，什么鬼呀，竟然是 getPidByMob，这个 sql 很简单啊， 怎么会拖库呢？

<select id="getPidByMob" resultType="Long">
    select passenger_id from passenger_info
    <where>
        <choose>
            <when test="mob != null and mob != ''">mob = #{mob}</when>
            <when test="mobEncrypt != null and mobEncrypt != ''">and mob_encrypt = #{mobEncrypt}</when>
            <otherwise>and 1 = -1</otherwise>
        </choose>
    </where>
</select>

看到这我心里暗惊，这个是我加解密改造时写的代码，数据库有两个字段，mob（明文） 和 mobEncrypt （密文）。在 mobEncrypt 全部填充完之后，我已经把 mob 的值都已经清空了。难不成我的加解密插件有问题！！！ 哦，不，800大板难不成是打我！！！

于是我赶紧看看线程执行流程，看看我加解密插件是否正常运行，追踪到如下代码：

还好还好，我看完整个栈信息后发现，我的插件是正常执行的，在插件执行前，只有一个参数String，值为 187xxxxxxxx。经过我插件执行之后，成功的将参数替换为了 Map，且 mob = ‘’ ，mobEncrypt = ur8FB1toxxxxxxxxxxxxxxxxxxxxxxxxxxxx。
因此，最终执行出来的 sql 必然是：select passenger_id from passenger_info where mobEncrypt = 'ur8FB1toxxxxxxxxxxxxxxxxxxxxxxxxxxxx'。哈哈，这波优势在我！！！

同时我也纳闷了，我插件既然执行成功了，那怎么会拖库呢？于是我赶紧找到生成 sql 的方法查看。

what the f**k，为什么最终生成的 sql 是这个：select passenger_id from passenger_info where mob = '' ！！！不可能，绝对不可能！！！
我就想问问，在参数 mob = ‘’ ，mobEncrypt = ur8FB1toxxxxxxxxxxxxxxxxxxxxxxxxxxxx 的条件下，以上 XML 何德何能他能生成出这条语句？？？

你今天就是天王老子来了，它也只能生成这条 sql : select passenger_id from passenger_info where mobEncrypt = 'ur8FB1toxxxxxxxxxxxxxxxxxxxxxxxxxxxx'。

因为我插件拦截的是 query(MappedStatement ms, Object parameterObject, RowBounds rowBounds, ResultHandler resultHandler) 方法。
在执行该方法前替换了 parameterObject。于是我赶紧定位在我插件和 query(MappedStatement ms, Object parameterObject, RowBounds rowBounds, ResultHandler resultHandler, CacheKey key, BoundSql boundSql) 之间有什么代码执行。

最终定位到如下代码：

在传递给 query(MappedStatement ms, Object parameterObject, RowBounds rowBounds, ResultHandler resultHandler, CacheKey key, BoundSql boundSql) 方法时，BoundSql 就已经生成了 select passenger_id from passenger_info where mob = ''。 那么问题必然出现在这个 BoundSql boundSql = ms.getBoundSql(parameterObject) 上面了，于是我继续追踪其代码，最终觉得是执行 mob != null and mob != ‘’ 时的 IfSqlNode 出了问题，导致 ‘’ != null and ‘’ != ‘’ 最终返回了true。

于是我继续定位，发现 mybatis 最终是采用 OGNL 执行的动态表达式，代码如下：

小样，今天不把问题搞清楚，我必不可能回家！！！！！！

一：mybaits 执行 OGNL 解析 动态SQL。

1.1 动态sql执行源码

mybatis 会通过 XMLStatementBuilder 将 XML 解析成 sqlSource（不再本文范围内，具体逻辑可翻阅源码），最终在执行 动态sql 时将表达式和参数传递给 OgnlCache 计算表达式的值，源码如下：

通过上述代码我们可以发现，为了复用表达式，mybatis使用了全局复用的表达式缓存，缓存了所有表达式的 Node。
Ognl.getValue() 处理表达式的时候，会先生成一个 tree 这个 tree 的本质是一个 SimpleNode 实例，树的每个节点都是继承至 SimpleNode。实际结果为该 Node 执行之后的结果。

1.2 Node 结构分析

为了方便大家理解，我们以下面的表达式为例：” mob != null and mob ! ‘’ “，生成的树形结构如下：

我们分析上述表达式的树结构为：

1. 顶层是 ASTAnd 节点实例，它的结果由 mob != null 和 mob != ‘’ 使用 and 判断结果。
2. 第二层是ASTNotEq 节点实例，它的结果由 mob（ASTProperty 表示值需要从 content 中获取属性值）和 null （常量节点，不需要运算，直接存储进 constantValue）使用 eq 判断结果。右侧同理。
3. 第三层表示属性名为 mob，它会在 ASTProperty 这一层调用 getProperty 拿到属性名。

ps：稍微解释一下常量节点，mob != ‘’ 中，其中 ‘’ 是写死的，不管何时获取都应该是 ‘’，因此 node 会在首次执行的时候把结果缓存，后续会提到这个逻辑（罪魁祸首就是这个 ASTConst！！！）。

下图是其真正的内存结构：

二：OGNL具体执行流程

通过第一节我们知道，OGNL 表达式的结果是通过执行 Node 树的 getValue(ognlContext, root) 获得。我们参阅其具体源码：

源码执行其实很简单，context.getTraceEvaluations() 源码默认为false，除非设置系统参数：org.apache.ibatis.ognl.traceEvaluations = true。

接下来我们翻阅 evaluateGetValueBody(OgnlContext context, Object source) 源码，源码如下：

我们的bug 罪魁祸首便是 hasConstantValue 和 constantValue 这两个变量！！！！至于为什么会出现这个bug，听我后面慢慢讲来。

我们先来说一下为什么会存在 if (!this.constantValueCalculated) 这个逻辑。通过方法名我们也知道，这个逻辑实际上是为了缓存所有的常量节点。constantValueCalculated = true 这个操作是标识该节点已经被判定过是否常量节点。
因为常量节点继承 SimpleNode 节点且复写了 isConstant(context)，该方法会直接返回 true，这时候会将常量节点的 value 直接 copy 到 constantValue。
因为 constantValueCalculated、hasConstantValue 和 constantValue 属于全局变量，因此首次执行完之后，下次再执行该常量节点会直接返回 constantValue 。

ASTConst 源码如下：

ASTConst 变量初始值如下：

三：BUG 原理

我们这边通过一个线上拖库的 sql 来演示 bug 形成的原因，sql 示例如下： 此时 mob = “” ，mobEncrypt = “123456”

<select id="getDriverIdByMob" resultType="Long">
    select passenger_id from passenger_info
    <where>
        <choose>
            <when test="mob != null and mob != '')">mob = #{mob}</when>
            <when test="mobEncrypt != null and mobEncrypt != ''">and mob_encrypt = #{mobEncrypt}</when>
            <otherwise>and 1 = -1</otherwise>
        </choose>
    </where>
</select>

这里我们过一下这棵树节点：

3.1 正常业务执行

我们先模拟正常业务执行的逻辑，为了降低大家理解成本，我这边省略了其他源码的解释，只做一些简单的解释，有兴趣的可以去看 mybatis 的源码。

先执行第一个表达式的左树：

1. 执行 mob != null，此时会递归执行 ASTProperty 获取 mob 的值，以及获取常量 null 的值。
2. ASTProperty 表示结果需要从 content 的属性中获取，调用 getProperty() 从常量节点中拿到属性名 mob，再通过 OgnlRuntime.getProperty(context, source, property) 从 content 中获取属性值 “”。
3. 执行 null 常量节点，将 value 赋值给 constantValue 后返回。
4. “” != null 返回 true。

因为是 and，当左树满足要求后，会执行第一个表达式的右树：

1. 先执行 mob != ‘’，此时会递归执行 ASTProperty 获取 mob 的值，以及获取常量 null 的值。
2. ASTProperty 表示结果需要从 content 的属性中获取，调用 getProperty() 从常量节点中拿到属性名 mob，再通过 OgnlRuntime.getProperty(context, source, property) 从 content 中获取属性值 “”。
3. 执行 null 常量节点，将 value 赋值给 constantValue 后返回。
4. “” != “” 返回 false。

最终的结果为 false，这时候就会去判断第二个 动态 sql ：mobEncrypt != null and mobEncrypt != ''，同样的原理执行完后， 123456 != null and 123456 != '' 结果为 true，此时完整sql如下：select passenger_id from passenger_info where mob_encrypt = 123456

3.2 并发解析

这个时候我们假设，我们并发了两条 sql ，其中两条 sql 参数分别为：
A： mob = “” ，mobEncrypt = “123456”
B：mob = “” ，mobEncrypt = “abcdef”

此时 A、B 两条语句执行逻辑都一样，先执行第一个表达式的左树：

1. 执行 mob != null，此时会递归执行 ASTProperty 获取 mob 的值，以及获取常量 null 的值。
2. ASTProperty 表示结果需要从 content 的属性中获取，调用 getProperty() 从常量节点中拿到属性名 mob，再通过 OgnlRuntime.getProperty(context, source, property) 从 content 中获取属性值 “”。
3. 执行 null 常量节点，将 value 赋值给 constantValue 后返回。
4. “” != null 返回 true。

因为是 and，当左树满足要求后，会执行第一个表达式的右树：

1. 先执行 mob != ‘’，此时会递归执行 ASTProperty 获取 mob 的值，以及获取常量 null 的值。
2. ASTProperty 表示结果需要从 content 的属性中获取，调用 getProperty() 从常量节点中拿到属性名 mob，再通过 OgnlRuntime.getProperty(context, source, property) 从 content 中获取属性值 “”。

执行完之后，我们 A、B 两个表达式为：'' != null and '' != ?

3.3 bug流程开始

此时，我们开始考虑并发问题，并引发 OGNL 表达式bug，先看最后一个节点 ‘’ （ASTConst 节点）的执行流程以及变量初始值：

我们用时序图模拟并发时以下代码：

public abstract class SimpleNode implements Node, Serializable {
    private boolean constantValueCalculated; // 初始值 false    
    private boolean hasConstantValue;// 初始值 false    
    private Object constantValue;// 初始值 null    
    
    protected Object evaluateGetValueBody(OgnlContext context, Object source) throws OgnlException {     
        context.setCurrentObject(source);        
        context.setCurrentNode(this);        
        if (!this.constantValueCalculated) {            
            this.constantValueCalculated = true;            
            this.hasConstantValue = this.isConstant(context);            
            if (this.hasConstantValue) {                
                this.constantValue = this.getValueBody(context, source);            
                }        
            }        
            return this.hasConstantValue ? this.constantValue : this.getValueBody(context, source);    
        }
    }

A 和 B 执行时序图：

由时序图我们可知，当 mob != null and mob != ‘’ 首次执行时，因为节点缓存的原因，共用了最后一个 ASTConst 节点（即常量值为 “” 的节点）。

如果 A 执行到第 12 行代码时，这次由于并发问题，b 执行完第 9 行得到 false，之后直接 return 了一个未初始化的 constantValue。本来 B 应该获取到 “” （空字符串），结果得到的是 null。

最终 B 得到的表达式为：'' != null and '' != null，此时命中该动态语句，执行 sql :select passenger_id from passenger_info where mob = ''

在上述并发条件中，服务会在启动的时候，开始执行这条语句。而加解密已经将明文清除，此时这条语句无疑是一条拖库的全表查询！！！！！最终导致我们线上拖了 6000多万数据导致 OC 100%，之后频繁 GC 又无法回收该内存，导致服务直接挂了。

实际上，我盘了一下内部项目，发现有很多老项目都是使用的存在bug版本的mybatis。而之所以频繁FGC的现象只会在我们服务出现，是因为数据量的确太大了，该表数据高达8亿，虽然只会在启动的时候第一次执行出现并发的情况下触发拖库，但是在庞大的数据量下，执行一次该语句就是致命的。所以并不是其他服务不会出现拖库，而是其他涉及加解密的服务也会拖库，但是数据量完全能被内存cover住，所以暂时还没有暴露出问题。

因此，我紧急推动改造，把 mob != ''这种语句全改为 !mob.isEmpty()，防止因常量节点的 bug 导致拖库。之后让 mybatis 在 3.3.X 以下版本的项目统一进行jar包升级来彻底解决该 bug。

四：如何修复bug

通过翻阅 mybatis 的 issues，我找到了这个 bug ：https://github.com/mybatis/mybatis-3/issues/224。
这个 bug 是因为 ognl 执行未考虑并发导致，bugfix 记录如下：https://issues.apache.org/jira/browse/OGNL-121。

mybatis 最终引入了 bugfix 版本的 ognl，并将其合并到了 3.3.X 版本，也就是说，只要 mybatis 升级到 3.3.X 以上，就不会出现该bug。

尾：总结

在排查问题的时候，我也翻阅不少人的博客和文章，也找到过与该 bug 相关的博客，当时他们提到这个bug，并瞎几把解释了一通，我以为我发现了正确答案。

可是在和别人解释的过程中，我代入一看。不对，根本不是这样，这样并不会引发bug，到底是什么引发的呢？我开始怀疑他们说的 mybatis 的 bug 是不是真的是个bug了。

于是我登录了我的 github，找到了mybatis 的源码，通过其 issues 一个一个翻阅，最终找到了这个 bug 的记录，同时也索引到了 ognl 的 bugfix 记录里面，后续我才确认，的确是 ognl 有 bug。

但是，bug 是怎么产生的呢？为什么会有bug，网上大部分都没解释直接说有 bug，找到一个提示有bug的，结果他还是自己瞎说的，bug 地方都说错了。

没办法，真要找bug，那就只能翻源码 + debugger，在知道 bug 位置后，多动手，多阅读，总能找到原因的。于是在我一次又一次的以为找到了答案，一次又一次的推翻答案中，揭开了真相的序幕。

不得不说，在加解密的插件开发过程中，我基本能把 mybatis 的代码背下来了，现在又排查了 ognl 表达式的 bug，我基本又能把 ognl 的流程背下来了。 说句实话，在找 bug 的时候，我一度都自我怀疑，甚至觉得反正只要升级 mybatis 就能解决问题，为什么要找呢，不如直接解决问题算了。 但是吧，人还是得有些追求，寻不到的真相总是让人惦记，排查不了的 bug 总是让人难受，还好我没放弃，最终才寻得了真相。