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