定制 Spring Boot 日志，将异常摘要追加到第一行末尾

为什么要定制

Spring Boot 默认使用 Logback 作为日志实现，而我们一般使用 SLF4J 来输出日志：

private static final Logger LOGGER = LoggerFactory.getLogger(<当前类>.class);

public void foo() {
    try {
        // ...
    } catch (Exception e) {
        LOGGER.error("foo: Oops, something is wrong!", e);
    }
}

上述代码打印的日志看起来是这样：

2019-05-16 11:26:13.194 ERROR 13789 --- [nio-8080-exec-1] com.hsinwong.demo.Service    : foo: Oops, something is wrong!

java.lang.NullPointerException: null
    at Main.main(Main.java:4)

当生产环境出现问题需要排查的时候，由于日志太多，我们可能会使用 grep 命令过滤日志：

[root@hsinwong demo]# grep error demo.log
2019-05-16 11:26:13.194 ERROR 13789 --- [nio-8080-exec-1] com.hsinwong.demo.Service    : foo: Oops, something is wrong!
[root@hsinwong demo]# 

完全看不到有关异常的任何信息。所以有经验的程序员可能会这样输出日志：

LOGGER.error("foo: Oops, something is wrong! message={}", e.getMessage(), e);

一劳永逸

在 Spring Boot 的资源目录下新增 logback-spring.xml 文件：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="aEx" converterClass="com.hsinwong.demo.logging.ExtendedAdditionThrowableProxyConverter" />

    <logger name="org.apache.catalina.startup.DigesterFactory" level="ERROR"/>
    <logger name="org.apache.catalina.util.LifecycleBase" level="ERROR"/>
    <logger name="org.apache.coyote.http11.Http11NioProtocol" level="WARN"/>
    <logger name="org.apache.sshd.common.util.SecurityUtils" level="WARN"/>
    <logger name="org.apache.tomcat.util.net.NioSelectorPool" level="WARN"/>
    <logger name="org.eclipse.jetty.util.component.AbstractLifeCycle" level="ERROR"/>
    <logger name="org.hibernate.validator.internal.util.Version" level="WARN"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m${LOG_EXCEPTION_CONVERSION_WORD:-%aEx}}</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

该文件的原型是 Spring Boot 内置的 Logback 默认配置文件 defaults.xml：

<?xml version="1.0" encoding="UTF-8"?>

<!--
Default logback configuration provided for import, equivalent to the programmatic
initialization performed by Boot
-->

<included>
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
    <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />
    <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
    <property name="FILE_LOG_PATTERN" value="${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>

    <logger name="org.apache.catalina.startup.DigesterFactory" level="ERROR"/>
    <logger name="org.apache.catalina.util.LifecycleBase" level="ERROR"/>
    <logger name="org.apache.coyote.http11.Http11NioProtocol" level="WARN"/>
    <logger name="org.apache.sshd.common.util.SecurityUtils" level="WARN"/>
    <logger name="org.apache.tomcat.util.net.NioSelectorPool" level="WARN"/>
    <logger name="org.eclipse.jetty.util.component.AbstractLifeCycle" level="ERROR"/>
    <logger name="org.hibernate.validator.internal.util.Version" level="WARN"/>
</included>

新增 logback-spring.xml 文件后，还要新增一个自定义的类：

package com.hsinwong.demo.logging;

import ch.qos.logback.classic.pattern.ExtendedThrowableProxyConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.IThrowableProxy;
import ch.qos.logback.core.CoreConstants;
import org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter;

/**
 * 在 {@link ExtendedWhitespaceThrowableProxyConverter} 的基础上附加异常摘要到日志第一行末尾<br>
 * 便于筛选日志时快速了解异常信息
 *
 * @author hsinwong
 */
public class ExtendedAdditionThrowableProxyConverter extends ExtendedThrowableProxyConverter {

    @Override
    public String convert(ILoggingEvent event) {
        IThrowableProxy tp = event.getThrowableProxy();
        if (tp == null) {
            return CoreConstants.LINE_SEPARATOR;
        }
        return super.convert(event);
    }

    @Override
    protected String throwableProxyToString(IThrowableProxy tp) {
        return " ==> " + tp.getClassName() + ": " + tp.getMessage() + CoreConstants.LINE_SEPARATOR +
                CoreConstants.LINE_SEPARATOR + super.throwableProxyToString(tp) + CoreConstants.LINE_SEPARATOR;
    }

}

日志现在看起来像这样：

2019-05-16 11:26:13.194 ERROR 13789 --- [nio-8080-exec-1] com.hsinwong.demo.Service    : foo: Oops, something is wrong! ==> java.lang.NullPointerException: null

java.lang.NullPointerException: null
    at Main.main(Main.java:4)

大大提高了 grep error demo.log 命令的实用性。

又能挤出点写代码和排查问题的时间来划水了……