讓logger語句記錄異常的堆疊資訊

前言

補個日誌。

其實CSND也有類似的文章，但是我也有思考過，所以我也想記錄一下。我們直接用logger.info("異常資訊為："+e)或者logger.info(e.getMessage())只能記錄到異常的描述資訊，卻沒有其異常具體發生在哪一行程式碼。這樣即使通過日誌發現出現了異常，也沒法馬上定位問題。因此就催生了一個想法，是否能像在idea本地跑程式時出現未捕獲的異常時，控制檯能打印出完整的錯誤堆疊資訊，把這個資訊記錄到logger語句中。

描述

寫介面時，為了方便後期檢視日誌定位問題，我對service的logger日誌進行了改造，將所有的logger語句拼接成一條記錄，然後再打印出來。因此會在service層最外層使用try catch finally。這樣一個請求的日誌就能統一出現，不會由於多個請求導致的日誌穿插記錄。日誌如：

[2018-06-26 17:09:54.038] -- [http-nio-8079-exec-27] -- [INFO] -- [OrderServiceImpl.java:513 >>>> Method = query] -- [Content = 
********【1121訂單查詢】標識：useruuid==d86a732d-2da6-11e8-xxx-xxxx,source==1,phone==135705xxxxx,orderNo==201806260000xxxxx
********【1121訂單查詢】入參：com.uroad.etc.dto.OrderInput@6ab68cb3[useruuid=d86a732d-2
 
da6-11e8-xxx-xxxx,orderNo=2018062600xxxx,source=1]
********【1121訂單查詢】請求：request decode data:1121110802CCF5B968C014E702xxxxx
********【1121訂單查詢】響應：response deceode data:90001A4B0D01060F103136303832323xxxxxx
********【1121訂單查詢】updateTradStateAndPushMsgByCardNo 更新表結果：1,cardNo:1608227140xxx
********【1121訂單查詢】出參：com.uroad.etc
 
.dto.OrderOutput@42879e4b[tradeText=2018-06-26 17:09:31,tradeDate=2018xxx,tradTime=170xxx,orderNo=201806260000003xxx,tradMoney=1,tradState=3,serialNo=<null>,cardNo=160822714xxx,terminalNo=<null>,billState=<null>,orderType=1,cardType=<null>,plateNo=<null>,payChannel=6]]

但這樣做有個不好的地方，就是當出現異常的時候，雖然捕獲了，也列印了異常資訊，但是異常資訊不能準確定位錯誤資訊，會像這樣：

[2018-07-31 21:41:04] -- [main] -- [INFO] -- [TestException.java:17 >>>> Method = main] -- [Content = 
異常資訊為：java.lang.NullPointerException]

假如service層程式碼簡單，那麼可以很快就定位出出現異常的地方。可是假如service層稍稍複雜些，程式碼稍稍多一些，就沒法迅速的找處是哪個地方出現異常。

像我們在本地測試的時候，當出現了意料之外的執行時異常，控制檯是能打印出完整的錯誤資訊，像這樣：

public static void main(String[] args) {
    String s = "1";
    if(s.equals("1")){
        s=null;
    }
    s.equals("1");
}

控制檯是能打印出完整資訊的：

Exception in thread "main" java.lang.NullPointerException
    at TestException.main(TestException.java:14)

這樣我們就能一下子就知道錯誤是在TestException的第14行，即s.equals("1)這裡，那我們就能推出是物件s是空物件。

但是由於我在service層的最外層使用了try catch，即我的程式碼是像這樣的：

public static void main(String[] args) {
    try {
        String s = "1";
        if(s.equals("1")){
            s=null;
        }
        s.equals("1");
    }catch (Exception e){
        logger.info("異常資訊為：" + e);
    }
}

這樣，當出現異常，異常資訊為：

[2018-07-31 21:46:04] -- [main] -- [INFO] -- [TestException.java:17 >>>> Method = main] -- [Content = 
異常資訊為：java.lang.NullPointerException]

這樣，只能知道是第17行的logger語句列印的資訊。但是正如我前面所說我在service層使用了try catch finally來處理日誌，所以只有一個logger語句，所以沒法知道錯誤發生在哪裡。

解決方法

public static String toStackTrace(Exception e)
{
    StringWriter sw = new StringWriter();
    PrintWriter pw = new PrintWriter(sw);

    try
    {
        e.printStackTrace(pw);
        return sw.toString();
    }
    catch(Exception e1)
    {
        return "";
    }
}

只是，不知道這樣會不會很佔記憶體。很佔空間。

解決方法2

這樣也能打印出錯誤位置：logger.info(e.getMessage(),e);

輸出如：

[2018-07-31 21:52:57] -- [main] -- [INFO] -- [TestException.java:17 >>>> Method = main] -- [Content = 
null]
java.lang.NullPointerException: null
    at TestException.main(TestException.java:15)

這樣也行：

logger.info("出現異常啦：",e);

但是這樣就必須得一個單獨的logger語句。

可以通過執行緒號去追蹤。。。

最優解決方法

找到了個新方法，不需要改JVM配置，也不需要用Write流：

public static String logClzInfo(Exception e) {
    StringBuffer sb = new StringBuffer();
    sb.append(e.getClass() + " " + e.getMessage() + "\n");
    StackTraceElement[] stackTraceElement = e.getStackTrace();
    for (StackTraceElement traceElement : stackTraceElement) {
        sb.append("\tat " + traceElement + "\n");
    }
    return sb.toString();
}

這樣，就能在catch中通過引數e獲取到完整的錯誤資訊了。這樣一來，以後出了問題，通過日誌，就能一下找到問題所在了。