年年出妖事,一例由JSON解析导致的"薛定谔BUG"排查过程记录

前言

做开发这么多年,也碰到无数的bug了。不过再复杂的bug,只要仔细去研读代码,加上debug,总能找到原因。

但是最近公司内碰到的这一个bug,这个bug初看很简单,但是非常妖孽,在一段时间内我甚至是百思不得其解。在长达几天的时间内,复现的概率非常低。几乎难以抓住任何踪迹。

所以这篇文章就非常写实的来记录一下此Bug的发现和排查整个过程。

起因

同事之前做了个需求,提交测试。测试同事在测的一半的时候。发现了后台的一个报错

com.alibaba.fastjson.JSONException: can not cast to String, value : {"code":"00","msg":"成功","data":{这里是正确的数据}}
	at com.alibaba.fastjson.util.TypeUtils.castToInt(TypeUtils.java:564) ~[fastjson-1.2.29.jar:na]
	at com.alibaba.fastjson.serializer.IntegerCodec.deserialze(IntegerCodec.java:89) ~[fastjson-1.2.29.jar:na]

一看就知道这错很简单,就是一个fastjson的转换类型的报错。接受的json和要转化的类型不匹配造成的。基本上检查下代码,一眼就能解决的。

结果同事看了好一会儿,都没发现哪有问题。

然后远程在测试环境debug运行,打上断点准备调试,测试同事操作下来,却又好了。

然后释放断点,正常运行。操作一会,又出现了相同报错。

继续打上断点,还是正常。

这个现象把同事整的有点懵,我在群里看到这个,觉得这个现象很有趣,结果竟然依赖于是否观测,这什么鬼。。

我接过手看了下代码,我初步看下来也是完全没问题的。

代码我经过了精简和一些伪代码处理,如下所示:

public <T> T executeLua(String luaName, Class<T> c, Object... args){
	String json = 执行器.执行(luaName,args);
  log.info("执行结果为:{}",json);
  T resut = JSON.parseObject(json, c);
  return result;
}

调用的时候如此调用:

LuaResult result = executeLua("xxxx", LuaResult.class, args);

而返回对象的泛型T则是一个LuaResult对象,其结构也很简单:

public class LuaResult<T> {

	protected String code;

	protected String msg;

	protected T data;
  
  ...
}

根据打印出来的json结果来看,返回的数据是正确的结果,并且是完全匹配LuaResult对象这个结构的。虽然在调用的时候没加泛型,但是由于前面代码并用不到LuaResult里的data,所以解析出来依旧保留了JsonObject的类型。从运行的角度上来说,是完全没问题的。我也用本地的main方法用相同的数据跑了下,是完全能正常解析的。甚至于我在本地试了循环解析多次,多线程去解析,都是没问题的。

那为什么一到服务器环境就偶发性的报错呢。

我也决定远程debug下,我不相信会有薛定谔的bug这么一说。

我远程打上断点,测试同事开始做业务,一切完全正常。

于是我去掉断点,在没过多久后,测试同事给我发来了报错的截图。一切还真的和之前的同事如出一辙。。。

这下我也凌乱了,这么简单的报错,看不出问题也就罢了,还没法调试??而打出的日志返回的json字符串,又都完全是正常的业务返回数据。

太妖孽。

排查(一)

首先可以肯定的是返回数据是完全正确的,这点在日志打印的时候就可以看到。不存在低级失误,json不匹配返回类型这一说。

那问题很明显了,就是fastjson的解析问题,而项目使用的fastjson的版本相对较老,为1.2.29版本。

但是问题究竟在哪,本来很简单的错,但是在数据和结构都完全正确的情况下偶发性的报出,就显得很诡异了。

而且我根本就不相信在debug的时候恢复正常,在正常运行时就会有问题这种事实。

而且在接下来这个bug就像消失了一样,无论是debug启动还是正常启动,都不再出现了。

看到这,肯定会有人说,这还不简单。换个json解析框架,或是升级fastjson不就行了。

对于换框架来说,私下有和同事聊过换成jackson。首先系统内多处要改,其次即便换了,问题不再复现了。但对于问题而言,等于是绕过去了,而没有真正意义上正面去解决。而我本身对这个bug的根源非常感兴趣。所以不打算换,正面刚。

对于升级fastjson,其实有猜测过是因为fastjson的某些bug导致。但是得拿出证据,否则升级之后就算不复发,也不能证明是因为升级了fastjson而修复的,因为这个bug是极其偶发的。也就是说,还是得找到确定的根源问题。不能只依靠长时间的观测而去证明是否修复。

终于在一个偶然的机会,我在debug中终于断点捕捉到了一次。

这也就说明了,不存在薛定谔bug这么一说,至少我在观测时能捕捉到。

断点的地方在以下这个位置(部分业务数据做了一些改动)

//json为:{"code":"00","msg":"成功","data":{"xxx":21,"yyy":5}}
//c为LuaResult.class
T resut = JSON.parseObject(json, c);

用IDEA的Evaluate工具进行了查看执行结果

然后继续反复执行,大概在按几十次回车之后,终于出现了一个报错:

这就很诡异了有没有,同样的数据,同样的代码。执行几十次就出错了。

但是问题肯定是在fastjson这边了。接下去就是要破解这个问题的根源了。为了抓住这个原因,我还真舍不得马上升级。

排查(二)

之前说到过调用的时候并没有加泛型,于是我抱着试一试的想法,给这个调用加上了泛型,参数换成了TypeReference

LuaResult<Map<String,Object>> result = executeLua("xxxx", new TypeReference<LuaResult<Map<String,Object>>>(){}, args);

再去断点,通过Evaluate工具去诊断,点了有上百次,都没出现那个错。

那这样就确定应该是泛型引起的了。通过搜索相关关键字,找到了一篇关于fastjson关于对于泛型解析的文章。大致意思就是:fastjson对于那些没有定义明确泛型类型的相同对象,会默认使用上一次泛型的类型。也就是说,fastjson会对相同对象的前一次的泛型定义进行缓存。

这样,我就能大致理解这个妖孽bug的偶发原因了。

为此,我特地在本地写了一段代码来模拟这个bug的产生。

大家也可以复制到本地来运行下,fastjson版本要为1.2.29。

public static void main(String... args) throws Exception {
    try {
        String json = "{\"code\":\"00\",\"msg\":\"成功\",\"data\":{\"xxx\":21,\"yyy\":5}}";
        LuaResult result = JSON.parseObject(json, LuaResult.class);
        System.out.println(result);
    }catch (Exception e){
        log.error("出错了", e);
    }

    try {
        String json1 = "{\"msg\":\"成功\",\"data\":\"31\",\"code\":\"00\"}";
        LuaResult<Integer> result = JSON.parseObject(json1, new TypeReference<LuaResult<Integer>>(){});
        System.out.println(result);
    }catch (Exception e){
        log.error("出错了", e);
    }

 		//上面2个没问题,到执行第三段的时候,就会必现
    try {
        String json = "{\"code\":\"00\",\"msg\":\"成功\",\"data\":{\"xxx\":21,\"yyy\":5}}";
        LuaResult result = JSON.parseObject(json, LuaResult.class);
        System.out.println(result);
    }catch (Exception e){
        log.error("出错了", e);
    }
}

执行后出现报错:

有意思的是,只有三段代码是这个顺序的时候,才出错,把三段代码换个顺序,又正常了。

这下是一个必现的bug了。原形毕露!

由于项目使用的fastjson是1.2.29版本,我逐个版本升级,想知道到底是哪个版本会修复这个bug。在试到1.2.33版本时,这个bug终于没了。去github上找1.2.33这个版本的release信息,发现了作者修复了不使用参数泛型解析错误的issue。

结论

所以结论就是:这个薛定谔的bug就是因为fastjson在早期的版本中存在着对泛型解析的不严谨bug产生的。

既然都到这个程度了,那继续再深入研究发现,fastjson在1.2.33版本以下,对同一个对象的泛型存在着缓存现象。之前如果一直执行带泛型定义的LuaResult这是没问题的,如果前几个是带泛型的,后一个执行到不带泛型的,这就出现问题了。会按照上次缓存的泛型进行解析,由于前一次的泛型是Integer,所以不管这次json是什么数据,都会按照Integer类型去进行转换,所以就导致了can not cast to int这个错误。

至于为什么一开始,会出现类似于薛定谔的幻觉,现在也有了定论,这是因为测试同学的测试的顺序。正好debug的时候,没按照这个顺序执行,而正常运行的时候,是按照这个顺序执行的。我猜想这可能就是一个巧合。

知道了根源原因,修复起来只要升级到最新版本即可。

有人会觉得我绕了一大圈,直接升级就完事了。何必去究其原因。

一方面我觉得在技术上要严谨点,知其所以,更要知其所以然。二者我对这个如何产生的,抱有很大的兴趣(执念)。所以即便升级一个版本号就能解决,也要弄清楚来龙去脉。

如果大家喜欢类似的bug寻找过程的文章,也请在留言评论告诉我,我以后多安排一些。

我是铂赛东,一个有趣且有深度的开发,希望你关注我,在我的公号里,会分享技术以及开源相关的内容。也会分享点生活观。

posted @ 2022-05-07 11:57  铂赛东  阅读(1031)  评论(2编辑  收藏  举报