首先記錄異常的根本原因

Logback日志庫的0.9.30版本帶來了一個很棒的新功能：從根（最內部）異常而不是最外部異常開始記錄堆棧跟蹤。當然，我的興奮與我貢獻了此功能無關。

用塞西爾·德·米勒（Cecil B. de Mille） 的話來解釋：“撰寫博客文章的方法是從堆棧跟蹤開始，直到達到高潮 ” –在這里：

詳細信息還不重要，但是從100英尺視圖中您可以看到很長的堆棧跟蹤，并且有多個相互包裹的異常（引起）。我們將回到此堆棧跟蹤，但首先要介紹一些基礎知識。如果拋出異常，則會以某種方式記錄日志，以顯示異常發生時瞬間堆棧的外觀。在最底部，您將看到靜態的main（）或Thread.run（） ，該方法通過調用直到第一個堆棧跟蹤行的方法進行處理，該行指示實際拋出異常的位置。這非常方便，因為您可以看到導致異常的整個控制流程：

public class BookController {private final BookService bookService = new BookService();public void alpha() { beta(); }private void beta() { gamma(); }private void gamma() { bookService.delta(); }public static void main(String[] args) {new BookController().alpha();}
}class BookService {private final BookDao bookDao = new BookDao();public void delta() { epsilon(); }private void epsilon() { zeta(); }private void zeta() { bookDao.eta(); }
}class BookDao {public void eta() { theta(); }private void theta() { iota(); }public void iota() { throw new RuntimeException("Omega server not available"); }
}

如果您不知道希臘字母，則可以從堆棧跟蹤中開始學習（請記住，控制流從底部開始并一直向上）：

java.lang.RuntimeException: Omega server not availableat BookDao.iota(BookController.java:50)at BookDao.theta(BookController.java:48)at BookDao.eta(BookController.java:46)at BookService.zeta(BookController.java:41)at BookService.epsilon(BookController.java:39)at BookService.delta(BookController.java:37)at BookController.gamma(BookController.java:22)at BookController.beta(BookController.java:20)at BookController.alpha(BookController.java:18)at BookController.main(BookController.java:26)

太好了吧？從上到下閱讀時，您可以說： iota（）由theta（）調用，而eta（）則調用…清晰而簡單。但是，如果有人決定包裝原始異常并重新拋出該異常怎么辦？

public class BookController {private static final Logger log = LoggerFactory.getLogger(BookController.class);private final BookService bookService = new BookService();public void alpha() { beta(); }private void beta() { gamma(); }private void gamma() {try {bookService.delta();} catch (Exception e) {throw new RuntimeException("Sorry, try again later", e);}}public static void main(String[] args) {try {new BookController().alpha();} catch (Exception e) {log.error("", e);}}
}class BookService {private final BookDao bookDao = new BookDao();public void delta() { epsilon(); }private void epsilon() { zeta(); }private void zeta() {try {bookDao.eta();} catch (Exception e) {throw new RuntimeException("Unable to save order", e);}}
}class BookDao {public void eta() { theta(); }private void theta() { iota(); }public void iota() {try {throw new RuntimeException("Omega server not available");} catch (Exception e) {throw new RuntimeException("Database problem", e);}}
}

現在快速：在堆棧跟蹤中找到根本原因！

java.lang.RuntimeException: Sorry, try again laterat BookController.gamma(BookController.java:26)at BookController.beta(BookController.java:20)at BookController.alpha(BookController.java:18)at BookController.main(BookController.java:32)
Caused by: java.lang.RuntimeException: Unable to save orderat BookService.zeta(BookController.java:51)at BookService.epsilon(BookController.java:45)at BookService.delta(BookController.java:43)at BookController.gamma(BookController.java:24)... 8 common frames omitted
Caused by: java.lang.RuntimeException: Database problemat BookDao.iota(BookController.java:66)at BookDao.theta(BookController.java:60)at BookDao.eta(BookController.java:58)at BookService.zeta(BookController.java:49)... 11 common frames omitted
Caused by: java.lang.RuntimeException: Omega server not availableat BookDao.iota(BookController.java:64)... 14 common frames omitted

原來main（）不再是最后一行。更糟糕的是，一切似乎都出現了亂碼，請嘗試再次閱讀希臘字母…現在讓我們回到原始的堆棧跟蹤中。它來自Spring框架啟動失敗，想象它可能長達數頁。

為了方便起見，我添加了箭頭來標記您重構控制流所應遵循的路徑：從紅色箭頭的尾部（ Thread.run（） ）開始，在中間的某個位置向上，然后…跳至橙色箭頭的尾部。從橙色箭頭的頭部跳到綠色箭頭的尾巴，依此類推...不是很直觀，您不覺得嗎？這個紅色的橢圓顯示了什么？是的，這是失敗的根本原因（最內部的異常）。另一方面，在最開始打印的異常（通常是您一開始就讀到的異常）說明了創建DefaultAnnotationHandlerMapping＃0時發生的錯誤（是什么？）真正的錯誤（ 沒有匹配的bean類型…… ）被巧妙地隱藏了……

那么這個新功能到底是什么呢？還是我們的簡單例子。升級到0.9.30之后，只需在日志記錄模式的末尾添加％rEx （或等效的％rootException ）：

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"><encoder><pattern>%d{ISO8601} | %-5level | %thread | %logger{1} | %m%n%rEx</pattern></encoder>
</appender>

這將用我親自貢獻的默認堆棧跟蹤打印路由代替。現在將打印相同的希臘程序：

java.lang.RuntimeException: Omega server not availableat BookDao.iota(BookController.java:64)
Wrapped by: java.lang.RuntimeException: Database problemat BookDao.iota(BookController.java:66)at BookDao.theta(BookController.java:60)at BookDao.eta(BookController.java:58)at BookService.zeta(BookController.java:49)
Wrapped by: java.lang.RuntimeException: Unable to save orderat BookService.zeta(BookController.java:51)at BookService.epsilon(BookController.java:45)at BookService.delta(BookController.java:43)at BookController.gamma(BookController.java:24)
Wrapped by: java.lang.RuntimeException: Sorry, try again laterat BookController.gamma(BookController.java:26)at BookController.beta(BookController.java:20)at BookController.alpha(BookController.java:18)at BookController.main(BookController.java:32)

請仔細將其與先前的輸出進行比較。首先，第一行指出了問題所在。在大多數情況下，您可能都不會跳過“ 由...引起的 ”例外，因此可能會跳過其余部分。其次，控制流是不間斷且連續的–您仍然可以從上至下閱讀，反之亦然。最后但并非最不重要的一點是–同時保留了異常被包裹的事實，但不會使堆棧跟蹤混亂。

現在您應該看到利用％rEx打印的原始Spring異常：

觀察結果完全相同：問題的根本原因從一開始就出現，從而縮短了需要研究問題的時間。同樣，在分析控制流時，不會跳躍-Thread.main（）位于底部，您可以連續讀取底部到頂部的軌跡。

如果您使用堆棧跟蹤（在開發中或在生產/支持中）進行大量工作–請考慮切換到根本原因優先日志記錄。每次您分析特定異常時，它將節省您幾秒鐘的時間。但是我還注意到，經驗不足的開發人員有時甚至不知道“ 由...引起的 ”規則： 找到第一個異常并查看最后一個“由...引起的” –仍然不清楚問題到底是什么，僅查看最外部，最不具體，最通用的錯誤。這也將對他們有幫助。

順便說一下，如果您完全避免包裝和重新拋出異常，則可以避免所有這些麻煩。我知道，我們經常會因檢查異常而被迫這么做……

參考： 日志異常的根源首先來自我們的JCG合作伙伴Tomek Nurkiewicz，位于NoBlogDefFound

編碼愉快！不要忘記分享！

相關文章：