生產(chǎn)環(huán)境一次詭異的NPE問(wèn)題，反轉(zhuǎn)了4次

大家好，我是蘇三，又跟大家見面了。

前言

公司為了保證系統(tǒng)的穩(wěn)定性，加了很多監(jiān)控，比如：接口響應(yīng)時(shí)間、cpu使用率、內(nèi)存使用率、錯(cuò)誤日志等等。如果系統(tǒng)出現(xiàn)異常情況，會(huì)郵件通知相關(guān)人員，以便于大家能在第一時(shí)間解決隱藏的系統(tǒng)問(wèn)題。此外，我們這邊有個(gè)不成文的規(guī)定，就是線上問(wèn)題最好能夠當(dāng)日解決，除非遇到那種非常棘手的問(wèn)題。

1.起因

有個(gè)周一的早上，我去公司上班，查看郵件，收到我們老大轉(zhuǎn)發(fā)的一封郵件，讓我追查線上的一個(gè)NPE（NullPointException）問(wèn)題。

郵件是通過(guò)sentry發(fā)出來(lái)的，我們通過(guò)點(diǎn)擊郵件中的相關(guān)鏈接，可以直接跳轉(zhuǎn)到sentry的詳情頁(yè)面。在這個(gè)頁(yè)面中，展示了很多關(guān)鍵信息，比如：操作時(shí)間、請(qǐng)求的接口、出錯(cuò)的代碼位置、報(bào)錯(cuò)信息、請(qǐng)求經(jīng)過(guò)了哪些鏈路等等。真是居家旅行，查bug的良藥，有了這些，小case一眼就能查到原因。

我當(dāng)時(shí)沒(méi)費(fèi)吹灰之力，就訪問(wèn)到了NPE的sentry報(bào)錯(cuò)頁(yè)面（其實(shí)只用鼠標(biāo)雙擊一下就搞定）。果然上面有很多關(guān)鍵信息，我一眼就看到了NPE的具體代碼位置：

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

劇情發(fā)展得如此順利，我都有點(diǎn)不好意思了。

根據(jù)類名和代碼行號(hào)，我在idea中很快找到那行代碼，不像是我寫的，這下可以放心不用背鍋了。于是接下來(lái)看了看那行的代碼修改記錄，最后修改人是XXX。

什么？是他？

他在一個(gè)月前已經(jīng)離職了，看來(lái)這個(gè)無(wú)頭公案已經(jīng)無(wú)從問(wèn)起，只能自己查原因。

我當(dāng)時(shí)內(nèi)心的OS是：代碼沒(méi)做兼容處理。

為什么這么說(shuō)呢？

這行代碼其實(shí)很簡(jiǎn)單，就是從當(dāng)前用戶上下文中獲取用戶名稱，然后設(shè)置到notify實(shí)體的inUserName字段上，最終notify的數(shù)據(jù)會(huì)保存到數(shù)據(jù)庫(kù)。

該字段表示那條推送通知的添加人，正常情況下沒(méi)啥卵用，主要是為了出現(xiàn)線上問(wèn)題扯皮時(shí)，有個(gè)地方可以溯源。如果出現(xiàn)冤案，可以還你清白。

順便提一嘴，這里說(shuō)的推送通知跟mq中的消息是兩回事，前者指的是websocket長(zhǎng)連接推送的實(shí)時(shí)通知，我們這邊很多業(yè)務(wù)場(chǎng)景，在頁(yè)面功能操作完之后，會(huì)實(shí)時(shí)推送通知給指定用戶，以便用戶能夠及時(shí)處理相關(guān)單據(jù)，比如：您有一個(gè)審批單需要審批，請(qǐng)及時(shí)處理等。

CurrentUser內(nèi)部包含了一個(gè)ThreadLocal對(duì)象，它負(fù)責(zé)保存當(dāng)前線程的用戶上下文信息。當(dāng)然為了保證在線程池中，也能從用戶上下文中獲取到正確的用戶信息，這里用了阿里的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呢？在線程池中，由于線程會(huì)被多次復(fù)用，導(dǎo)致從普通的ThreadLocal中無(wú)法獲取正確的用戶信息。父線程中的參數(shù)，沒(méi)法傳遞給子線程，而TransmittableThreadLocal很好解決了這個(gè)問(wèn)題。

然后在項(xiàng)目中定義一個(gè)全局的spring mvc攔截器，專門設(shè)置用戶上下文到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);
      }
   } 
}

用戶在請(qǐng)求我們接口時(shí)，會(huì)先觸發(fā)該攔截器，它會(huì)根據(jù)用戶cookie中的token，調(diào)用調(diào)用接口獲取redis中的用戶信息。如果能獲取到，說(shuō)明用戶已經(jīng)登錄，則把用戶信息設(shè)置到CurrentUser類的ThreadLocal中。

接下來(lái)，在api服務(wù)的下層，即business層的方法中，就能輕松通過(guò)CurrentUser.getCurrent();方法獲取到想要的用戶上下文信息了。

這套用戶體系的想法是很good的，但深入使用后，發(fā)現(xiàn)了一個(gè)小插曲：

api服務(wù)和mq消費(fèi)者服務(wù)都引用了business層，business層中的方法兩個(gè)服務(wù)都能直接調(diào)用。

我們都知道在api服務(wù)中用戶是需要登錄的，而mq消費(fèi)者服務(wù)則不需要登錄。

如果business中的某個(gè)方法剛開始是給api開發(fā)的，在方法深處使用了CurrentUser.getCurrent();獲取用戶上下文。但后來(lái)，某位新來(lái)的帥哥在mq消費(fèi)者中也調(diào)用了那個(gè)方法，并未發(fā)覺這個(gè)小機(jī)關(guān)，就會(huì)中招，出現(xiàn)找不到用戶上下文的問(wèn)題。

所以我當(dāng)時(shí)的第一個(gè)想法是：代碼沒(méi)做兼容處理，因?yàn)橹斑@類問(wèn)題偶爾會(huì)發(fā)生一次。

想要解決這個(gè)問(wèn)題，其實(shí)也很簡(jiǎn)單。只需先判斷一下能否從CurrentUser中獲取用戶信息，如果不能，則取配置的系統(tǒng)用戶信息。偽代碼如下：

@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());
}

這種簡(jiǎn)單無(wú)公害的代碼，如果只是在一兩個(gè)地方加還OK。

但如果有多個(gè)地方都在獲取用戶信息，難道在每個(gè)地方都需要把相同的判斷邏輯寫一遍？對(duì)于有追求的程序員來(lái)說(shuō)，這種簡(jiǎn)單的重復(fù)是寫代碼的大忌，如何更優(yōu)雅的解決問(wèn)題呢？

答案將會(huì)在文章后面揭曉。

這個(gè)NPE問(wèn)題表面上，已經(jīng)有答案了。根據(jù)以往的經(jīng)驗(yàn)，由于在代碼中沒(méi)有做兼容處理，在mq消費(fèi)者服務(wù)中獲取到的用戶信息為空，對(duì)一個(gè)空對(duì)象，調(diào)用它的方法，就會(huì)出現(xiàn)NPE。

2.第一次反轉(zhuǎn)

但這個(gè)答案顯得有點(diǎn)草率，會(huì)不會(huì)還有什么機(jī)關(guān)？

于是我在項(xiàng)目工程中全局搜索CurrentUser.set關(guān)鍵字，竟然真的找到了一個(gè)機(jī)關(guān)。

劇情出現(xiàn)第一次反轉(zhuǎn)。

有個(gè)地方寫了一個(gè)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);
         }
      }
      
      ...
   }
}

它會(huì)攔截所有mq消費(fèi)者中的onMessage方法，在該方法執(zhí)行之前，從userProperty中獲取用戶信息，并且創(chuàng)建用戶對(duì)象，設(shè)置到用戶上下文中。

溫馨提醒一下，免得有些朋友依葫蘆畫瓢踩坑。上面的偽代碼只給出了設(shè)置用戶上下文的關(guān)鍵代碼，用完后，刪除用戶上下文的代碼沒(méi)有給出，感興趣的朋友可以找我私聊。

既然有獲取用戶信息的地方，我猜測(cè)必定有設(shè)置的地方。這時(shí)候突然發(fā)現(xiàn)自己有點(diǎn)當(dāng)偵探的潛力，因?yàn)楹竺孢€真找到了。

意不意外，驚不驚喜？

另外一個(gè)同事自己自定義了一個(gè)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生產(chǎn)者在發(fā)送異步消息之前，先將當(dāng)前用戶上下文信息設(shè)置到mq消息的header中，這樣在mq消費(fèi)者中就能通過(guò)userProperty獲取到，它的本質(zhì)也是從header中獲取到的。

這個(gè)設(shè)計(jì)比較巧妙，完美的解決了mq的消費(fèi)者中通過(guò)CurrentUser.getCurrent();無(wú)法獲取用戶信息的問(wèn)題。

此時(shí)線索一下子斷了，沒(méi)有任何進(jìn)展。

我再去查了一下服務(wù)器的日志。確認(rèn)了那條有問(wèn)題的mq消息,它的header信息中確實(shí)沒(méi)有userId和userName字段。

莫非是mq生產(chǎn)者沒(méi)有往header中塞用戶信息？這是需要重點(diǎn)懷疑的地方。

因?yàn)閙q生產(chǎn)者是另外一個(gè)團(tuán)隊(duì)寫的代碼，在EOA（簽報(bào)系統(tǒng)）回調(diào)他們系統(tǒng)時(shí)，會(huì)給我們發(fā)mq消息，通知我們簽報(bào)狀態(tài)。

而EOA是第三方的系統(tǒng)，用戶體系沒(méi)有跟我們打通。所以在另外一個(gè)團(tuán)隊(duì)的回調(diào)接口中，沒(méi)法獲取當(dāng)前登錄的用戶信息，AOP的攔截器就沒(méi)法自動(dòng)往header中塞用戶信息，這樣在mq的消費(fèi)者中自然就獲取不到了。

這樣想來(lái)還真的是順理成章。

3.第二次反轉(zhuǎn)

但真的是這樣的嗎？

我們抱著很大的希望，給他們發(fā)了一封郵件，讓他們幫忙查一下問(wèn)題。

很快，他們回郵件了。

但他們說(shuō)：已經(jīng)本地測(cè)試過(guò)，功能正常。

就這樣劇情第二次反轉(zhuǎn)了。

我此時(shí)有點(diǎn)好奇，他們是怎么往header中塞用戶信息的。帶著“學(xué)習(xí)的心態(tài)”，于是找他們一起查看了相關(guān)代碼。

他們?cè)诎l(fā)送mq消息之前，會(huì)調(diào)用一個(gè)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);
    }
}

好吧，不得不承認(rèn)，這樣做確實(shí)可以解決header傳入用戶信息的問(wèn)題，比之前需要手動(dòng)判斷用戶信息是否為空要優(yōu)雅得多，因?yàn)樽⑷胫蟮挠脩粜畔⒖隙ㄊ遣粸榭盏摹?/p>

折騰了半天，NPE問(wèn)題還是沒(méi)有著落。

我回頭再仔細(xì)看了那個(gè)自定義的RocketMQTemplate類，發(fā)現(xiàn)里面重寫的方法：asyncSend，它包含了5個(gè)參數(shù)。而他們?cè)诮o我們推消息時(shí)，調(diào)用的asyncSend卻只傳了3個(gè)參數(shù)。

一下子，問(wèn)題又有了新的進(jìn)展，有沒(méi)有可能是他們調(diào)錯(cuò)接口了？

原本應(yīng)該調(diào)用5個(gè)參數(shù)的方法，但實(shí)際上他們調(diào)用了3個(gè)參數(shù)的方法。

這樣就能解釋通了。

4.第三次反轉(zhuǎn)

終于有點(diǎn)思路，我?guī)е环菹矏?，?zhǔn)備開始證明剛剛的猜測(cè)。

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

這次是反轉(zhuǎn)最快的一次。

怎么回事呢？

原本我以為是另外一個(gè)團(tuán)隊(duì)的人，在發(fā)mq消息時(shí)調(diào)錯(cuò)方法了，應(yīng)該調(diào)用5個(gè)參數(shù)的asyncSend方法，但他們的代碼中實(shí)際上調(diào)用的是3個(gè)參數(shù)的同名方法。

為了防止出現(xiàn)冤枉同事的事情發(fā)生。我本著盡職盡責(zé)的態(tài)度，仔細(xì)看了看RocketMQTemplate類的所有方法，這個(gè)類是rocketmq框架提供的。

意外發(fā)現(xiàn)了一些藕斷絲連的關(guān)系，偽代碼如下：

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());
}

這個(gè)背后隱藏著一個(gè)天大的秘密，這些同名的方法殊途同歸，竟然最終都會(huì)調(diào)用5個(gè)參數(shù)的asyncSend方法。

這樣看來(lái)，如果在子類中重寫了5個(gè)的asyncSend方法，相當(dāng)于重寫了所有的asyncSend方法。再次證明他們沒(méi)錯(cuò)。

溫馨提醒一下，有些類的重載方法會(huì)相互調(diào)用，如果在子類中重新了最底層的那個(gè)重載方法，等于把所有的重載方法都重寫了。

頭疼，又要回到原點(diǎn)了。

5.第四次反轉(zhuǎn)

此時(shí)，我有點(diǎn)迷茫了。

不過(guò)，有個(gè)好習(xí)慣是：遇到線上問(wèn)題不知道怎辦時(shí)，會(huì)多查一下日志。

本來(lái)不報(bào)啥希望的，但是沒(méi)想到通過(guò)再查日志。

出現(xiàn)了第四次反轉(zhuǎn)。

這次抱著試一下的心態(tài)，根據(jù)messageID去查了mq生產(chǎn)者的日志，查到了一條消息的發(fā)送日志。

這次眼睛擦得雪亮，發(fā)現(xiàn)了一個(gè)小細(xì)節(jié)：時(shí)間不對(duì)。

這條日志顯示的消息發(fā)送日期是2021-05-21，而實(shí)際上mq消費(fèi)者處理的日期是2021-05-28。

這條消息一個(gè)星期才消費(fèi)完？

顯然不是。

我有點(diǎn)肅然起敬了。再回去用那個(gè)messageID查了mq消費(fèi)者的日志，發(fā)現(xiàn)里面其實(shí)消費(fèi)了6次消息。前5次竟然是同一天，都在2021-05-21，而且都處理失敗了。另一次是2021-05-28，處理成功了。

為什么同一條消息，會(huì)在同一天消費(fèi)5次？

如果你對(duì)rocketmq比較熟悉的話，肯定知道它支持重試機(jī)制。

如果mq消費(fèi)者消息處理失敗了，可以在業(yè)務(wù)代碼中拋一個(gè)異常。然后框架層面捕獲該異常返回ConsumeConcurrentlyStatus.RECONSUME_LATER，rocketmq會(huì)自動(dòng)將該消息放到重試隊(duì)列。流程圖如下：這樣mq消費(fèi)者下次可以重新消費(fèi)那條消息，直到達(dá)到一定次數(shù)（這里我們配置的5次），rocketmq會(huì)將那條消息發(fā)送到死信隊(duì)列。流程圖如下：后面就不再消費(fèi)了。

最后為什么會(huì)多消費(fèi)一次？

最后的那條消息不可能是其他的mq生產(chǎn)者發(fā)出的，因?yàn)閙essageID是唯一的，其他的生產(chǎn)者不可能產(chǎn)生一樣的messageID。

那么接下來(lái)，只有一種可能，那就是人為發(fā)了條消息。

查線上日志時(shí)，時(shí)間、messageID、traceID、記錄條數(shù) 這幾個(gè)維度至關(guān)重要。

6.真相

后來(lái)發(fā)現(xiàn)還真的是人為發(fā)的消息。

一周前，線上有個(gè)用戶，由于EOA頁(yè)面回調(diào)接口失?。ㄖ卦囈彩。?，導(dǎo)致審核狀態(tài)變更失敗。該審核單在EOA系統(tǒng)中審批通過(guò)了，但mq消費(fèi)者去處理該審核單的時(shí)候，發(fā)現(xiàn)狀態(tài)還是待審核，就直接返回了，沒(méi)有走完后續(xù)的流程，從而導(dǎo)致該審核單數(shù)據(jù)數(shù)據(jù)異常。

為了修復(fù)這個(gè)問(wèn)題，我們當(dāng)時(shí)先修改了線上該審核單的狀態(tài)。接下來(lái)，手動(dòng)的在rocketmq后臺(tái)發(fā)了條消息。由于當(dāng)時(shí)在rocketmq后臺(tái)看不到header信息，所以發(fā)消息時(shí)沒(méi)有管header，直接往指定的topic中發(fā)消息了。

千萬(wàn)注意，大家在手動(dòng)發(fā)mq消息時(shí)，一定要注意header中是否也需要設(shè)置相關(guān)參數(shù)，尤其是rocketmq，不然就可能會(huì)出問(wèn)題。

mq消費(fèi)者消費(fèi)完那條消息之后，該審核單正常走完了流程，當(dāng)時(shí)找測(cè)試一起測(cè)試過(guò)，數(shù)據(jù)庫(kù)的狀態(tài)都是正常的。

大家都以為沒(méi)有問(wèn)題了，但是所有人都忽略了一個(gè)小細(xì)節(jié)：就是在正常業(yè)務(wù)邏輯處理完之后，會(huì)發(fā)websocket通知給指定用戶。但這個(gè)功能是已經(jīng)離職的那個(gè)同事加的新邏輯，其他人都不知道。站在手動(dòng)發(fā)消息的那個(gè)人的角度來(lái)說(shuō)，他沒(méi)錯(cuò)，因?yàn)樗静恢佬鹿δ艿拇嬖凇?/p>

由于這行代碼是最后一行代碼，并且跟之前的代碼不在同一個(gè)事物當(dāng)中，即使出了問(wèn)題也不會(huì)影響正常的業(yè)務(wù)邏輯。

所以這個(gè)NPE問(wèn)題影響范圍很小，只是那個(gè)商戶沒(méi)有收到某個(gè)通知而已。

有個(gè)好習(xí)慣，就是把跟核心業(yè)務(wù)邏輯無(wú)關(guān)的代碼，放在事務(wù)之外，防止出現(xiàn)問(wèn)題時(shí)，影響主流程。

說(shuō)實(shí)話，有時(shí)候遇到線上問(wèn)題，對(duì)于我們來(lái)說(shuō)未必是一件壞事。通過(guò)這次線上問(wèn)題定位，讓我熟悉了公司更多新功能，學(xué)習(xí)了其他同事的一些好的思想，總結(jié)了一些經(jīng)驗(yàn)和教訓(xùn)，是一次難得的提升自己的好機(jī)會(huì)。

最后說(shuō)一句(求關(guān)注，別白嫖我)

碼字不易，且行且珍惜。你的認(rèn)同是我堅(jiān)持的最大動(dòng)力，求一鍵三連：點(diǎn)贊、轉(zhuǎn)發(fā)、在看。

關(guān)注公眾號(hào)：【蘇三說(shuō)技術(shù)】，在公眾號(hào)中回復(fù)：面試、代碼神器、開發(fā)手冊(cè)、時(shí)間管理有超贊的粉絲福利，另外回復(fù)：加群，可以跟很多BAT大廠的前輩交流和學(xué)習(xí)。