zhanghaxi

zhanghaxi

关注
发信
关注(28)粉丝(399)

SpringCloud升级之路2020.0.x版-42.SpringCloudGateway 现有的可供分析的请求日志以及缺陷

本系列代码地址：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：

03-05 16:14
Powered by LMLPHP ©2024 zhanghaxi 0.085627