springboot+logback日志输出企业实践（下）

一句话概括：logback 在实现了基本的日志输出到文件功能后，在企业实践中，还会有其它的进阶需求，本文对logback的进阶使用进行描述。

1.引言

上一篇文章《springboot+logback 日志输出企业实践（上）》对 logback 的使用及配置进行描述，并实现按日志级别输出到独立文件功能。但在企业实践中，还会有其它的需求，如需要在多环境下使用不同日志级别，日志输出性能低怎么处理，还有分布式系统如何追踪请求日志等等，对于这些需求，logback 有提供相应的功能，本文将对这几种需求的实现进行讲解。具体有如下内容：

• 使用异步输出日志提高性能
• logback 在多环境下选择日志级别配置
• 使用 MDC 在分布式系统中追踪请求

如需看源码，本文示例工程地址：https://github.com/mianshenglee/my-example/tree/master/springboot-logback-demo

2. 输出 logback 状态数据

logback 官方文档指出，强烈建议启用 logback 状态数据的输出，将会在很大程度上帮助我们诊断 logback 相关问题。通过这些状态数据，可以知道 logback 配置文件加载情况，配置中对应的 appender，logger的装载情况等。启用状态数据输出有两种方式：

• 在根元素( configuration ) 中设置属性debug="true"
• 添加元素( statusListener )，class 使用OnConsoleStatusListener。如下：

<!-- 输出logback的本身状态数据 -->
<statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

注意，二者选其一即可，此处的 debug 与配置文件中的日志级别没有关系，只用于表示输出状态数据。

本示例中，使用第二种方式（添加 statusListener 元素），添加后，输出内容如下所示：

3. logback 异步输出日志

3.1 异步输出配置

按之前的 logback 配置，日志输出到文件是同步输出的，即每次输出都会直接写IO到磁盘文件，从而产生阻塞，造成不必要的性能损耗。当然，对于一般的应用，影响不大，但对于高并发的应用，还是有必要对性能进行优化的。logback 提供了日志异步输出的 AsyncAppender。 异步输出日志的方式很简单，添加一个基于异步写日志的appender，并指向原先配置的appender即可 。见以下配置：

<!-- 异步输出 -->
<appender name="ASYNCDEBUG" class="ch.qos.logback.classic.AsyncAppender">
    <!-- 默认如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志，若要保留全部日志，设置为0 -->
    <discardingThreshold>0</discardingThreshold>
    <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
    <queueSize>1024</queueSize>
    <!-- 添加附加的appender,最多只能添加一个 -->
    <appender-ref ref="DEBUGFILE"/>
    <includeCallerData>true</includeCallerData>
</appender>
//INFO 结构同上，略
//WARN 结构同上，略
//ERROR 结构同上，略
<!-- 异步输出关联到root -->
<root level="DEBUG">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="ASYNCDEBUG" />
    ...//略
</root>

AsyncAppender 对应需要设置的参数主要有 :

属性名	类型	描述
queueSize	int	队列的最大容量，默认为 256
discardingThreshold	int	默认，当队列还剩余 20% 的容量时，会丢弃级别为 TRACE, DEBUG 与 INFO 的日志，仅仅只保留 WARN 与 ERROR 级别的日志。想要保留所有的事件，可以设置为 0
includeCallerData	boolean	获取调用者的数据相对来说比较昂贵。为了提高性能，默认情况下不会获取调用者的信息。默认情况下，只有像线程名或者 MDC 这种"便宜"的数据会被复制。设置为 true 时，appender 会包含调用者的信息
maxFlushTime	int	根据所引用 appender 队列的深度以及延迟， AsyncAppender 可能会耗费长时间去刷新队列。当 LoggerContext 被停止时， AsyncAppender stop 方法会等待工作线程指定的时间来完成。使用 maxFlushTime 来指定最大的刷新时间，单位为毫秒。在指定时间内没有被处理完的事件将会被丢弃。这个属性的值的含义与 Thread.join(long)) 相同
neverBlock	boolean	默认为 false，在队列满的时候 appender 会阻塞而不是丢弃信息。设置为 true，appender 不会阻塞你的应用而会将消息丢弃

3.2 异步输出原理

AsyncAppender 的实现方式是通过阻塞队列( BlockingQueue )来避免日志直接输出到文件，而是把日志事件输出到 BlockingQueue 中，然后启动一个新的worker线程，主线程不阻塞，worker线程则从队列中获取需要写的日志，异步输出到对应的位置。

4. springboot 多环境下 logback 配置

使用 springboot 进行应用开发，支持对多环境的配置支持，只需要按application-*.properties 格式添加配置文件，然后使用 spring.profiles.active 指定环境即可。同样，日志输出，一般在开发环境，使用 DEBUG 级别，以便以检查问题，而在生产环境，则只输出 ERROR 级别的日志。如下所示，profile定义开发环境为 dev ，生产环境为 prod：

<!-- 开发环境:debug级别-->
<springProfile name="dev">
    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
        ...//略
    </root>
</springProfile>

<!-- 生产环境:error级别-->
<springProfile name="prod">
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        ...//略
    </root>
</springProfile>

上述配置是对 root 进行 设置（当然，其它元素也可以使用）。经过此设置后，则会根据 spring.profiles.active 而决定使用指定日志级别输出。

其实 logback 还支持使用 if 元素，使用 if-then-else 的形式，结合 condition 属性来实现条件处理。有兴趣的读者可以看官方文档说明 "Conditional processing of configuration files"

5. MDC 分布式应用追踪请求

使用springboot开发分布式应用，很多都微服务化，当请求过来，可能需要调用多个服务来完成请求动作。在查询日志时，特别是请求量大的情况下，日志多，很难找到对应请求的日志，造成定位异常难，日志难以追踪等问题。针对此类问题，logback 提供了 MDC （ Mapped Diagnostic Contexts 诊断上下文映射 ），MDC可以让开发人员可以在 诊断上下文 中放置信息，这些消息是内部使用了 ThreadLocal实现了线程与线程之间的数据隔离，管理每个线程的上下文信息 。而在日志输出时，可以通过标识符%X{key} 来输出MDC中的设置的内容。因此，在分布式应用在追踪请求时，实现思路如下：

1. web应用中，添加拦截器，在请求进入时，添加唯一id作为request-id，以标识此次请求。
2. 添加此 request-id 到MDC中
3. 若需要调用其它服务，把此request-id作为 header 参数
4. 在日志输出时，添加此request-id的输出作为标识
5. 请求结束后，清除此request-id

5.1 添加拦截器

5.1.1 拦截器实现

通过拦截器，实现在请求前添加request-id，并放到 MDC 中；请求完成后清除的动作。添加包 interceptor 存放拦截器类，类定义如下：

@Slf4j
@Component
public class RequestIdTraceInterceptor implements HandlerInterceptor {

    public static final String REQUEST_ID_KEY = "request-id";

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        MDC.put(REQUEST_ID_KEY, getRequestId(request));
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
        //把requestId添加到响应头，以便其它应用使用
        response.addHeader(REQUEST_ID_KEY, MDC.get(REQUEST_ID_KEY));
        //请求完成，从MDC中移除requestId
        MDC.remove(REQUEST_ID_KEY);
    }
    
    public static String getRequestId(HttpServletRequest request) {...// 后面给出}
}

此拦截器主要覆盖 preHandle 及 afterCompletion 方法，分别请求前和请求完成后的处理。使用 MDC.put() 及 MDC.remove() 实现对MDC的写入及清除操作。

在获取 request-id 时，使用方法是 getRequestId()，如下所示：

public static String getRequestId(HttpServletRequest request) {
    String requestId;
    String parameterRequestId = request.getParameter(REQUEST_ID_KEY);
    String headerRequestId = request.getHeader(REQUEST_ID_KEY);
    // 根据请求参数或请求头判断是否有“request-id”，有则使用，无则创建
    if (parameterRequestId == null && headerRequestId == null) {
        log.debug("no request-id in request parameter or header");
        requestId = IdUtil.simpleUUID();
    } else {
        requestId = parameterRequestId != null ? parameterRequestId : headerRequestId;
    }

    return requestId;
}

根据请求参数或请求头判断是否有“request-id”，有则使用，无则创建，创建的request-id 为simpleUUID，以此作为唯一标识。

5.1.2 注册拦截器到web配置中

添加 config 包用于存放配置文件。继承 WebMvcConfigurer 实现 addInterceptors 来添加拦截器到 web 配置中：

@Configuration
public class WebAppConfig implements WebMvcConfigurer {
    @Autowired
    RequestIdTraceInterceptor requestIdTraceInterceptor;

    /**
     * 添加拦截器
     * @param registry
     */
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        //添加requestId
        registry.addInterceptor(requestIdTraceInterceptor);
    }
}

5.2 设置 MDC 日志输出

logback 的 MDC 输出是用%X{key} 来作标识符进行输出，因此，修改 logback-spring.xml 文件，在输出格式中添加 %X{request-id} 输出，如下：

<property name="log.pattern"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} %5level [%10thread] [%X{request-id}] %40.40logger{40} [%10method,%line] : %msg%n"/>

至此，MDC处理完毕，启动应用，访问其中的某一个接口，输出如下（其中8e955ff61fa7494788f52891a4fdbc6a即可 request-id）：

注意，示例代码没有给出调用其它服务时的处理，当调用时，从 MDC 中获取 request-id ，然后把它作为 header参数，实现 request-id 的传递。这样查询日志时，根据此id来追踪就可以了。

6. 总结

本篇文章针对springboot应用开发中，如何更好的使用 logback 解决日志输出的相关问题，主要包括 loback 状态数据的输出，使用异步解决日志输出性能问题，配置多环境下的日志输出以及使用MDC解决分布式应用追踪请求。希望能对大家有帮助。

本文中使用的示例代码已放在我的github：https://github.com/mianshenglee/my-example/tree/master/springboot-logback-demo，有兴趣的同学可以pull代码，结合示例一起学习。

参考资料

• logback官网: http://logback.qos.ch
• logback中文手册: http://www.logback.cn/
• logback github： https://github.com/qos-ch/logback
• 使用requestId在分布式系统追踪请求： https://juejin.im/post/5b51f85c5188251af91a7525

往期文章

• springboot+logback 日志输出企业实践（上）
• springboot+swagger 接口文档企业实践（下）
• springboot+swagger接口文档企业实践（上）
• 查阅了十几篇学习资源后，我总结了这份AI学习路径
• java应用监测(8)-阿里诊断工具arthas
• java应用监测(7)-在线动态诊断神器BTrace

关注我的公众号（搜索Mason技术记录），获取更多技术记录：