在日志中记录Java异常信息的正确姿势

偏执的太偏执、 2022-12-31 10:21 218阅读 0赞

## 遇到的问题 ##

今天遇到一个线上的BUG，在执行表单提交时失败，但是从程序日志中看不到任何异常信息。  
在Review源代码时发现，当catch到异常时只是输出了`e.getMessage()`，如下所示：

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

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

## 原因分析 ##

先来看一下Java中的异常类图：  
![Java异常类图][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即可。  
![Java日志组件集成][Java 1]

<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.25</version>
    </dependency>
    
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.2.3</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.3</version>
    </dependency>

上述配置以集成slf4j和logback为例，添加对应的logback配置文件（logback.xml）：

<configuration scan="false" scanPeriod="30 seconds" debug="false" packagingData="true">
        <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"/>
        
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
            </encoder>
        </appender>
        　　
        
        <appender name="FILE" class="ch.qos.logback.core.FileAppender">
            <file>test.log</file>
            <encoder>
                <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
            </encoder>
        </appender>
    
        <root level="info">
            <appender-ref ref="STDOUT"/>
            <appender-ref ref="FILE" />
        </root>
    </configuration>

在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]
    
    ......

[Java]: /images/20221120/e23e8f272df14dc1a84cfd53d167923a.png
[Java 1]: /images/20221120/517db23ab7bd4e75967cfc259e626dd4.png