遇到的问题

今天遇到一个线上的BUG,在执行表单提交时失败,但是从程序日志中看不到任何异常信息。

在Review源代码时发现,当catch到异常时只是输出了e.getMessage(),如下所示:

logger.error("error: {}, {}", params, e.getMessage());

在日志中看不到任何信息,说明e.getMessage()返回值为空字符串。

原因分析

先来看一下Java中的异常类图:


Throwable是Java中所有异常信息的顶级父类,其中的成员变量detailMessage就是在调用e.getMessage()返回的值。

那么这个属性会在什么时候赋值呢,追溯源码发现,该属性只会在Throwable构造函数中赋值。

public Throwable() {
// 在默认构造函数中不会给detailMessage属性赋值
fillInStackTrace();
}
public Throwable(String message) {
fillInStackTrace();
// 直接将参数赋值给detailMessage
detailMessage = message;
}
public Throwable(String message, Throwable cause) {
fillInStackTrace();
// 直接将参数赋值给detailMessage
detailMessage = message;
this.cause = cause;
}
public Throwable(Throwable cause) {
fillInStackTrace();
// 当传入的Throwable对象不为空时,为detailMessage赋值
detailMessage = (cause==null ? null : cause.toString());
this.cause = cause;
}
protected Throwable(String message, Throwable cause,
boolean enableSuppression,
boolean writableStackTrace) {
if (writableStackTrace) {
fillInStackTrace();
} else {
stackTrace = null;
}
// 直接将参数赋值给detailMessage
detailMessage = message;
this.cause = cause;
if (!enableSuppression)
suppressedExceptions = null;
}

显然,从源码中可以看到在Throwable的默认构造函数中是不会给detailMessage属性赋值的。

也就是说,当异常对象是通过默认构造函数实例化的,或者实例化时传入的message为空字符串,那么调用getMessage()方法时返回值就为空,也就是我遇到的情形。

所以,在程序日志中不要单纯使用getMessage()方法获取异常信息(返回值为空时,不利于问题排查)。

正确的做法

在Java开发中,常用的日志框架及组件通常是:slf4j,log4j和logback,他们的关系可以描述为:slf4j提供了统一的日志API,将具体的日志实现交给log4j与logback。

也就是说,通常我们只需要在项目中使用slf4j作为日志API,再集成log4j或者logback即可。

org.slf4j
slf4j-api
1.7.25
ch.qos.logback
logback-core
1.2.3
ch.qos.logback
logback-classic
1.2.3
上述配置以集成slf4j和logback为例,添加对应的logback配置文件(logback.xml):
%date %level [%thread] %logger{10} [%file:%line] %msg%n
test.log
%date %level [%thread] %logger{10} [%file:%line] %msg%n
在Java中通过slf4j提供的日志API记录日志:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Test {
private static final Logger logger = LoggerFactory.getLogger(Test.class);
}
当我们需要在程序日志中输出异常信息时,应该直接传入异常对象即可,而不要单纯通过异常对象的getMessage()方法获取输出异常信息。
public void test() {
try {
// 使用默认构造函数实实例化异常对象
throw new NullPointerException();
} catch (Exception e) {
// 直接将异常对象传入日志接口,保存异常信息到日志文件中
logger.error("error: {}", e.getMessage(), e);
e.printStackTrace();
}
}

如下是保存到日志文件中的异常信息片段:

2019-06-20 20:04:25,290 ERROR [http-nio-8090-exec-1] o.c.s.f.c.TestExceptionController [TestExceptionController.java:26] error: null # 使用默认构造参数实例化异常对象时,getMessage()方法返回值为空对象

# 如下是具体的异常堆栈信息
java.lang.NullPointerException: null
at org.chench.springboot.falsework.controller.TestExceptionController.test(TestExceptionController.java:24) ~[classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_181]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_181]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209) [spring-web-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136) [spring-web-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) [tomcat-embed-core-8.5.31.jar:8.5.31]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851) [spring-webmvc-5.0.6.RELEASE.jar:5.0.6.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [tomcat-embed-core-8.5.31.jar:8.5.31]
......