• 年年出妖事,一例由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寻找过程的文章,也请在留言评论告诉我,我以后多安排一些。

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

  • 相关阅读:
    常用集合之HashMap
    开发板TFTP调试
    【Flink】第一节 源码编译
    VSCODE中使用Vue3教程
    Pipeline aggregations管道聚合-Sibling-1
    `Target Support Files/Pods-Runner/Pods-Runner.debug.xcconfig`
    【80天学习完《深入理解计算机系统》】第十六天 4.2 Y86-64的顺序实现
    不讲武德!为击破苹果的“隐私高墙”,谷歌、Facebook 竟然“二打一”?
    Spring拦截器的简单应用
    「ETL趋势」FDL数据中心库/表查看和调试功能上线、数据源新增支持MongoDB写入
  • 原文地址:https://www.cnblogs.com/bryan31/p/16241900.html