日志格式化意图

​ 为了合作日志剖析系统ELK(ElasticSearch，Logstash，Kibana)方便解析日志文件，需求对日志文件的输出格式进行JSON格式化，我这儿使用的日志工具是logback（幸运的躲过了log4j的缝隙）+logstash-encoder包进行的封装的一个日志插件，该插件完成了日志JSON格式化，适配了多种中心件的链路追寻，支撑了中心件，RPC的长途调用的耗时计算等，而且完美支撑spring xml接入和spring boot接入两种方法。总的来说我这儿接入这个日志插件有三方面原因，1.日志格式化、2.日志链路追寻、3.中心进程耗时剖析。

​ 日志插件的快速接入方法这儿不做过多介绍了，可以参阅我的这个插件的开源项目，项目里供给了插件接入文档已经使用示例，项目地址是，也可以参阅我的博客文章。

Spring Cloud Gateway日志等级链路追寻设计

​ log-helper插件开端并不支撑Spring Cloud Gateway的链路追寻及转发下流接口的耗时统计，所以在Spring Cloud Alibaba开发脚手架搭建的进程中意识到了这一点，而且对其进行了适配，下面就简单说一下适配日志链路追寻的方法。

​ log-helper插件是根据MDC完成的链路追寻，各个中心件适配也是根据中心件的Filter或Interceptor完成的，所以Spring Cloud Gateway也是沿用这个思路。

​ Spring Cloud Gateway供给了过滤器功能，这儿简单介绍一下， Spring Cloud Gateway的过滤器， Spring Cloud Gateway供给了两个过滤器，一个大局过滤器，一个部分过滤器，下面简单介绍一下他们之间的差异。

  • 大局过滤器：GlobalFilter，这是一个接口，完成了该接口并完成filter方法，一切的恳求都会经过该过滤器。

  • 部分过滤器：AbstractGatewayFilterFactory，它是一个抽象类，承继该抽象类，并重写apply方法后需求在网关的装备文件中装备过滤器，假如不装备是不会流经该过滤器的，装备项是spring.cloud.gateway.routes.filters[].name中装备，详细装备示例如下：

    spring:
  cloud:
    gateway:
      routes:
        - id: account-svc
          uri: lb://account-svc
          predicates:
            - Path=/gateway/account/**
          filters:
            - StripPrefix=1
            # url黑名单 这是一个部分过滤器
            - name: BlackListUrlFilter
              args: 
                blackListUrl:
                  - /account/list

    BlackListUrlFilter对应的便是承继了AbstractGatewayFilterFactory的过滤器类，该完成要是Spring办理的。

​ 经过上面对Spring Cloud Gateway过滤器技术的介绍，下面咱们来完成咱们日志插件的过滤器，这儿选用的就应该是大局过滤器，因为关于网关来说，一切的恳求都应该经过该过滤器，而且这儿需求两个过滤器，一个是链路追寻的过滤器，一个是转发接口呼应时间计算的过滤器，下面详细介绍两个过滤器完成。

链路追寻过滤器-TracerFilter

​ 完成该过滤器后，便是要从Http恳求头中获取链路信息，这其实也是一种标准，假如整个系统都要完成链路追寻，那么咱们就必定要有链路追寻数据的标准，包含不限于 数据传输 标准，数据生成标准等，更高级的链路追寻标准可以参阅OpenTracing协议，该协议是APM软件的协议，我这儿也对该协议进行了一些参阅，并完成了自己的日志等级的Tracer。

​ 简单说链路追寻过滤器的逻辑便是从Http恳求头中获取链路数据，假如有链路数据就直接用获取到的数据组装Tracer数据，假如没有链路数据那么就直接生成Tracer数据，并将Tracer数据传递到转发的接口上，传递也是将Tracer数据经过Http恳求头进行传递。详细完成代码如下：

​ AbstractInterceptor是log-helper插件的抽象类，作用是从MDC中获取链路数据和调用其他链路前后做一些时间计算和日志打标签的功能，Tracer是log-helper供给的OpenTracing的参阅完成。

​ 值得注意的是这儿完成了Ordered接口而且完成了getOrder接口，该接口是Spring供给的顺序办理的接口，意图是告知整个过滤器调用链，该过滤器的优先级是最高的，也便是说要最先履行（Ordered.HIGHEST_PRECEDENCE）。

​ filter方法在处理完链路数据后调用了executeBefore(SCG_INVOKE_START + request.getURI().getPath());方法，该方法是给日志打了一个网关开端处理的标签，AbstractInterceptor的代码可以参阅log-helper。

@Slf4j
public class TracerFilter extends AbstractInterceptor implements GlobalFilter, Ordered {
    @Override
    public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {
        ServerHttpRequest request = exchange.getRequest();
        Mono<Void> voidMono = chain.filter(exchange.mutate()
                .request(builder -> builder.headers(httpHeaders -> {
                    List<String> traceList = httpHeaders.get(Tracer.TRACE_ID);
                    String traceId = null;
                    if (traceList != null && traceList.size() > 0) {
                        traceId = traceList.get(0);
                    }
                    List<String> spanList = httpHeaders.get(Tracer.SPAN_ID);
                    String spanId = null;
                    if (spanList != null && spanList.size() > 0) {
                        spanId = spanList.get(0);
                    }
                    List<String> parentList = httpHeaders.get(Tracer.PARENT_ID);
                    String parentId = null;
                    if (parentList != null && parentList.size() > 0) {
                        parentId = parentList.get(0);
                    }
                    Tracer.trace(traceId, spanId, parentId);
                    httpHeaders.set(Tracer.TRACE_ID, traceId());
                    httpHeaders.set(Tracer.PARENT_ID, parentId());
                    httpHeaders.set(Tracer.SPAN_ID, spanId());
                })).build());
        executeBefore(SCG_INVOKE_START + request.getURI().getPath());
        return voidMono;
    }
    @Override
    public int getOrder() {
        return Ordered.HIGHEST_PRECEDENCE;
    }
}

转发接口呼应耗时计算过滤器-RtFilter

​ 该接口的意图便是计算出网关处理完一个恳求的耗时，详细代码如下：

@Slf4j
public class RtFilter extends AbstractInterceptor implements GlobalFilter, Ordered {
    @Override
    public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {
        return chain.filter(exchange).transformDeferred(request -> {
            final long start = System.currentTimeMillis();
            return request.doFinally(s -> {
               MDC.put(START_TIME, String.valueOf(start));
               executeAfter(SCG_INVOKE_END);
            });
        });
    }
    @Override
    public int getOrder() {
        return Ordered.LOWEST_PRECEDENCE - 1;
    }
}

Spring Boot Autoconfigure完成

​ 两个过滤器完成完，咱们要将其在项目发动时加载到Spring中，下面便是经过Spring Boot主动安装完成；关于主动安装常识这儿不做过多介绍。

  • spring.factories

​ 在resources/META-INF/spring.factories中装备如下内容

org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
  com.redick.starter.configure.ScgTraceAutoConfiguration
  • Config类编写
@Configuration
public class ScgTraceAutoConfiguration {
    @Bean
    public TracerFilter tracerFilter() {
        return new TracerFilter();
    }
    @Bean
    public RtFilter rtFilter() {
        return new RtFilter();
    }
}

Spring Cloud Gateway日志链路追寻发测验

  • 预备两个服务
  1. ruuby-gateway：网关
  2. ruuby-account-svc：库存服务
  • 验证

​ 发动两个服务并经过网关恳求接口curl -X GET http://127.0.0.1:8081/gateway/account/list，日志结果如下：

ruuby-gateway日志：

​ 网关层的日志记录了链路追寻数据traceId,parentId,spanId和日志标签trace_tag，而且在第三条日志的duration中记录了此次恳求处理耗时490ms，可以看到经过这些链路数据可以在ELK平台上就可以进行日志剖析和问题排查了。

{"@timestamp":"2023-05-22T19:26:08.742+08:00","@version":"0.0.1","message":"scg_invoke_start/gateway/account/list","logger_name":"com.redick.support.AbstractInterceptor","thread_name":"reactor-http-nio-2","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"1","parentId":"0","trace_tag":"scg_invoke_start/gateway/account/list"}
{"@timestamp":"2023-05-22T19:26:08.829+08:00","@version":"0.0.1","message":"LoadBalancerCacheManager not available, returning delegate without caching.","logger_name":"org.springframework.cloud.loadbalancer.core.ServiceInstanceListSupplierBuilder","thread_name":"reactor-http-nio-2","level":"WARN","level_value":30000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"1","parentId":"0"}
{"@timestamp":"2023-05-22T19:26:09.364+08:00","@version":"0.0.1","message":"scg_invoke_end","logger_name":"com.redick.support.AbstractInterceptor","thread_name":"reactor-http-nio-4","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"1","parentId":"0","trace_tag":"scg_invoke_end","duration":490}

ruuby-account-svc日志：

​ ruuby-account-svc接口的日志如下，经过网关的链路数据traceId就可以查到ruuby-account-svc服务的日志，致此就完成了日志层面的链路追寻。

{"@timestamp":"2023-05-22T19:26:09.149+08:00","@version":"0.0.1","message":"开端处理","logger_name":"io.redick.cloud.account.controller.AccountController","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","log_pos":"开端处理","data":[]}
{"@timestamp":"2023-05-22T19:26:09.205+08:00","@version":"0.0.1","message":"slave2数据库","logger_name":"io.redick.cloud.datasource.context.DBContextHolder","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","log_pos":"进程"}
{"@timestamp":"2023-05-22T19:26:09.247+08:00","@version":"0.0.1","message":"开端履行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","trace_tag":"sql_exec_before"}
{"@timestamp":"2023-05-22T19:26:09.250+08:00","@version":"0.0.1","message":"完毕履行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","trace_tag":"sql_exec_after","duration":3}
{"@timestamp":"2023-05-22T19:26:09.277+08:00","@version":"0.0.1","message":"开端履行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","trace_tag":"sql_exec_before"}
{"@timestamp":"2023-05-22T19:26:09.285+08:00","@version":"0.0.1","message":"完毕履行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","trace_tag":"sql_exec_after","duration":8}
{"@timestamp":"2023-05-22T19:26:09.322+08:00","@version":"0.0.1","message":"处理完毕","logger_name":"io.redick.cloud.account.controller.AccountController","thread_name":"http-nio-8088-exec-1","level":"INFO","level_value":20000,"traceId":"44a806f6-ea41-4e3b-85a5-477052d77474","spanId":"2","request_type":"account#list","parentId":"1","log_pos":"处理完毕","data":{"msg":null,"serialVersionUID":1,"SUCCESS":200,"code":200,"data":[{"pageIndex":0,"pageSize":10,"orderByColumn":"","asc":"asc","productId":"123","totalCount":200,"productName":"华为P100","beginTime":null,"endTime":null,"productDesc":"华为手机牛逼"},{"pageIndex":0,"pageSize":10,"orderByColumn":"","asc":"asc","productId":"200","totalCount":100,"productName":"华为Mate100","beginTime":null,"endTime":null,"productDesc":"华为手机真牛逼"}],"FAIL":500},"duration":172,"trace_tag":"endpoint_done","result":"成功"}

源码

源码参阅GitHub，假如对您有协助费事点个赞支撑下，谢谢！