首先记录异常的根本原因

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

编码愉快！不要忘记分享！

相关文章：