生產環境一次詭異的空指標問題，竟然反轉了4次

蘇三說技術發表於2021-06-20

前言

公司為了保證系統的穩定性，加了很多監控，比如：介面響應時間、cpu使用率、記憶體使用率、錯誤日誌等等。如果系統出現異常情況，會郵件通知相關人員，以便於大家能在第一時間解決隱藏的系統問題。此外，我們這邊有個不成文的規定，就是線上問題最好能夠當日解決，除非遇到那種非常棘手的問題。

1.起因

有個週一的早上，我去公司上班，檢視郵件，收到我們老大轉發的一封郵件，讓我追查線上的一個NPE（NullPointException）問題。

郵件是通過sentry發出來的，我們通過點選郵件中的相關連結，可以直接跳轉到sentry的詳情頁面。在這個頁面中，展示了很多關鍵資訊，比如：操作時間、請求的介面、出錯的程式碼位置、報錯資訊、請求經過了哪些鏈路等等。真是居家旅行，查bug的良藥，有了這些，小case一眼就能查到原因。

我當時沒費吹灰之力，就訪問到了NPE的sentry報錯頁面（其實只用滑鼠雙擊一下就搞定）。果然上面有很多關鍵資訊，我一眼就看到了NPE的具體程式碼位置：

notify.setName(CurrentUser.getCurrent().getUserName());

劇情發展得如此順利，我都有點不好意思了。

最近無意間獲得一份BAT大廠大佬寫的刷題筆記，一下子打通了我的任督二脈，越來越覺得演算法沒有想象中那麼難了。

[BAT大佬寫的刷題筆記，讓我offer拿到手軟](這位BAT大佬寫的Leetcode刷題筆記，讓我offer拿到手軟)

根據類名和程式碼行號，我在idea中很快找到那行程式碼，不像是我寫的，這下可以放心不用背鍋了。於是接下來看了看那行的程式碼修改記錄，最後修改人是XXX。

什麼？是他？

他在一個月前已經離職了，看來這個無頭公案已經無從問起，只能自己查原因。

我當時內心的OS是：程式碼沒做相容處理。

為什麼這麼說呢？

這行程式碼其實很簡單，就是從當前使用者上下文中獲取使用者名稱稱，然後設定到notify實體的inUserName欄位上，最終notify的資料會儲存到資料庫。

該欄位表示那條推送通知的新增人，正常情況下沒啥卵用，主要是為了出現線上問題扯皮時，有個地方可以溯源。如果出現冤案，可以還你清白。

順便提一嘴，這裡說的推送通知跟mq中的訊息是兩回事，前者指的是websocket長連線推送的實時通知，我們這邊很多業務場景，在頁面功能操作完之後，會實時推送通知給指定使用者，以便使用者能夠及時處理相關單據，比如：您有一個審批單需要審批，請及時處理等。

CurrentUser內部包含了一個ThreadLocal物件，它負責儲存當前執行緒的使用者上下文資訊。當然為了保證線上程池中，也能從使用者上下文中獲取到正確的使用者資訊，這裡用了阿里的TransmittableThreadLocal。虛擬碼如下：

@Data
public class CurrentUser {
    private static final TransmittableThreadLocal<CurrentUser> THREA_LOCAL = new TransmittableThreadLocal<>();
    
    private String id;
    private String userName;
    private String password;
    private String phone;
    ...
    
    public statis void set(CurrentUser user) {
      THREA_LOCAL.set(user);
    }
    
    public static void getCurrent() {
      return THREA_LOCAL.get();
    }
}

這裡為什麼用了阿里的TransmittableThreadLocal，而不是普通的ThreadLocal呢？線上程池中，由於執行緒會被多次複用，導致從普通的ThreadLocal中無法獲取正確的使用者資訊。父執行緒中的引數，沒法傳遞給子執行緒，而TransmittableThreadLocal很好解決了這個問題。

然後在專案中定義一個全域性的spring mvc攔截器，專門設定使用者上下文到ThreadLocal中。虛擬碼如下：

public class UserInterceptor extends HandlerInterceptorAdapter {
   
   @Override  
   public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
      CurrentUser user = getUser(request);
      if(Objects.nonNull(user)) {
         CurrentUser.set(user);
      }
   } 
}

使用者在請求我們介面時，會先觸發該攔截器，它會根據使用者cookie中的token，呼叫呼叫介面獲取redis中的使用者資訊。如果能獲取到，說明使用者已經登入，則把使用者資訊設定到CurrentUser類的ThreadLocal中。

接下來，在api服務的下層，即business層的方法中，就能輕鬆通過CurrentUser.getCurrent();方法獲取到想要的使用者上下文資訊了。

這套使用者體系的想法是很good的，但深入使用後，發現了一個小插曲：

api服務和mq消費者服務都引用了business層，business層中的方法兩個服務都能直接呼叫。

我們都知道在api服務中使用者是需要登入的，而mq消費者服務則不需要登入。

如果business中的某個方法剛開始是給api開發的，在方法深處使用了CurrentUser.getCurrent();獲取使用者上下文。但後來，某位新來的帥哥在mq消費者中也呼叫了那個方法，並未發覺這個小機關，就會中招，出現找不到使用者上下文的問題。

所以我當時的第一個想法是：程式碼沒做相容處理，因為之前這類問題偶爾會發生一次。

想要解決這個問題，其實也很簡單。只需先判斷一下能否從CurrentUser中獲取使用者資訊，如果不能，則取配置的系統使用者資訊。虛擬碼如下：

@Autowired
private BusinessConfig businessConfig;

CurrentUser user = CurrentUser.getCurrent();
if(Objects.nonNull(user)) {
   entity.setUserId(user.getUserId());
   entity.setUserName(user.getUserName());
} else {
   entity.setUserId(businessConfig.getDefaultUserId());
   entity.setUserName(businessConfig.getDefaultUserName());
}

這種簡單無公害的程式碼，如果只是在一兩個地方加還OK。

但如果有多個地方都在獲取使用者資訊，難道在每個地方都需要把相同的判斷邏輯寫一遍？對於有追求的程式設計師來說，這種簡單的重複是寫程式碼的大忌，如何更優雅的解決問題呢？

答案將會在文章後面揭曉。

這個NPE問題表面上，已經有答案了。根據以往的經驗，由於在程式碼中沒有做相容處理，在mq消費者服務中獲取到的使用者資訊為空，對一個空物件，呼叫它的方法，就會出現NPE。

2.第一次反轉

但這個答案顯得有點草率，會不會還有什麼機關？

於是我在專案工程中全域性搜尋CurrentUser.set關鍵字，竟然真的找到了一個機關。

劇情出現第一次反轉。

有個地方寫了一個rocketmq的AOP攔截器，虛擬碼如下：

@Aspect
@Component
public class RocketMqAspect {

   @Pointcut("execution(* onMessage(..)&&@within(org.apache.rocketmq.spring.annotation.RocketMQMessageListener))")
   public void pointcut() {
   
   }
   ...

   @Around(value="pointcut")
   public void around(ProceedingJoinPoint point) throws Throwable {
      if(point.getArgs().length == 1 && point.getArgs()[0] instanceof MessageExt) {
         Message message = (Message)point.getArgs()[0];
         String userId = message.getUserProperty("userId");
         String userName = message.getUserProperty("userName");
         if(StringUtils.notEmpty(userId) && StringUtils.notEmpty(userName))  {
             CurrentUser user = new CurrentUser();
             user.setUserId(userId);
             user.setUserName(userName);
             CurrentUser.set(user);
         }
      }
      
      ...
   }
}

它會攔截所有mq消費者中的onMessage方法，在該方法執行之前，從userProperty中獲取使用者資訊，並且建立使用者物件，設定到使用者上下文中。

溫馨提醒一下，免得有些朋友依葫蘆畫瓢踩坑。上面的虛擬碼只給出了設定使用者上下文的關鍵程式碼，用完後，刪除使用者上下文的程式碼沒有給出，感興趣的朋友可以找我私聊。

既然有獲取使用者資訊的地方，我猜測必定有設定的地方。這時候突然發現自己有點當偵探的潛力，因為後面還真找到了。

意不意外，驚不驚喜？

另外一個同事自己自定義了一個RocketMQTemplate。虛擬碼如下：

public class MyRocketMQTemplate extends RocketMQTemplate {
    
    @Override
    public void asyncSend(String destnation, Meassage<?> message, SendCallback sendCallback, long timeout, int delayLevel) {
      
      MessageBuilder builder = withPayload(message.getPayLoad());
      CurrentUser user = CurrentUser.getCurrent();
      builder.setHeader("userId", user.getUserId());
      builder.setHeader("userName", user.getUserName());
      
      super.asyncSend(destnation,message,sendCallback,timeout,delayLevel);
    }
}

這段程式碼的主要作用是在mq生產者在傳送非同步訊息之前，先將當前使用者上下文資訊設定到mq訊息的header中，這樣在mq消費者中就能通過userProperty獲取到，它的本質也是從header中獲取到的。

這個設計比較巧妙，完美的解決了mq的消費者中通過CurrentUser.getCurrent();無法獲取使用者資訊的問題。

此時線索一下子斷了，沒有任何進展。

我再去查了一下伺服器的日誌。確認了那條有問題的mq訊息,它的header資訊中確實沒有userId和userName欄位。

莫非是mq生產者沒有往header中塞使用者資訊？這是需要重點懷疑的地方。

因為mq生產者是另外一個團隊寫的程式碼，在EOA（簽報系統）回撥他們系統時，會給我們發mq訊息，通知我們簽報狀態。

而EOA是第三方的系統，使用者體系沒有跟我們打通。所以在另外一個團隊的回撥介面中，沒法獲取當前登入的使用者資訊，AOP的攔截器就沒法自動往header中塞使用者資訊，這樣在mq的消費者中自然就獲取不到了。

這樣想來還真的是順理成章。

3.第二次反轉

但真的是這樣的嗎？

我們抱著很大的希望，給他們發了一封郵件，讓他們幫忙查一下問題。

很快，他們回郵件了。

但他們說：已經本地測試過，功能正常。

就這樣劇情第二次反轉了。

我此時有點好奇，他們是怎麼往header中塞使用者資訊的。帶著“學習的心態”，於是找他們一起檢視了相關程式碼。

他們在傳送mq訊息之前，會呼叫一個UserUtil工具注入使用者。該工具類的虛擬碼如下：

@Component
public class UserUtil{
    @Value("${susan.userId}")
    private String userId;

    @Value("${susan.userName}")
    private String userName;

    public void injectUser() {
        CurrentUser user = new CurrentUser();
        user.setUserId(userId);
        user.setUserName(userName);
        CurrentUser.set(user);
    }
}

好吧，不得不承認，這樣做確實可以解決header傳入使用者資訊的問題，比之前需要手動判斷使用者資訊是否為空要優雅得多，因為注入之後的使用者資訊肯定是不為空的。

折騰了半天，NPE問題還是沒有著落。

我回頭再仔細看了那個自定義的RocketMQTemplate類，發現裡面重寫的方法：asyncSend，它包含了5個引數。而他們在給我們推訊息時，呼叫的asyncSend卻只傳了3個引數。

一下子，問題又有了新的進展，有沒有可能是他們調錯介面了？

原本應該呼叫5個引數的方法，但實際上他們呼叫了3個引數的方法。

這樣就能解釋通了。

4.第三次反轉

終於有點思路，我帶著一份喜悅，準備開始證明剛剛的猜測。

但事實證明，我真的高興的太早了，馬上被啪啪打臉。

這次是反轉最快的一次。

怎麼回事呢？

原本我以為是另外一個團隊的人，在發mq訊息時調錯方法了，應該呼叫5個引數的asyncSend方法，但他們的程式碼中實際上呼叫的是3個引數的同名方法。

為了防止出現冤枉同事的事情發生。我本著盡職盡責的態度，仔細看了看RocketMQTemplate類的所有方法，這個類是rocketmq框架提供的。

意外發現了一些藕斷絲連的關係，虛擬碼如下：

public void asyncSend(String destination, Message<?> message, SendCallback sendCallback, long timeout, int delayLevel) {
  if (Objects.isNull(message) || Objects.isNull(message.getPayload())) {
      log.error("asyncSend failed. destination:{}, message is null ", destination);
      throw new IllegalArgumentException("`message` and `message.payload` cannot be null");
    }

    try {
        org.apache.rocketmq.common.message.Message rocketMsg = RocketMQUtil.convertToRocketMessage(objectMapper,
            charset, destination, message);
        if (delayLevel > 0) {
            rocketMsg.setDelayTimeLevel(delayLevel);
        }
        producer.send(rocketMsg, sendCallback, timeout);
    } catch (Exception e) {
        log.info("asyncSend failed. destination:{}, message:{} ", destination, message);
        throw new MessagingException(e.getMessage(), e);
    }
}
    

public void asyncSend(String destination, Message<?> message, SendCallback sendCallback, long timeout) {
    asyncSend(destination,message,sendCallback,timeout,0);
}

public void asyncSend(String destination, Message<?> message, SendCallback sendCallback) {
    asyncSend(destination, message, sendCallback, producer.getSendMsgTimeout());
}

public void asyncSend(String destination, Object payload, SendCallback sendCallback, long timeout) {
     Message<?> message = this.doConvert(payload, null, null);
     asyncSend(destination, message, sendCallback, timeout);
}

public void asyncSend(String destination, Object payload, SendCallback sendCallback) {
    asyncSend(destination, payload, sendCallback, producer.getSendMsgTimeout());
}

這個背後隱藏著一個天大的祕密，這些同名的方法殊途同歸，竟然最終都會呼叫5個引數的asyncSend方法。

這樣看來，如果在子類中重寫了5個的asyncSend方法，相當於重寫了所有的asyncSend方法。再次證明他們沒錯。

溫馨提醒一下，有些類的過載方法會相互呼叫，如果在子類中重新了最底層的那個過載方法，等於把所有的過載方法都重寫了。

頭疼，又要回到原點了。

5.第四次反轉

此時，我有點迷茫了。

不過，有個好習慣是：遇到線上問題不知道怎辦時，會多查一下日誌。

本來不報啥希望的，但是沒想到通過再查日誌。

出現了第四次反轉。

這次抱著試一下的心態，根據messageID去查了mq生產者的日誌，查到了一條訊息的傳送日誌。

這次眼睛擦得雪亮，發現了一個小細節：時間不對。

這條日誌顯示的訊息傳送日期是2021-05-21，而實際上mq消費者處理的日期是2021-05-28。

這條訊息一個星期才消費完？

顯然不是。

我有點肅然起敬了。再回去用那個messageID查了mq消費者的日誌，發現裡面其實消費了6次訊息。前5次竟然是同一天，都在2021-05-21，而且都處理失敗了。另一次是2021-05-28，處理成功了。

為什麼同一條訊息，會在同一天消費5次？

如果你對rocketmq比較熟悉的話，肯定知道它支援重試機制。

如果mq消費者訊息處理失敗了，可以在業務程式碼中拋一個異常。然後框架層面捕獲該異常返回ConsumeConcurrentlyStatus.RECONSUME_LATER，rocketmq會自動將該訊息放到重試佇列。

流程圖如下：

這樣mq消費者下次可以重新消費那條訊息，直到達到一定次數（這裡我們配置的5次），rocketmq會將那條訊息傳送到死信佇列。

流程圖如下：

後面就不再消費了。

最後為什麼會多消費一次？

最後的那條訊息不可能是其他的mq生產者發出的，因為messageID是唯一的，其他的生產者不可能產生一樣的messageID。

那麼接下來，只有一種可能，那就是人為發了條訊息。

查線上日誌時，時間、messageID、traceID、記錄條數這幾個維度至關重要。

6.真相

後來發現還真的是人為發的訊息。

一週前，線上有個使用者，由於EOA頁面回撥介面失敗（重試也失敗），導致稽核狀態變更失敗。該稽核單在EOA系統中審批通過了，但mq消費者去處理該稽核單的時候，發現狀態還是待稽核，就直接返回了，沒有走完後續的流程，從而導致該稽核單資料資料異常。

為了修復這個問題，我們當時先修改了線上該稽核單的狀態。接下來，手動的在rocketmq後臺發了條訊息。由於當時在rocketmq後臺看不到header資訊，所以發訊息時沒有管header，直接往指定的topic中發訊息了。

千萬注意，大家在手動發mq訊息時，一定要注意header中是否也需要設定相關引數，尤其是rocketmq，不然就可能會出問題。

mq消費者消費完那條訊息之後，該稽核單正常走完了流程，當時找測試一起測試過，資料庫的狀態都是正常的。

大家都以為沒有問題了，但是所有人都忽略了一個小細節：就是在正常業務邏輯處理完之後，會發websocket通知給指定使用者。但這個功能是已經離職的那個同事加的新邏輯，其他人都不知道。站在手動發訊息的那個人的角度來說，他沒錯，因為他根本不知道新功能的存在。

由於這行程式碼是最後一行程式碼，並且跟之前的程式碼不在同一個事物當中，即使出了問題也不會影響正常的業務邏輯。

所以這個NPE問題影響範圍很小，只是那個商戶沒有收到某個通知而已。

有個好習慣，就是把跟核心業務邏輯無關的程式碼，放在事務之外，防止出現問題時，影響主流程。

說實話，有時候遇到線上問題，對於我們來說未必是一件壞事。通過這次線上問題定位，讓我熟悉了公司更多新功能，學習了其他同事的一些好的思想，總結了一些經驗和教訓，是一次難得的提升自己的好機會。