原文链接：基于SLF4J的MDC机制和Dubbo的Filter机制，实现分布式系统的日志全链路追踪

一、日志系统

1、日志框架

在每个系统应用中，我们都会使用日志系统，主要是为了记录必要的信息和方便排查问题。

而现在主流的就是 SLF4J + Logback。

当我们的系统是单体应用，日志做起来时非常简单的，直接使用 log.info,log.error,log.warn 等等方法。

而当我们的系统是分布式系统，服务之间通信通常都是使用 Dubbo 这个 RPC 框架。

此时做日志就不是这么简单了，因为不同服务都是不同的实例，日志就无法做到一起了，怎么将服务间的调用串联起来，也是一个问题。

但是呢，SLF4J 提供了一个 MDC 机制，它的设计目标就是为了应对分布式应用系统的审计和调试。

所以，我们可以利用 MDC ，然后配合 Dubbo 的 RpcContext 来做分布式系统的全链路日志功能。

2、搭建日志系统

前提：我们使用的是 Spring Boot 项目。

Spring Boot 引入日志依赖：

<!-- log begin -->

<dependency>

    <groupId>org.slf4j</groupId>

    <artifactId>slf4j-api</artifactId>

</dependency>

<dependency>

    <groupId>ch.qos.logback</groupId>

    <artifactId>logback-core</artifactId>

</dependency>

<dependency>

    <groupId>com.alibaba</groupId>

    <artifactId>fastjson</artifactId>

    <version>1.2.68</version>

</dependency>

<!-- log end -->

加入 Logback 的 xml 配置文件：

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

<configuration debug="false">

    <!-- 程序服务名 -->

    <springProperty scope="context" name="SERVICE_NAME" source="spring.application.name" defaultValue="unknown"/>

    <!-- 定义日志的根目录 -->

    <springProperty scope="context" name="LOG_PATH" source="logging.file.path" defaultValue="/Users/howinfun/weblog/java/${SERVICE_NAME}"/>

    <!-- 日志输出格式 -->

    <springProperty scope="context" name="LOG_PATTERN" source="logging.pattern" defaultValue="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%-5level] [%logger{5}] [%X{uri}] [%X{trace_id}] - %msg%n"/>

    <!-- 控制台输出 -->

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

        <layout class="ch.qos.logback.classic.PatternLayout">

            <!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->

            <pattern>${LOG_PATTERN}</pattern>

        </layout>

        <!--此日志appender是为开发使用，只配置最底级别，控制台输出的日志级别是大于或等于此级别的日志信息-->

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">

            <level>debug</level>

        </filter>

        <encoder>

            <Pattern>${LOG_PATTERN}</Pattern>

            <!-- 设置字符集 -->

            <charset>UTF-8</charset>

        </encoder>

    </appender>

    // .... 还有各种 Info、Warn、Error 等日志配置

    <!-- 日志输出级别 -->

    <root level="INFO">

        <appender-ref ref="STDOUT" />

    </root>

</configuration>

上面的注释已经写得非常的清晰了，而我们最主要关注的就是LOG_PATTERN 这个属性。它主要是规定了日志打印的规范，如何打印日志，日志该带上哪些关键信息。

[%X{uri}]：这里主要是记录接口的请求 uri。
[%X{trace_id}]：这里主要是记录此次请求的 TraceId，这个 TraceId 也会带到 Dubbo 的服务提供端，让整个链路都带上这个 TraceId。这样在日志记录的时候，全都可以利用 TraceId 了。

这样等到日志排查的时候，只需要前端或者测试给后端的同学提供一个 TraceId，我们就能非常快速的定位到问题所在了。

下面的项目都是引入上面的依赖和加入 xml 文件即可。

二、项目搭建

接下来我们会创建四个项目，分别是 dubbo-api（提供API和工具类）、dubbo-provider-one（Dubbo 服务提供者1）、dubbo-provider-two（Dubbo 服务提供者2）、dubbo-consumer（Dubbo 服务消费者，对外提供 HTTP 接口）。

1、dubbo-api：

这里面最重要的是 TraceUtil 工具类。

这个工具类提供了几个很重要的方法：

TraceId 的初始化：生成 TraceId，并利用 MDC 将 Trace 相关信息存放在当前线程（请求）的 ThreaLocal 中。
TraceId 的存放：将当前线程（请求）的 Trace 相关信息存放在 Dubbo 的 RPC 上下文 RpcContext 中，这样可以将当前请求的 Trace 信息传递到 Dubbo 的服务提供者。
TraceId 的获取：当然了，Dubbo 的服务提供者也可以利用这工具类，从 RpcContext 中获取 Trace 信息。

下面直接上代码：

/**

 * Trace 工具

 * @author winfun

 * @date 2020/10/30 9:02 上午

 **/

public class TraceUtil {

    public final static String TRACE_ID = "trace_id";

    public final static String TRACE_URI = "uri";

    /**

     * 初始化 TraceId

     * @param uri 请求uri

     */

    public static void initTrace(String uri) {

        if(StringUtils.isBlank(MDC.get(TRACE_ID))) {

            String traceId = generateTraceId();

            setTraceId(traceId);

            MDC.put(TRACE_URI, uri);

        }

    }

    /**

     * 从 RpcContext 中获取 Trace 相关信息，包括 TraceId 和 TraceUri

     * 给 Dubbo 服务端调用

     * @param context Dubbo 的 RPC 上下文

     */

    public static void getTraceFrom(RpcContext context) {

        String traceId = context.getAttachment(TRACE_ID);

        if (StringUtils.isNotBlank(traceId)){

            setTraceId(traceId);

        }

        String uri = context.getAttachment(TRACE_URI);

        if (StringUtils.isNotEmpty(uri)) {

            MDC.put(TRACE_URI, uri);

        }

    }

    /**

     * 将 Trace 相关信息，包括 TraceId 和 TraceUri 放入 RPC上下文中

     * 给 Dubbo 消费端调用

     * @param context Dubbo 的 RPC 上下文

     */

    public static void putTraceInto(RpcContext context) {

        String traceId = MDC.get(TRACE_ID);

        if (StringUtils.isNotBlank(traceId)) {

            context.setAttachment(TRACE_ID, traceId);

        }

        String uri = MDC.get(TRACE_URI);

        if (StringUtils.isNotBlank(uri)) {

            context.setAttachment(TRACE_URI, uri);

        }

    }

    /**

     * 从 MDC 中清除当前线程的 Trace信息

     */

    public static void clearTrace() {

        MDC.clear();

    }

    /**

     * 将traceId放入MDC

     * @param traceId   链路ID

     */

    private static void setTraceId(String traceId) {

        traceId = StringUtils.left(traceId, 36);

        MDC.put(TRACE_ID, traceId);

    }

    /**

     * 生成traceId

     * @return  链路ID

     */

    private static String generateTraceId() {

        return TraceIdUtil.nextNumber();

    }

}

2、dubbo-consumer

项目结构如下：

项目是基于 Spring Boot 框架搭建的，使用 dubbo-spring-boot-starter 整合 Dubbo 框架。

WebRequestFilter：

首先，利用 @WebFilter，拦截所有 Http 请求，然后利用 TraceUtil 给这个请求初始化对应的 Trace 信息，然后将 Trace 信息利用 SLF4J 提供的 MDC 机制存放起来。之后利用 Logger 打日志的时候，会带上 Trace 信息。

下面上代码：

/**

 * Web Request Filter

 * @author winfun

 * @date 2020/10/30 3:02 下午

 **/

@Slf4j

@Order(1)

@WebFilter(urlPatterns = "/*")

public class WebRequestFilter implements Filter {

    @Override

    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {

        HttpServletRequest request = (HttpServletRequest) servletRequest;

        HttpServletResponse response = (HttpServletResponse) servletResponse;

        String uri = request.getRequestURI();

        // 初始化 TraceId

        TraceUtil.initTrace(uri);

        filterChain.doFilter(request,response);

        // 清除 TraceId 和 TraceUri

        TraceUtil.clearTrace();

    }

}

DubboTraceFilter：

接着，我们利用 Dubbo 提供的 Filter 机制，在每次进行 Dubbo 调用的前后，进行日志打印。

在过滤器的最开始，首先会处理 Trace 相关信息：

如果是当前调用时消费者的话，主动从 MDC 中获取 Trace 信息并放入 RpcContext 中，这样可以将 Trace 信息传递到服务提供者那边。
如果当前是服务提供者，则可以从 RpcContext 中获取 Trace 信息，接着利用 MDC 将 Trace 信息保存起来。

下面上代码：

/**

 * Dubbo Trace Filter

 * @author winfun

 * @date 2020/10/30 9:46 上午

 **/

@Slf4j

@Activate(order = 100,group = {Constants.PROVIDER_PROTOCOL,Constants.CONSUMER_PROTOCOL})

public class DubboTraceFilter implements Filter {

    @Override

    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {

        // 处理 Trace 信息

        printRequest(invocation);

        // 执行前

        handleTraceId();

        long start = System.currentTimeMillis();

        Result result = invoker.invoke(invocation);

        long end = System.currentTimeMillis();

        // 执行后

        printResponse(invocation,result,end-start);

        return result;

    }

    /***

     *  打印请求

     * @author winfun

     * @param invocation invocation

     * @return {@link }

     **/

    private void printRequest(Invocation invocation){

        DubboRequestDTO requestDTO = new DubboRequestDTO();

        requestDTO.setInterfaceClass(invocation.getInvoker().getInterface().getName());

        requestDTO.setMethodName(invocation.getMethodName());

        requestDTO.setArgs(getArgs(invocation));

        log.info("call Dubbo Api start , request is {}",requestDTO);

    }

    /***

     *  打印结果

     * @author winfun

     * @param invocation invocation

    	 * @param result result

     * @return {@link }

     **/

    private void printResponse(Invocation invocation,Result result,long spendTime){

        DubboResponseDTO responseDTO = new DubboResponseDTO();

        responseDTO.setInterfaceClassName(invocation.getInvoker().getInterface().getName());

        responseDTO.setMethodName(invocation.getMethodName());

        responseDTO.setResult(JSON.toJSONString(result.getValue()));

        responseDTO.setSpendTime(spendTime);

        log.info("call Dubbo Api end , response is {}",responseDTO);

    }

    /***

     *  获取 Invocation 参数，过滤掉大参数

     * @author winfun

     * @param invocation invocation

     * @return {@link Object[] }

     **/

    private Object[] getArgs(Invocation invocation){

        Object[] args = invocation.getArguments();

        args = Arrays.stream(args).filter(arg->{

            if (arg instanceof byte[] || arg instanceof Byte[] || arg instanceof InputStream || arg instanceof File){

                return false;

            }

            return true;

        }).toArray();

        return args;

    }

    /***

     *  处理 TraceId，如果当前对象是服务消费者，则将 Trace 信息放入 RpcContext中

     *  如果当前对象是服务提供者，则从 RpcContext 中获取 Trace 信息。

     * @author winfun

     * @return {@link  }

     **/

    private void handleTraceId() {

        RpcContext context = RpcContext.getContext();

        if (context.isConsumerSide()) {

            TraceUtil.putTraceInto(context);

        } else if (context.isProviderSide()) {

            TraceUtil.getTraceFrom(context);

        }

    }

}

ResponseBodyAdvice：

还有一个比较重要的点是，我们需要在接口返回时将 TraceId 返回给前端，我们当然不可能在每个接口那里植入返回 TraceId 的代码，而是利用 ResponseBodyAdvice，可以在接口结果返回前，对返回结果进行进一步的处理。

下面上代码：

/**

 * Response Advice

 * @author winfun

 * @date 2020/10/30 3:47 下午

 **/

@RestControllerAdvice(basePackages = "com.winfun")

public class WebResponseModifyAdvice implements ResponseBodyAdvice {

    @Override

    public boolean supports(final MethodParameter methodParameter, final Class converterType) {

        // 返回 class 为 ApiResult（带 TraceId 属性） & converterType 为 Json 转换

        return methodParameter.getMethod().getReturnType().isAssignableFrom(ApiResult.class)

                && converterType.isAssignableFrom(MappingJackson2HttpMessageConverter.class);

    }

    @Override

    public Object beforeBodyWrite(final Object body, final MethodParameter methodParameter, final MediaType mediaType, final Class aClass,

                                  final ServerHttpRequest serverHttpRequest, final ServerHttpResponse serverHttpResponse) {

        // 设置 TraceId

        ((ApiResult<?>) body).setTraceId(MDC.get(TraceUtil.TRACE_ID));

        return body;

    }

}

3、dubbo-provider-one & dubbo-provider-two

服务提供者也是非常的简单，同样只需要使用上面消费者的 DubboTraceFiler 即可，里面会先从 RpcContext 中获取 Trace 信息，然后将 Dubbo 调用前的 Request 和调用后的 Response 都打印出来。就没有其他多余的动作了。

三、测试

1、接口如下：

接口非常简单，直接引入两个服务提供者的依赖，然后进行 Dubbo 接口的调用，最后将俩接口的返回值拼接起来返回给前端即可。

下面上代码：

/**

 * Say Hello & Hi

 * @author winfun

 * @date 2020/10/29 5:12 下午

 **/

@RequestMapping("/hello")

@RestController

public class HelloController {

    @DubboReference(check = false,lazy = true)

    private DubboServiceOne dubboServiceOne;

    @DubboReference(check = false,lazy = true)

    private DubboServiceTwo dubboServiceTwo;

    @GetMapping("/{name}")

    public ApiResult sayHello(@PathVariable("name") String name){

        String hello = dubboServiceOne.sayHello(name);

        String hi = dubboServiceTwo.sayHi(name);

        return ApiResult.success(hello+" "+hi);

    }

}

2、接口返回：

我们可以看到接口已经成功返回，并且可以看到 TraceId 为16042841032799628772：

接下来，我们看看消费者的后台打印是否是同一个 TraceId，无疑是一样的：

最后，我们要确定两个服务提供者是否能拿到对应的 Trace 信息：

服务提供者One：

服务提供者Two：

到此，我们可以发现：不管是前端，Dubbo 消费者，和 Dubbo 提供者，都是同一个 TraceId。这样的话，我们整个日志链路就跑通了。

四、最后

当然了，上面的日志全链路追踪只适合用于 Dubbo 作为 PRC 框架。假设我们使用 OpenFeign 的话，只能自己再做扩展了。

虽然项目代码不多，但是就不全部放上来了，如果大家感兴趣，可以去看看：全链路日志记录

巴特西

基于SLF4J的MDC机制和Dubbo的Filter机制，实现分布式系统的日志全链路追踪

原文链接：基于SLF4J的MDC机制和Dubbo的Filter机制，实现分布式系统的日志全链路追踪

一、日志系统

1、日志框架

2、搭建日志系统

二、项目搭建

1、dubbo-api：

2、dubbo-consumer

WebRequestFilter：

DubboTraceFilter：

ResponseBodyAdvice：

3、dubbo-provider-one & dubbo-provider-two

三、测试

1、接口如下：

2、接口返回：

四、最后

最新文章

热门文章