天天看點

誰再悄咪咪的吃掉異常,我上去就是一 JIO

又到周末了,周更選手申請出站~

誰再悄咪咪的吃掉異常,我上去就是一 JIO

這次分享一下上個月碰到的離奇的問題。一個簡單的問題,硬是因為異常被悄咪咪吃掉,過關難度直線提升,導緻小黑哥排查一個晚上。

這個美好的晚上,本想着開兩把 LOL 無限火力,在召喚師峽谷來個五殺的~

哎,就這樣沒了啊!我知道,你們一定能了解這種五殺被搶的感覺~

下次,真的,誰再讓我看到悄咪咪的吃掉異常,我真的要上去一 Jio 了!

誰再悄咪咪的吃掉異常,我上去就是一 JIO
好了,本文可不是水文,看完本篇文章,你可以學到以下知識點:

  • Arthas 排查技巧
  • 啥是 NoClassDefFoundError
  • Dubbo 異常内部處理方式

好了,同學們,打開小本子,準備記好知識點~

誰再悄咪咪的吃掉異常,我上去就是一 JIO
先贊後看養成習慣,微信搜尋「程式通事」,關注就完事了

起因

我們有個業務系統,應用之間調用鍊如下所示:

誰再悄咪咪的吃掉異常,我上去就是一 JIO

A 應用是業務發生起始應用,在這個應用中将會根據一定規則選擇最後的通訊管道 C,然後将這個管道辨別傳遞給 B 應用。

B 應用的功能類似網關,這個應用将會根據 A 應用傳遞過來的管道辨別,将會請求路由下發到具體的 C 應用,起到服務路由的功能。

C 應用是與外部應用互動的應用,我們将其稱為管道通訊機。

假設一次業務中,A 應用根據規則選擇 C2 的管道辨別,然後傳遞給 B 應用。B 應用根據這個辨別選擇使用 C2 進行通訊,最後 C2 調用外部應用完成一次業務調用。

上述所有應用都基于 Dubbo 進行遠端通訊,B 應用實作原理在小黑哥之前文章「支付路由系統演進史」中有寫過,感興趣的同學可以檢視一下。

介紹完業務的基本情況,現在我們來看下到底發生了啥事。

一次業務需求中,需要改動 C2 應用,這次改動功能點真的很小,很快就完成了。小黑哥想着閑着也是閑着,于是就把之前 C2 應用中列印的日志中一些沒有脫敏的資訊,進行脫敏處理。

由于之前日志架構脫敏處理存在一些問題,于是就将日志架構從 Log4j 更新為 LogBack。更新之後,為了防止不同日志架構中之間的産生沖突,于是使用 IDEA Maven Helper 插件,統一将應用中所有的 Log4j 相關依賴都給排除了。

改動完成之後,将 C2 應用釋出到測試環境,再次從 A 應用發起測試, B 應用傳回異常提示未找到 C2 應用。

B 應用業務代碼類似如下:

public Response pay(Request req) {
    
    try {
        if (!isSupport(req.getChnlCode())) {
            return new Response("ERROR", "未找到相關管道應用");
        }
        return doPay(req);
    } catch (Exception e) {
        return new Response("ERROR", "未找到相關管道應用");
    }
}
           

正常情況下,若是配置存在問題,B 應用将會傳回未找到具體管道,請求也會在 B 應用結束,不會調用到 C2 應用(也沒辦法調用)。

然而此次配置什麼都沒問題, 而且最詭異的是 C2 應用居然收到了請求,并且成功處理了業務請求。

排查問題

由于 B 應用異常處理時,将異常吃掉了,我們沒辦法得知這個過程到底發生了啥事,是以第一要緊的事擷取異常資訊。

最簡單的辦法就是,将 B 應用改造一下,加入列印異常日志。不過當時比較懶,不想改造應用,就想擷取異常資訊,于是想到使用 Arthas。

Arthas 排錯技巧

Arthas

是Alibaba開源的Java診斷工具,這裡就不再詳細介紹這個工具,主要講下這次排錯用到的指令-watch。

watch 指令可以友善觀察指定方的調用情況,可以具體觀察方法的

傳回值

抛出異常

入參

,另外還可以通過 OGNL表達式檢視對應的變量。

這裡我們主要為了檢視方法抛出的異常資訊,執行指令如下:

watch com.dubbo.example.DemoService doPay -e -x 2 '{params,throwExp}'
           

上述指令将會在方法異常之後觀察方法的入參以及異常資訊。

注意,我們需要檢視

doPay

方法,而不是

pay

方法。這是因為

pay

方法中我們将異常捕獲,不太可能會抛出異常哦~

異常資訊如下所示:

誰再悄咪咪的吃掉異常,我上去就是一 JIO

真正引起此次錯誤的異常資訊為:

java.lang.NoClassDefFoundError: Could not initialize class xx.xxx.xx.GELogger
           

由于此次 B 應用不存在改動,是以推測這個異常實際發生在 C2 應用,于是在 C2 應用處再次使用 Arthas watch 指令,同樣觀察到相同的錯誤資訊。

NoClassDefFoundError

NoClassDefFound,從名字上我們可以推測是因為類不存在,進而引發的這個錯誤。按照這個思路,我們首先可以簡單檢視一下 B 應用中是否存在

GELogger

相關類。

檢視 B 應用相關依賴包,從中發現了這個類檔案,這說明這個類确實存在。

在 IDEA 反編譯檢視

GELogger

類相關源碼,從中發現了問題。

private static Logger logger;

static {
    System.out.println("static init");
    logger = Logger.getLogger(NoClassDefFoundErrorTestService.class);
    System.out.println("Logger init success");
}
           

GELogger

存在一個靜态代碼塊,用于初始化一個

org.apache.log4j.Logger

日志類。

然後在上面改動中,全部的

Log4j

依賴都被排除了,是以這裡運作時應該會抛出另外一個找到

org.apache.log4j.Logger

錯誤。

執行以下代碼,模拟抛錯過程。

System.out.println("模拟第一次 Error");
try {
    NoClassDefFoundErrorTestService noClassDefFoundErrorTestService=new NoClassDefFoundErrorTestService();
} catch (Throwable e) {
    e.printStackTrace();
}
System.out.println("模拟第二次 Error");
try {
    NoClassDefFoundErrorTestService noClassDefFoundErrorTestService=new NoClassDefFoundErrorTestService();
} catch (Throwable e) {
    e.printStackTrace();
}
           
誰再悄咪咪的吃掉異常,我上去就是一 JIO

第一次建立

NoClassDefFoundErrorTestService

執行個體時,Java 虛拟機讀取加載時,将會初始化靜态代碼塊時。由于

org.apache.log4j.Logger

類不存在,靜态代碼塊執行異常,進而導緻類加載失敗。

第二次再建立

NoClassDefFoundErrorTestService

執行個體時,Java 虛拟機不會再次讀取加載,是以直接傳回了以下異常。

java.lang.NoClassDefFoundError: Could not initialize class com.dubbo.example.NoClassDefFoundErrorTestService
           

找到問題真正原因,解決辦法也很簡單,直接排除

GELogger

所在依賴包。

Dubbo 内部異常處理

雖然問題到此解決了,但是這裡還有一個疑問,為何 C2 應用發生了異常,卻沒有相關錯誤日志,并且 C2 業務邏輯也正常處理完成。

這就要說到 Dubbo 内部異常錯誤處理方式,上面

GELogger

其實作用在一個 Dubbo 自定義 Filter 中,用來記錄結果,模拟代碼如下:

@Activate(
        group = {"provider", "consumer"}
)
public class ErrorFilter implements Filter {


    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {

        Result result = invoker.invoke(invocation);
        NoClassDefFoundErrorTestService noClassDefFoundErrorTestService=new NoClassDefFoundErrorTestService();
        // 處理業務邏輯
        return result;
    }
}
           

這個自定義 Filter 中首先執行

invoker

方法,這個方法将會調用真正的業務方法,這就是為什麼 C2 應用邏輯是正常處理完成。

業務方法處理完成之後,然後執行後續邏輯。由于

NoClassDefFoundErrorTestService

将會抛出

Error

,最終這個

Error

,将會在

HeaderExchangeHandler#handleRequest

被捕獲,然後将會把相關異常資訊傳回給調用 Dubbo 消費者。

誰再悄咪咪的吃掉異常,我上去就是一 JIO

而在 Dubbo 消費者接受到服務提供者傳回資訊之後,将會在

DefaultFuture#doReceived

轉化成

RemotingException

誰再悄咪咪的吃掉異常,我上去就是一 JIO

RemotingException

最終将會在

FailoverClusterInvoker#doInvoke

轉換成

RpcException

傳回給業務代碼。

誰再悄咪咪的吃掉異常,我上去就是一 JIO

總結

好了,說了這麼多,總結一下本文知識點

  1. 異常捕獲之後,一定要記得列印日志,并且要記得輸出堆棧資訊。
  2. 運作時類不存在,将會導緻

    NoClassDefFoundError

    ,類加載過程失敗,也會導緻

    NoClassDefFoundError

  3. 對外提供的二方包,最好不要依賴特定日志架構,如 Log4j,Logback 等,應該使用 Slf4j 架構。

幫助

1、當Dubbo遇上Arthas:排查問題的實踐

2、java.lang.NoClassDefFoundError 的解決方法一例

3、noclassdeffounderror-could-not-initialize-class-error

歡迎關注我的公衆号:程式通事,獲得日常幹貨推送。如果您對我的專題内容感興趣,也可以關注我的部落格:studyidea.cn