带你一步步实现最简单的分布式系统日志全链路追踪

柔情只为你懂 2022-11-22 07:43 461阅读 0赞

# 一、日志系统 #

## 1、日志框架 ##

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

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

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

而当我们的系统是分布式系统，服务之间通信通常都是使用 Dubbo 这个 RPC 框架。  
此时做日志就不是这么简单了，因为不同服务都是不同的实例，日志就无法做到一起了，怎么将服务间的调用串联起来，也是一个问题。

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

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

## 2、搭建日志系统 ##

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

**Spring Boot 引入日志依赖：**

<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>

**加入 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">
                
                <pattern>${LOG_PATTERN}</pattern>
            </layout>
            
            <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： ##

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center]

这里面最重要的是 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 框架。

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 1]

### 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 ##

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 2]  
服务提供者也是非常的简单，同样只需要使用上面消费者的 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**：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 3]

接下来，我们看看消费者的后台打印是否是同一个 TraceId，无疑是一样的：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 4]

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

服务提供者One：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 5]

服务提供者Two：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 6]  
到此，我们可以发现：不管是前端，Dubbo 消费者，和 Dubbo 提供者，都是同一个 TraceId。这样的话，我们整个日志链路就跑通了。

# 四、最后 #

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

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

[MDC]: https://www.jianshu.com/p/1dea7479eb07
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center]: /images/20221120/9a1b42e573744e2f9e3c584e7f4a5579.png
[dubbo-spring-boot-starter]: https://github.com/alibaba/dubbo-spring-boot-starter
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 1]: https://img-blog.csdnimg.cn/20201103210152931.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 2]: https://img-blog.csdnimg.cn/20201103210538335.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 3]: https://img-blog.csdnimg.cn/20201103210614532.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 4]: https://img-blog.csdnimg.cn/20201103210639656.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 5]: https://img-blog.csdnimg.cn/20201103210656143.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu_size_16_color_FFFFFF_t_70_pic_center 6]: https://img-blog.csdnimg.cn/20201103210713780.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0hvd2luZnVu,size_16,color_FFFFFF,t_70#pic_center
[Link 1]: https://github.com/Howinfun/study-in-work-and-life/tree/master/dubbo