CAT偶现NPE的问题

一、背景

咱们公司的调用链系统是基于大众点评的CAT客户端改造的，服务端彻底有本身设计开发的。在是用CAT客户端收集dubbo调用信息的时候，咱们发现了一个CAT偶现NPE的bug，该bug隐藏的很深，排查极其困难，致使了咱们公司4期线上故障，形成了很大的资产损失。
接下来让咱们看一下，这个NPE的发现与解决！！

二、问题描述

该问题最早发现于营销的应用，他们的发布以后马上一台机器出现cat-redis埋点的客户端大量抛NPE，表象是Cat.newTransaction()这行抛了NPE。当时花了1周排查无果，最终你们倾向于认为是jar包冲突。由于这个和jar包冲突很像，单机器，时有时没（jar包会被仲裁）！
第二次出现是在交易的应用中，也是应用刚发布就出现了NPE的问题，此次是表象是cat-redis埋点的客户端在Cat.newTransaction()过程当中出现了NPE，又引发了一块儿线上故障，形成了好几万的资产损失。。。

三、问题排查过程

重启了排查过程，此次必定要打破砂锅问到底！！！
排查回到原点，依然没有头绪，由于现象很简单就是m_producer为null，为何null，看初始化的过程就是一个SPI，并且是内存中加载的就想spring加载同样，不太多是初始化失败；可是有多是实例被destroy，也可能由于时序问题，先调用getProducer后去初始化。

由于不知道如何复现这个问题，只能硬着头皮在可疑的出现问题的地方打了几行日志，而后李文嘉同窗写了个python脚本不断在重启应用、kill应用、而后在重启。。。由于一次start/stop周期就要好几分钟，又正好周五打完收工！！！！

立刻又是忐忑的周一了，由于周末看代码仍是一点头绪都没有，不过好消息是咱们发现脚本不停start-stop过程当中（2000屡次重启）出现了24次同样的Cat.newTransaction的NPE现象，确实是个好消息。

可是问题是我和李文嘉同窗的采样都是错的，咱们打日志的面积又不够，因此消息是好的，线索仍是没有。接下来我一气呵成在snapshot版本中打满了日志，并且以CatNPE开头，保证grep出来都是本身想要的日志！！

打完包，脚本run起来，又等了一个晚上，次日早上来看日志，又有新的收获发现最开始不怀疑的地方setContainer方法报了NPE，可是问题为何throw RunTimeException 为何没抛出来了（被哪里catch了）。不过悲剧的是，我居然忘记在catch中打印异常堆栈了啊（智商不够用。。。）

因而又打包，脚本再run起来，又等了一个晚上，终于有一点收获了，定位到了包异常的位置，MessageIdFactory.initialize()方法中读取m_byteBuffer.getLong()的时候报错，java.nio.BufferUnderflowException 这个异常是意思是可读字节数不够，举例：buffer中的limit=cap=20, position=16,此时getLong读取8个字节，因为字节数不够(pos到limit之间只有4个字节)会出现BufferUnderflowException的异常

因而新的问题有来了，读取本身会报错，有的时候报错，多数时候正常呢？？？

最开始我怀疑是建立文件cat-appname.xml问题，由于建立文件可能会有权限问题，而后读取到了不完整的文件内容（当时严重怀疑这个）。因而在往这个方向找问题，可是交易的应用实在太笨重了，重启很麻烦。因而本身写了demo和脚本，打上日志不断的重启复现问题。正当我信心满满的时候，跑了2天脚本依然没有任何收获。。。因此打算放弃这条路。。。

期间和cat的做者吴其敏联系了一下，他怀疑是并发初始化问题

因而开始往线程并发方向开始找问题，期间把m_byteBuffer全部成员变量都输出来看，屡次debug发现pos的每条语句结束指都不太同样（有重大线程安全问题的嫌疑）；另外一个重大发现是debug的时候竟然有很高的几率复现问题，可是RUN的时候复现的几率低。。。。

pos     limit     cap
init        0        20      20
limit()     0        20      20
getInt()    4        20      20
getLong()   12       20      20

这个时候我严重怀疑是m_byteBuffer对象被多个线程操做了，因而找到了saveMask()有修改m_byteBuffer的（由于write方法会修改pos）。立刻Find Usages 马上发现有个异步线程在死循环的调用saveMask方法

这就能解释了为何debug的状况下有很大的几率能复现问题，由于main线程被断点了，异步run方法还能继续执行，调用saveMask方法能修改m_byteBuffer的position变量，而后主线程main初始化的时候pos被修改为了16，getLong读取8个字节接报错了！！！
不在debug环境下的时候，Main的初始化速度通常是能早于异步线程ChannelManager.run的执行完成，因此这就能解释大部分状况下是没有问题了！！！！
至此真相大白，全部的问题和现象都能解释的通了！！！！！！

2.2源码分析

MessageIdFactory.initialize()

public void initialize(String domain) throws IOException {
  ...... 省略其余代码
  m_markFile = new RandomAccessFile(mark, "rw");
  m_byteBuffer = m_markFile.getChannel().map(MapMode.READ_WRITE, 0, 20);
  if (m_byteBuffer.limit() > 0) {
    // 断点在此处，position变量很容易被异步线程修改掉，致使pos=16的时候，getLong就会报错BufferUnderflowException
    int index = m_byteBuffer.getInt();
    long lastTimestamp = m_byteBuffer.getLong();
    ....
  }
  saveMark();
}

ChannelManager.run

@Override
public void run() {
  while (m_active) {
    // 异步线程执行saveMark，会向m_byteBuffer中write值
    m_idfactory.saveMark();
    .....省略其余代码
  }
}

三、问题解决

3.1修改

这个bug 我以为并非线程安全问题，而是main线程初始化必定要先于异步线程。因此增长一个volatile init变量，在初始化完成以后修改init=true

m_markFile = new RandomAccessFile(mark, "rw");
m_byteBuffer = m_markFile.getChannel().map(MapMode.READ_WRITE, 0, 20);
if (m_byteBuffer.limit() > 0) {
  int index = m_byteBuffer.getInt();
  long lastTimestamp = m_byteBuffer.getLong();
}
saveMark();
m_init = true;

异步线程ChannelManager增长一个是否初始化完成的判断

public void run() {
  while (m_active) {
    // 增长是否初始的判断
    if(m_idfactory.isInit()){
      m_idfactory.saveMark();
      .....
   }
 }
}

四、开源回馈

本问题已经提交到cat官方issue和pr

issue
pr