【线上生产事故系列】定位生产问题思路-部分还款业务报空指针异常

【线上生产事故系列】定位生产问题思路-部分还款业务报空指针异常

定位生产问题思路-部分还款业务报空指针异常

一、 问题背景

整个服务异常维持时间:
14:48:49.771 -16:22;直到运维重启服务之后,得以恢复正常;
现象:
还款收单一共两台机器,仅119出现服务异常;
外部调用还款收单119机器,均能够正常进入;
还款收单119机器,调用外部api,在整个事故过程中,均抛出异常;
异常信息极其简单“restExchangeMap失败:null”,没有完整的错误栈信息;

二、 寻找完整错误栈信息

通过阅读代码,在寻找完整的错误栈信息过程中,发现几点问题:
1、 在catch异常的过程中,没有输出完整的错误栈信息(如果考虑日志性能的问题,请捕获已知的异常,简化输出,未知异常,请一定输出完整错误栈信息);
image.png
2、在通用的controller中发现有捕获全局异常,但是下面这样的日志输出,并不能够输出完整错误栈信息;
image.png
3、通过查阅代码,发现有三处通过aop方式,进行拦截的输出,里面有异常输出;但是完整错误栈信息,并不会出现在elk中;
image.png
4、历时两天,终于寻找到了完整的错误栈信息
image.png
三 Bug猜想

1、通过错误栈信息得出的bug的表象原因

Spring RestTemplate源码的信息转换器list包含了null,导致了NPE的发生。
image.png
2、 什么导致了MessageConverters中包含了null

通过一顿翻源码,找到了两处可疑代码块:
可疑代码块1:
image.png
可疑代码块2:
image.png
代码块1:
只有在程序启动的时候执行一次,赋值很明确,list只有一个元素,启动过程不存在并发问题,因此不可能导致list出现null元素;
代码块2:
这段代码会在具体功能执行过程中,反复执行。在
restTemplate.setMessageConverters(messageConverters);
这个一行内部存在并发问题,从而messageConverters带入了null;关于并发产生null数据的问题,请仔细阅读下面的代码和注释。
image.png

//存在并发的代码块
@Override
public void setMessageConverters(List<HttpMessageConverter<?>> messageConverters) {
    Assert.notEmpty(messageConverters, "At least one HttpMessageConverter required");
    // Take getMessageConverters() List as-is when passed in here
    if (getMessageConverters() != messageConverters) {
        //把数组元素全部设置为null,同时size=0
        getMessageConverters().clear();
        //把新的list,放入到messageConverters中
        getMessageConverters().addAll(messageConverters);
    }
}
/**
 * Removes all of the elements from this list.  The list will
 * be empty after this call returns.
 */
public void clear() {
    modCount++;

    // clear to let GC do its work
    for (int i = 0; i < size; i++)
        elementData[i] = null;

    size = 0;
}

//ArrayList并不是安全的,存在并发的代码块
public boolean addAll(Collection<? extends E> c) {
    Object[] a = c.toArray();
    //numNew为1
    int numNew = a.length;
    //确定数组大小足够,不行就行扩容了(扩容的可能性为零);
    ensureCapacityInternal(size + numNew);
    //把新的a数组,从0开始,拷贝到elementData中
    //大部分情况下,size=0;numNew=1;其中size存在并发操作可能性;
    //在并发的过程中,arraycopy和size += numNew,会导致size>=1,numNew=1;
//从而导致elementData[0]=null,elementData[i]=hashcode
    System.arraycopy(a, 0, elementData, size, numNew);
    //messageConverters的size累加
    size += numNew;
    return numNew != 0;
}

3、 完美证据

如果bug猜想没有问题,那么1.3.2的出现一次,如果代码2在再执行一次,那么服务异常的时间将是短暂的,不会维持较长时间。
通过代码分析, “调用贷后管理系统还款接口请求参数”关键日志在elk的输出,可以得知代码块2的执行时间:
在14:47执行之后没有出现过,一直到16:30之后再次出现(如果小龙16:22分不重启机器,该问题大概率会自行恢复)。
image.png
4、 不规范的使用

image.png
关于restTempale属性的初始化,不应当出现在业务代码中,应出现在config中,如果一定要有,请考虑数据安全问题。
四、 优化要求

image.png
1,com.xxx:util:2.0.37公共包存在使用风险问题,容易诱导开发不正确的使用;请排查AbstractRest.exchange的调用,尽快替换掉;
2,restTempale属性的初始化,是否放在config阶段了呢?如果没有,请通读全文,避免类似的NPE问题;
3,请分析目前收单系统中异常日志的输出,在未知异常,请确保完整错误栈的输出;(梳理清楚,排期上线)
4,请开发协助复现该问题(复现该问题了,提供优化方案,尽快上线)
复现步骤:
messageConvers中制造null数据;

public boolean addAll(Collection<? extends E> c) {
        Object[] a = c.toArray();
        int numNew = a.length;
        ensureCapacityInternal(size + numNew);  // Increments modCount
        System.arraycopy(a, 0, elementData, size, numNew);//
        size += numNew;//在这两行代码增加随机等待时间,制造并发问题;

        return numNew != 0;
    }

1步处理成功之后,调用api接口(需要调用第三方api的那种),将均出现NPE异常
复现结果:
image.png
五、总结
问题原因:调用eureka使用的老方法在并发时存在问题,可能会小概率的将messageConverter修改为null,影响公共调用eureka的方法全部异常。
应急措施:重启应用解决。
根本解决方案:全部修改为新的调用方法,将messageConverter在初始化赋值,不会再修改。
改进措施:检查其他应用调用eureka方法的使用,如果存在老的调用方式,应全部修改为新的调用方法,将messageConverter在初始化赋值,不会再修改。