生產環境一次詭異的空指標問題,竟然反轉了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();方法獲取到想要的使用者上下文資訊了。圖片

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

 

 

 

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

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

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

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

 

 

 

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

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

 

 

 

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

想要解決這個問題,其實也很簡單。只需先判斷一下能否從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關鍵字,竟然真的找到了一個機關。

劇情出現第一次反轉。

有個地方寫了一個rocketmqAOP攔截器,虛擬碼如下:

@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中獲取到的。

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

 

 

 

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

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

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

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

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

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

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

 

 

 

圖片

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

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傳入使用者資訊的問題,比之前需要手動判斷使用者資訊是否為空要優雅得多,因為注入之後的使用者資訊肯定是不為空的。生產環境一次詭異的空指標問題,竟然反轉了4次

 

 

 

圖片

折騰了半天,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方法。

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

 

 

 

這樣看來,如果在子類中重寫了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會自動將該訊息放到重試佇列圖片

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

 

 

 

流程圖如下:

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

 

 

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

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

 

 

 

流程圖如下:

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

 

 

 

後面就不再消費了。

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

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

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

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

6.真相

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

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

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

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

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

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

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

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

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

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

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

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

 

最後說一句(求關注,別白嫖我)

碼字不易,且行且珍惜。你的認同是我堅持的最大動力,求一鍵三連:點贊、轉發、在看。

關注公眾號:【蘇三說技術】,在公眾號中回覆:面試、程式碼神器、開發手冊、時間管理有超讚的粉絲福利,另外回覆:加群,可以跟很多BAT大廠的前輩交流和學習。

相關文章