关于spring-cloud:SpringCloud升级之路20200x版42SpringCloudGateway-现有的可供分析的请求日志以及缺陷

本系列代码地址：https://github.com/JoJoTec/sp…
网关因为是所有内部用户申请的入口，记录这些申请中咱们须要的元素，对于线上监控以及业务问题定位，是十分重要的。并且，在这些元素中，链路信息也是十分重要的。通过链路信息，咱们能够找到申请调用全链路相干的日志。并且，网关也是大部分申请链路起始的中央，记录申请中的元素的同时，也要带上链路信息。

咱们须要在网关记录每个申请的：

HTTP 相干元素：
URL 相干信息
申请信息，例如 HTTP HEADER，申请工夫等等
某些类型的申请体
响应信息，例如响应码
某些类型响应的响应体
链路信息
现有的可供剖析的日志以及缺点

首先咱们来看 Spring Cloud Gateway 中自身咱们能够利用的日志。Spring Cloud Gateway 基于 Spring-WebFlux，Spring-WebFlux 基于 Project Reactor，咱们没有在网关退出额定的 Web 容器依赖，所以 Web 容器用的是默认的基于 Project Reactor 的 reactor-netty 实现的 Web 容器。

netty 抓包日志

应用了 netty 咱们能够联想到 netty 的抓包日志，Spring Cloud Gateway 封装了这个性能，并裸露了配置。Spring Cloud Gateway 是一个网关，他会作为 HTTP 服务器承受 HTTP 申请的同时，还在作为 HTTP 客户端将申请转发到上游的微服务。所以，这里有两种抓包日志，一种是作为 HTTP 服务器接管到的申请和响应，另一种是做为 HTTP 客户端收回的申请和响应。别离对应两个配置：

spring.cloud.gateway:
httpserver:

wiretap: true

httpclient:

wiretap: true

常常有读者私信我问如何看 spring cloud 有哪些配置，官网文档感觉不够分明全面。我个别是看源码，然而鉴于很多人没有精力去钻研源码，一种偷懒的形式是去看 jar 包外面的 spring-configuration-metadata.json。外面蕴含了比拟全的配置，以及配置类（如果存在的话），这是很不便的。例如咱们这里的两个配置，在这个 json 中对应：

{
“name”: “spring.cloud.gateway.httpclient.wiretap”,
“type”: “java.lang.Boolean”,
“description”: “Enables wiretap debugging for Netty HttpClient.”,
“sourceType”: “org.springframework.cloud.gateway.config.HttpClientProperties”,
“defaultValue”: false
},
{
“name”: “spring.cloud.gateway.httpserver.wiretap”,
“type”: “java.lang.Boolean”,
“description”: “Enables wiretap debugging for Netty HttpServer.”,
“defaultValue”: “false”
},
能够看出，spring.cloud.gateway.httpclient.wiretap 对应配置类 org.springframework.cloud.gateway.config.HttpClientProperties（这个配置类外面的配置咱们前面还会用到，到时候会详细分析其中的配置项），默认为 false。spring.cloud.gateway.httpserver.wiretap 没有配置类，他是被间接应用的，对应源码：

GatewayAutoConfiguration.java

@Bean
@ConditionalOnProperty(name = “spring.cloud.gateway.httpserver.wiretap”)
public NettyWebServerFactoryCustomizer nettyServerWiretapCustomizer(Environment environment,

    ServerProperties serverProperties) {return new NettyWebServerFactoryCustomizer(environment, serverProperties) {
    @Override
    public void customize(NettyReactiveWebServerFactory factory) {factory.addServerCustomizers(httpServer -> httpServer.wiretap(true));
        super.customize(factory);
    }
};

}
减少这两个配置为 true 之后，减少日志输入配置，我这里应用的是 log4j2（其实就是设置 reactor.netty.http.server.HttpServer 和 reactor.netty.http.server.HttpClient 的日志级别为 DEBUG）：

<AsyncLogger name=”reactor.netty.http.server.HttpServer” level=”debug” additivity=”false” includeLocation=”true”>

<appender-ref ref="console" />

</AsyncLogger>
<AsyncLogger name=”reactor.netty.http.client.HttpClient” level=”debug” additivity=”false” includeLocation=”true”>

<appender-ref ref="console" />

</AsyncLogger>
而后，再次申请咱们后面实现的网关，能够看到相似于上面的日志：

2021-11-27 01:16:06,262 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] READ: 466B

     +-------------------------------------------------+
     |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

2021-11-27 01:16:06,262 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@317ee5cc
2021-11-27 01:16:06,378 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] READ COMPLETE
2021-11-27 01:16:06,381 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1] REGISTERED
2021-11-27 01:16:06,437 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1] CONNECT: httpbin.org/18.232.227.86:80
2021-11-27 01:16:06,656 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1, L:/172.168.160.198:52819 – R:httpbin.org/18.232.227.86:80] ACTIVE
2021-11-27 01:16:06,672 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1-1, L:/172.168.160.198:52819 – R:httpbin.org/18.232.227.86:80] WRITE: 775B

     +-------------------------------------------------+
     |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

2021-11-27 01:16:06,672 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1-1, L:/172.168.160.198:52819 – R:httpbin.org/18.232.227.86:80] FLUSH
2021-11-27 01:16:06,890 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1-1, L:/172.168.160.198:52819 – R:httpbin.org/18.232.227.86:80] READ: 1315B

     +-------------------------------------------------+
     |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

2021-11-27 01:16:06,904 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] WRITE: 207B

     +-------------------------------------------------+
     |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

2021-11-27 01:16:06,904 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] FLUSH
2021-11-27 01:16:06,909 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] WRITE: 1084B

     +-------------------------------------------------+
     |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

2021-11-27 01:16:06,909 DEBUG [sports,,] [10632] reactor-http-nio-6:[id:6666c1d1, L:/172.168.160.198:52819 – R:httpbin.org/18.232.227.86:80] READ COMPLETE
2021-11-27 01:16:06,910 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] FLUSH
2021-11-27 01:16:06,910 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] WRITE: 0B
2021-11-27 01:16:06,910 DEBUG [sports,,] [10632] reactor-http-nio-2:[id:1277d54e-2, L:/127.0.0.1:8181 – R:/127.0.0.1:52797] FLUSH

能够从日志中看出上面比拟重要的信息：

从抓包日志从能够得出 HTTP 申请与响应包中的所有内容。
这里的日志，因为没被 spring-cloud-sleuth 包装，所以日志自身的占位符没有相干链路信息
然而从包中，能够看到 spring-cloud-sleuth 的链路信息，这里是: “X-B3-Parentspanid”: “ef9653a0003ed68e”, “X-B3-Sampled”: “0”, “X-B3-Spanid”: “82b6a0202dc1566b”, “X-B3-Traceid”: “ef9653a0003ed68e”,
netty 自身有 traceId，即这里的 6666c1d1 和 1277d54e (别离是作为 HttpServer 承受申请和作为 HttpClient 转发申请后盾微服务)，这样其实就能够将 spring-cloud-sleuth 的链路信息与 netty 的链路信息联合在一起
这些日志很全面，然而有上面一些不好用的问题：

只能输入所有申请响应的包内容，并不能定制输入哪些内容。例如对于文件上传申请，咱们其实并不想看他的申请体，然而这里无奈定制化。
日志太多了，会影响咱们的性能。
HttpWebHandlerAdapter 的 TRACE 日志

在系列后面文章的源码剖析中，咱们晓得在入口的 HttpWebHandlerAdapter 中有申请与响应日志，能够通过上面的配置进行启用：

<AsyncLogger name=”org.springframework.web.server.adapter.HttpWebHandlerAdapter” level=”trace” additivity=”false” includeLocation=”true”>

<appender-ref ref="console" />

</AsyncLogger>
这样就能启用相似于上面的日志：

2021-11-27 01:25:28,472 TRACE [sports,,] [16188] reactor-http-nio-2:[8d5138d1-3] HTTP GET “/test-ss/anything”, headers={masked}
2021-11-27 01:25:28,696 TRACE [sports,,] [16188] reactor-http-nio-2:[8d5138d1-3] Completed 200 OK, headers={masked}
如何让 headers 不要被掩码，能够通过上面的配置实现：

spring.codec:
log-request-details: true
这个配置对应的配置类是：CodecProperties，通过源码咱们也能够发现，咱们还能够在这里限度 body 的大小：

CodecProperties.java

@ConfigurationProperties(prefix = “spring.codec”)
public class CodecProperties {

private boolean logRequestDetails;
private DataSize maxInMemorySize;

}
加上配置后，日志如下：

2021-11-27 01:32:50,501 TRACE [sports,,] [17668] reactor-http-nio-2:[ecf9f55a-1] HTTP GET “/test-ss/anything”, headers=[Host:”127.0.0.1:8181″, Connection:”keep-alive”, Cache-Control:”max-age=0″, Upgrade-Insecure-Requests:”1″, User-Agent:”Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.25 Safari/537.36 Core/1.70.3879.400 QQBrowser/10.8.4552.400″, Accept:”text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8″, Accept-Encoding:”gzip, deflate, br”, Accept-Language:”zh-CN,zh;q=0.9″]
2021-11-27 01:32:51,212 TRACE [sports,,] [17668] reactor-http-nio-2:[ecf9f55a-1] Completed 200 OK, headers=[Date:”Sat, 27 Nov 2021 01:32:48 GMT”, Content-Type:”application/json”, Server:”gunicorn/19.9.0″, Access-Control-Allow-Origin:”*”, Access-Control-Allow-Credentials:”true”, content-length:”1084″]
然而这个日志内容太少，只蕴含申请和响应头，并且没有 spring-cloud-sleuth 相干的链路信息。

AccessLog

Spring Cloud Gateway 应用基于 reactor-netty 的 http 服务器，在 spring-boot 的封装中，能够通过增加 NettyServerCustomizer Bean 来实现增加自定义 AccessLog。AccessLog 蕴含的元素有：

AccessLogArgProvider.java

public interface AccessLogArgProvider {

@Nullable
@Deprecated
String zonedDateTime();

@Nullable
ZonedDateTime accessDateTime();

@Nullable
SocketAddress remoteAddress();

@Nullable
CharSequence method();

@Nullable
CharSequence uri();

@Nullable
String protocol();

@Nullable
String user();

@Nullable
CharSequence status();

long contentLength();

long duration();

@Nullable
CharSequence requestHeader(CharSequence name);

@Nullable
CharSequence responseHeader(CharSequence name);

@Nullable
Map<CharSequence, Set<Cookie>> cookies();

}

能够看出外面没有 spring cloud sleuth 相干的链路信息，然而咱们能够通过实现 Global Filter 将链路信息退出 Response 的 Header 中，并且通过 AccessLogArgProvider 的 requestHeader 将这些 Header 输入到 accesslog：

package com.github.jojotech.spring.cloud.apigateway.filter;

import java.util.List;

import lombok.extern.log4j.Log4j2;
import reactor.core.publisher.Mono;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.cloud.gateway.filter.GatewayFilterChain;
import org.springframework.cloud.gateway.filter.GlobalFilter;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceContext;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.core.Ordered;
import org.springframework.http.HttpHeaders;
import org.springframework.http.server.reactive.ServerHttpResponse;
import org.springframework.stereotype.Component;
import org.springframework.web.server.ServerWebExchange;

@Log4j2
@Component
public class CommonTraceFilter implements GlobalFilter, Ordered {

public static final String TRACE_ID = "traceId";
public static final String SPAN_ID = "spanId";

@Autowired
private Tracer tracer;

@Override
public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {Span span = tracer.currentSpan();
    if (span == null) {span = tracer.nextSpan();
    }
    TraceContext context = span.context();
    ServerHttpResponse response = exchange.getResponse();
    HttpHeaders headers = response.getHeaders();
    headers.put(TRACE_ID, List.of(context.traceId()));
    headers.put(SPAN_ID, List.of(context.spanId()));

    return chain.filter(exchange);
}

@Override
public int getOrder() {
    // 须要在所有的 Filter 之前，拿到 trace 信息
    return Ordered.HIGHEST_PRECEDENCE;
}

}

而后，通过实现 NettyServerCustomizer 注册一个 Bean 来配置 Access Log。

package com.github.jojotech.spring.cloud.apigateway.filter;

import java.net.InetSocketAddress;
import java.net.SocketAddress;

import reactor.netty.http.server.HttpServer;
import reactor.netty.http.server.logging.AccessLog;
import reactor.netty.http.server.logging.AccessLogFactory;
import reactor.util.annotation.Nullable;

import org.springframework.boot.web.embedded.netty.NettyServerCustomizer;
import org.springframework.stereotype.Component;

@Component
public class AccessLogNettyServerCustomizer implements NettyServerCustomizer {

static final String DEFAULT_LOG_FORMAT =
        "{},{} -> {} - {} [{}] \"{} {} {}\"{} {} {} ms";
static final String MISSING = "-";

@Override
public HttpServer apply(HttpServer httpServer) {
    httpServer = httpServer.accessLog(true, AccessLogFactory.createFilter(
            accessLogArgProvider -> {
                // 所有的都打印
                return true;
            }, accessLogArgProvider -> {
                return AccessLog.create(DEFAULT_LOG_FORMAT, accessLogArgProvider
                                .responseHeader(CommonTraceFilter.TRACE_ID) == null ? MISSING : accessLogArgProvider
                                .responseHeader(CommonTraceFilter.TRACE_ID), accessLogArgProvider
                                .responseHeader(CommonTraceFilter.SPAN_ID) == null ? MISSING : accessLogArgProvider
                                .responseHeader(CommonTraceFilter.SPAN_ID), applyAddress(accessLogArgProvider
                                .remoteAddress()), accessLogArgProvider.user(),
                        accessLogArgProvider.zonedDateTime(), accessLogArgProvider.method(), accessLogArgProvider
                                .uri(), accessLogArgProvider.protocol(), accessLogArgProvider.status(),
                        accessLogArgProvider.contentLength() > -1 ? accessLogArgProvider
                                .contentLength() : MISSING, accessLogArgProvider.duration());
            })
    );
    return httpServer;
}

static String applyAddress(@Nullable SocketAddress socketAddress) {if (socketAddress instanceof InetSocketAddress) {InetSocketAddress inetSocketAddress = (InetSocketAddress) socketAddress;
        return inetSocketAddress.getHostString() + ":" + inetSocketAddress.getPort();
    }
    else {return MISSING;}
}

}

这样，咱们就能够失去像上面的 access log：

2021-11-27 03:56:10,948 INFO [sports,,] [8536] reactor-http-nio-2:baa69b779a8497eb,baa69b779a8497eb -> 127.0.0.1:64196 – – [2021-11-27T03:56:10.720844200Z[Etc/GMT]] “GET /test-ss/anything HTTP/1.1” 200 1084 228 ms
accesslog 的也不能输入 body，所以咱们还是须要定制本人的日志 Filter。

咱们在下一节，会开始实现咱们本人定制的日志 Filter

微信搜寻“我的编程喵”关注公众号，每日一刷，轻松晋升技术，斩获各种 offer：