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

头像
已注销
    阅读 25 分钟
    头图

    本系列代码地址：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 |
    0000000047 45 54 20 2f 74 65 73 74 2d 73 73 2f 61 6e 79GET /test-ss/any
    0000001074 68 69 6e 67 20 48 54 54 50 2f 31 2e 31 0d 0athing HTTP/1.1..
    0000002048 6f 73 74 3a 20 31 32 37 2e 30 2e 30 2e 31 3aHost: 127.0.0.1:
    0000003038 31 38 31 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e8181..Connection
    000000403a 20 6b 65 65 70 2d 61 6c 69 76 65 0d 0a 43 61: keep-alive..Ca
    0000005063 68 65 2d 43 6f 6e 74 72 6f 6c 3a 20 6d 61 78che-Control: max
    000000602d 61 67 65 3d 30 0d 0a 55 70 67 72 61 64 65 2d-age=0..Upgrade-
    0000007049 6e 73 65 63 75 72 65 2d 52 65 71 75 65 73 74Insecure-Request
    0000008073 3a 20 31 0d 0a 55 73 65 72 2d 41 67 65 6e 74s: 1..User-Agent
    000000903a 20 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 28 57: Mozilla/5.0 (W
    000000a069 6e 64 6f 77 73 20 4e 54 20 31 30 2e 30 3b 20indows NT 10.0;
    000000b057 4f 57 36 34 29 20 41 70 70 6c 65 57 65 62 4bWOW64) AppleWebK
    000000c069 74 2f 35 33 37 2e 33 36 20 28 4b 48 54 4d 4cit/537.36 (KHTML
    000000d02c 20 6c 69 6b 65 20 47 65 63 6b 6f 29 20 43 68, like Gecko) Ch
    000000e072 6f 6d 65 2f 37 30 2e 30 2e 33 35 33 38 2e 32rome/70.0.3538.2
    000000f035 20 53 61 66 61 72 69 2f 35 33 37 2e 33 36 205 Safari/537.36
    0000010043 6f 72 65 2f 31 2e 37 30 2e 33 38 37 39 2e 34Core/1.70.3879.4
    0000011030 30 20 51 51 42 72 6f 77 73 65 72 2f 31 30 2e00 QQBrowser/10.
    0000012038 2e 34 35 35 32 2e 34 30 30 0d 0a 41 63 63 658.4552.400..Acce
    0000013070 74 3a 20 74 65 78 74 2f 68 74 6d 6c 2c 61 70pt: text/html,ap
    0000014070 6c 69 63 61 74 69 6f 6e 2f 78 68 74 6d 6c 2bplication/xhtml+
    0000015078 6d 6c 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2fxml,application/
    0000016078 6d 6c 3b 71 3d 30 2e 39 2c 69 6d 61 67 65 2fxml;q=0.9,image/
    0000017077 65 62 70 2c 69 6d 61 67 65 2f 61 70 6e 67 2cwebp,image/apng,
    000001802a 2f 2a 3b 71 3d 30 2e 38 0d 0a 41 63 63 65 70/;q=0.8..Accep
    0000019074 2d 45 6e 63 6f 64 69 6e 67 3a 20 67 7a 69 70t-Encoding: gzip
    000001a02c 20 64 65 66 6c 61 74 65 2c 20 62 72 0d 0a 41, deflate, br..A
    000001b063 63 65 70 74 2d 4c 61 6e 67 75 61 67 65 3a 20ccept-Language:
    000001c07a 68 2d 43 4e 2c 7a 68 3b 71 3d 30 2e 39 0d 0azh-CN,zh;q=0.9..
    000001d00d 0a..

    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 |
    0000000047 45 54 20 2f 61 6e 79 74 68 69 6e 67 20 48 54GET /anything HT
    0000001054 50 2f 31 2e 31 0d 0a 43 61 63 68 65 2d 43 6fTP/1.1..Cache-Co
    000000206e 74 72 6f 6c 3a 20 6d 61 78 2d 61 67 65 3d 30ntrol: max-age=0
    000000300d 0a 55 70 67 72 61 64 65 2d 49 6e 73 65 63 75..Upgrade-Insecu
    0000004072 65 2d 52 65 71 75 65 73 74 73 3a 20 31 0d 0are-Requests: 1..
    0000005055 73 65 72 2d 41 67 65 6e 74 3a 20 4d 6f 7a 69User-Agent: Mozi
    000000606c 6c 61 2f 35 2e 30 20 28 57 69 6e 64 6f 77 73lla/5.0 (Windows
    0000007020 4e 54 20 31 30 2e 30 3b 20 57 4f 57 36 34 29NT 10.0; WOW64)
    0000008020 41 70 70 6c 65 57 65 62 4b 69 74 2f 35 33 37AppleWebKit/537
    000000902e 33 36 20 28 4b 48 54 4d 4c 2c 20 6c 69 6b 65.36 (KHTML, like
    000000a020 47 65 63 6b 6f 29 20 43 68 72 6f 6d 65 2f 37Gecko) Chrome/7
    000000b030 2e 30 2e 33 35 33 38 2e 32 35 20 53 61 66 610.0.3538.25 Safa
    000000c072 69 2f 35 33 37 2e 33 36 20 43 6f 72 65 2f 31ri/537.36 Core/1
    000000d02e 37 30 2e 33 38 37 39 2e 34 30 30 20 51 51 42.70.3879.400 QQB
    000000e072 6f 77 73 65 72 2f 31 30 2e 38 2e 34 35 35 32rowser/10.8.4552
    000000f02e 34 30 30 0d 0a 41 63 63 65 70 74 3a 20 74 65.400..Accept: te
    0000010078 74 2f 68 74 6d 6c 2c 61 70 70 6c 69 63 61 74xt/html,applicat
    0000011069 6f 6e 2f 78 68 74 6d 6c 2b 78 6d 6c 2c 61 70ion/xhtml+xml,ap
    0000012070 6c 69 63 61 74 69 6f 6e 2f 78 6d 6c 3b 71 3dplication/xml;q=
    0000013030 2e 39 2c 69 6d 61 67 65 2f 77 65 62 70 2c 690.9,image/webp,i
    000001406d 61 67 65 2f 61 70 6e 67 2c 2a 2f 2a 3b 71 3dmage/apng,/;q=
    0000015030 2e 38 0d 0a 41 63 63 65 70 74 2d 45 6e 63 6f0.8..Accept-Enco
    0000016064 69 6e 67 3a 20 67 7a 69 70 2c 20 64 65 66 6cding: gzip, defl
    0000017061 74 65 2c 20 62 72 0d 0a 41 63 63 65 70 74 2date, br..Accept-
    000001804c 61 6e 67 75 61 67 65 3a 20 7a 68 2d 43 4e 2cLanguage: zh-CN,
    000001907a 68 3b 71 3d 30 2e 39 0d 0a 46 6f 72 77 61 72zh;q=0.9..Forwar
    000001a064 65 64 3a 20 70 72 6f 74 6f 3d 68 74 74 70 3bded: proto=http;
    000001b068 6f 73 74 3d 22 31 32 37 2e 30 2e 30 2e 31 3ahost="127.0.0.1:
    000001c038 31 38 31 22 3b 66 6f 72 3d 22 31 32 37 2e 308181";for="127.0
    000001d02e 30 2e 31 3a 35 32 37 39 37 22 0d 0a 58 2d 46.0.1:52797"..X-F
    000001e06f 72 77 61 72 64 65 64 2d 46 6f 72 3a 20 31 32orwarded-For: 12
    000001f037 2e 30 2e 30 2e 31 0d 0a 58 2d 46 6f 72 77 617.0.0.1..X-Forwa
    0000020072 64 65 64 2d 50 72 6f 74 6f 3a 20 68 74 74 70rded-Proto: http
    000002100d 0a 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 72..X-Forwarded-Pr
    0000022065 66 69 78 3a 20 2f 74 65 73 74 2d 73 73 0d 0aefix: /test-ss..
    0000023058 2d 46 6f 72 77 61 72 64 65 64 2d 50 6f 72 74X-Forwarded-Port
    000002403a 20 38 31 38 31 0d 0a 58 2d 46 6f 72 77 61 72: 8181..X-Forwar
    0000025064 65 64 2d 48 6f 73 74 3a 20 31 32 37 2e 30 2eded-Host: 127.0.
    0000026030 2e 31 3a 38 31 38 31 0d 0a 68 6f 73 74 3a 200.1:8181..host:
    0000027068 74 74 70 62 69 6e 2e 6f 72 67 0d 0a 58 2d 42httpbin.org..X-B
    0000028033 2d 54 72 61 63 65 49 64 3a 20 65 66 39 36 353-TraceId: ef965
    0000029033 61 30 30 30 33 65 64 36 38 65 0d 0a 58 2d 423a0003ed68e..X-B
    000002a033 2d 53 70 61 6e 49 64 3a 20 38 32 62 36 61 303-SpanId: 82b6a0
    000002b032 30 32 64 63 31 35 36 36 62 0d 0a 58 2d 42 33202dc1566b..X-B3
    000002c02d 50 61 72 65 6e 74 53 70 61 6e 49 64 3a 20 65-ParentSpanId: e
    000002d066 39 36 35 33 61 30 30 30 33 65 64 36 38 65 0df9653a0003ed68e.
    000002e00a 58 2d 42 33 2d 53 61 6d 70 6c 65 64 3a 20 30.X-B3-Sampled: 0
    000002f00d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68..content-length
    000003003a 20 30 0d 0a 0d 0a: 0....

    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 |
    0000000048 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0dHTTP/1.1 200 OK.
    000000100a 44 61 74 65 3a 20 53 61 74 2c 20 32 37 20 4e.Date: Sat, 27 N
    000000206f 76 20 32 30 32 31 20 30 31 3a 31 36 3a 30 34ov 2021 01:16:04
    0000003020 47 4d 54 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79GMT..Content-Ty
    0000004070 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2fpe: application/
    000000506a 73 6f 6e 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65json..Content-Le
    000000606e 67 74 68 3a 20 31 30 38 34 0d 0a 43 6f 6e 6ength: 1084..Conn
    0000007065 63 74 69 6f 6e 3a 20 6b 65 65 70 2d 61 6c 69ection: keep-ali
    0000008076 65 0d 0a 53 65 72 76 65 72 3a 20 67 75 6e 69ve..Server: guni
    0000009063 6f 72 6e 2f 31 39 2e 39 2e 30 0d 0a 41 63 63corn/19.9.0..Acc
    000000a065 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c 6c 6fess-Control-Allo
    000000b077 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a 41 63 63w-Origin: *..Acc
    000000c065 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c 6c 6fess-Control-Allo
    000000d077 2d 43 72 65 64 65 6e 74 69 61 6c 73 3a 20 74w-Credentials: t
    000000e072 75 65 0d 0a 0d 0a 7b 0a 20 20 22 61 72 67 73rue....{. "args
    000000f022 3a 20 7b 7d 2c 20 0a 20 20 22 64 61 74 61 22": {}, . "data"
    000001003a 20 22 22 2c 20 0a 20 20 22 66 69 6c 65 73 22: "", . "files"
    000001103a 20 7b 7d 2c 20 0a 20 20 22 66 6f 72 6d 22 3a: {}, . "form":
    0000012020 7b 7d 2c 20 0a 20 20 22 68 65 61 64 65 72 73{}, . "headers
    0000013022 3a 20 7b 0a 20 20 20 20 22 41 63 63 65 70 74": {. "Accept
    0000014022 3a 20 22 74 65 78 74 2f 68 74 6d 6c 2c 61 70": "text/html,ap
    0000015070 6c 69 63 61 74 69 6f 6e 2f 78 68 74 6d 6c 2bplication/xhtml+
    0000016078 6d 6c 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2fxml,application/
    0000017078 6d 6c 3b 71 3d 30 2e 39 2c 69 6d 61 67 65 2fxml;q=0.9,image/
    0000018077 65 62 70 2c 69 6d 61 67 65 2f 61 70 6e 67 2cwebp,image/apng,
    000001902a 2f 2a 3b 71 3d 30 2e 38 22 2c 20 0a 20 20 20/;q=0.8", .
    000001a020 22 41 63 63 65 70 74 2d 45 6e 63 6f 64 69 6e"Accept-Encodin
    000001b067 22 3a 20 22 67 7a 69 70 2c 20 64 65 66 6c 61g": "gzip, defla
    000001c074 65 2c 20 62 72 22 2c 20 0a 20 20 20 20 22 41te, br", . "A
    000001d063 63 65 70 74 2d 4c 61 6e 67 75 61 67 65 22 3accept-Language":
    000001e020 22 7a 68 2d 43 4e 2c 7a 68 3b 71 3d 30 2e 39"zh-CN,zh;q=0.9
    000001f022 2c 20 0a 20 20 20 20 22 43 61 63 68 65 2d 43", . "Cache-C
    000002006f 6e 74 72 6f 6c 22 3a 20 22 6d 61 78 2d 61 67ontrol": "max-ag
    0000021065 3d 30 22 2c 20 0a 20 20 20 20 22 43 6f 6e 74e=0", . "Cont
    0000022065 6e 74 2d 4c 65 6e 67 74 68 22 3a 20 22 30 22ent-Length": "0"
    000002302c 20 0a 20 20 20 20 22 46 6f 72 77 61 72 64 65, . "Forwarde
    0000024064 22 3a 20 22 70 72 6f 74 6f 3d 68 74 74 70 3bd": "proto=http;
    0000025068 6f 73 74 3d 5c 22 31 32 37 2e 30 2e 30 2e 31host=\"127.0.0.1
    000002603a 38 31 38 31 5c 22 3b 66 6f 72 3d 5c 22 31 32:8181\";for=\"12
    0000027037 2e 30 2e 30 2e 31 3a 35 32 37 39 37 5c 22 227.0.0.1:52797\""
    000002802c 20 0a 20 20 20 20 22 48 6f 73 74 22 3a 20 22, . "Host": "
    0000029068 74 74 70 62 69 6e 2e 6f 72 67 22 2c 20 0a 20httpbin.org", .
    000002a020 20 20 22 55 70 67 72 61 64 65 2d 49 6e 73 65"Upgrade-Inse
    000002b063 75 72 65 2d 52 65 71 75 65 73 74 73 22 3a 20cure-Requests":
    000002c022 31 22 2c 20 0a 20 20 20 20 22 55 73 65 72 2d"1", . "User-
    000002d041 67 65 6e 74 22 3a 20 22 4d 6f 7a 69 6c 6c 61Agent": "Mozilla
    000002e02f 35 2e 30 20 28 57 69 6e 64 6f 77 73 20 4e 54/5.0 (Windows NT
    000002f020 31 30 2e 30 3b 20 57 4f 57 36 34 29 20 41 7010.0; WOW64) Ap
    0000030070 6c 65 57 65 62 4b 69 74 2f 35 33 37 2e 33 36pleWebKit/537.36
    0000031020 28 4b 48 54 4d 4c 2c 20 6c 69 6b 65 20 47 65(KHTML, like Ge
    0000032063 6b 6f 29 20 43 68 72 6f 6d 65 2f 37 30 2e 30cko) Chrome/70.0
    000003302e 33 35 33 38 2e 32 35 20 53 61 66 61 72 69 2f.3538.25 Safari/
    0000034035 33 37 2e 33 36 20 43 6f 72 65 2f 31 2e 37 30537.36 Core/1.70
    000003502e 33 38 37 39 2e 34 30 30 20 51 51 42 72 6f 77.3879.400 QQBrow
    0000036073 65 72 2f 31 30 2e 38 2e 34 35 35 32 2e 34 30ser/10.8.4552.40
    0000037030 22 2c 20 0a 20 20 20 20 22 58 2d 41 6d 7a 6e0", . "X-Amzn
    000003802d 54 72 61 63 65 2d 49 64 22 3a 20 22 52 6f 6f-Trace-Id": "Roo
    0000039074 3d 31 2d 36 31 61 31 38 36 64 34 2d 34 31 38t=1-61a186d4-418
    000003a032 30 65 31 66 36 33 39 30 32 64 34 64 33 63 6320e1f63902d4d3cc
    000003b064 38 62 39 64 22 2c 20 0a 20 20 20 20 22 58 2dd8b9d", . "X-
    000003c042 33 2d 50 61 72 65 6e 74 73 70 61 6e 69 64 22B3-Parentspanid"
    000003d03a 20 22 65 66 39 36 35 33 61 30 30 30 33 65 64: "ef9653a0003ed
    000003e036 38 65 22 2c 20 0a 20 20 20 20 22 58 2d 42 3368e", . "X-B3
    000003f02d 53 61 6d 70 6c 65 64 22 3a 20 22 30 22 2c 20-Sampled": "0",
    000004000a 20 20 20 20 22 58 2d 42 33 2d 53 70 61 6e 69. "X-B3-Spani
    0000041064 22 3a 20 22 38 32 62 36 61 30 32 30 32 64 63d": "82b6a0202dc
    0000042031 35 36 36 62 22 2c 20 0a 20 20 20 20 22 58 2d1566b", . "X-
    0000043042 33 2d 54 72 61 63 65 69 64 22 3a 20 22 65 66B3-Traceid": "ef
    0000044039 36 35 33 61 30 30 30 33 65 64 36 38 65 22 2c9653a0003ed68e",
    0000045020 0a 20 20 20 20 22 58 2d 46 6f 72 77 61 72 64. "X-Forward
    0000046065 64 2d 48 6f 73 74 22 3a 20 22 31 32 37 2e 30ed-Host": "127.0
    000004702e 30 2e 31 3a 38 31 38 31 22 2c 20 0a 20 20 20.0.1:8181", .
    0000048020 22 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 72"X-Forwarded-Pr
    0000049065 66 69 78 22 3a 20 22 2f 74 65 73 74 2d 73 73efix": "/test-ss
    000004a022 0a 20 20 7d 2c 20 0a 20 20 22 6a 73 6f 6e 22". }, . "json"
    000004b03a 20 6e 75 6c 6c 2c 20 0a 20 20 22 6d 65 74 68: null, . "meth
    000004c06f 64 22 3a 20 22 47 45 54 22 2c 20 0a 20 20 22od": "GET", . "
    000004d06f 72 69 67 69 6e 22 3a 20 22 31 32 37 2e 30 2eorigin": "127.0.
    000004e030 2e 31 2c 20 35 39 2e 31 35 32 2e 32 35 34 2e0.1, 59.152.254.
    000004f032 33 38 22 2c 20 0a 20 20 22 75 72 6c 22 3a 20238", . "url":
    0000050022 68 74 74 70 3a 2f 2f 31 32 37 2e 30 2e 30 2e"http://127.0.0.
    0000051031 3a 38 31 38 31 2f 61 6e 79 74 68 69 6e 67 221:8181/anything"
    000005200a 7d 0a.}.

    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 |
    0000000048 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0dHTTP/1.1 200 OK.
    000000100a 44 61 74 65 3a 20 53 61 74 2c 20 32 37 20 4e.Date: Sat, 27 N
    000000206f 76 20 32 30 32 31 20 30 31 3a 31 36 3a 30 34ov 2021 01:16:04
    0000003020 47 4d 54 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79GMT..Content-Ty
    0000004070 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2fpe: application/
    000000506a 73 6f 6e 0d 0a 53 65 72 76 65 72 3a 20 67 75json..Server: gu
    000000606e 69 63 6f 72 6e 2f 31 39 2e 39 2e 30 0d 0a 41nicorn/19.9.0..A
    0000007063 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6cccess-Control-Al
    000000806c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a 41low-Origin: *..A
    0000009063 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6cccess-Control-Al
    000000a06c 6f 77 2d 43 72 65 64 65 6e 74 69 61 6c 73 3alow-Credentials:
    000000b020 74 72 75 65 0d 0a 63 6f 6e 74 65 6e 74 2d 6ctrue..content-l
    000000c065 6e 67 74 68 3a 20 31 30 38 34 0d 0a 0d 0aength: 1084....

    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 |
    000000007b 0a 20 20 22 61 72 67 73 22 3a 20 7b 7d 2c 20{. "args": {},
    000000100a 20 20 22 64 61 74 61 22 3a 20 22 22 2c 20 0a. "data": "", .
    0000002020 20 22 66 69 6c 65 73 22 3a 20 7b 7d 2c 20 0a"files": {}, .
    0000003020 20 22 66 6f 72 6d 22 3a 20 7b 7d 2c 20 0a 20"form": {}, .
    0000004020 22 68 65 61 64 65 72 73 22 3a 20 7b 0a 20 20"headers": {.
    0000005020 20 22 41 63 63 65 70 74 22 3a 20 22 74 65 78"Accept": "tex
    0000006074 2f 68 74 6d 6c 2c 61 70 70 6c 69 63 61 74 69t/html,applicati
    000000706f 6e 2f 78 68 74 6d 6c 2b 78 6d 6c 2c 61 70 70on/xhtml+xml,app
    000000806c 69 63 61 74 69 6f 6e 2f 78 6d 6c 3b 71 3d 30lication/xml;q=0
    000000902e 39 2c 69 6d 61 67 65 2f 77 65 62 70 2c 69 6d.9,image/webp,im
    000000a061 67 65 2f 61 70 6e 67 2c 2a 2f 2a 3b 71 3d 30age/apng,/;q=0
    000000b02e 38 22 2c 20 0a 20 20 20 20 22 41 63 63 65 70.8", . "Accep
    000000c074 2d 45 6e 63 6f 64 69 6e 67 22 3a 20 22 67 7at-Encoding": "gz
    000000d069 70 2c 20 64 65 66 6c 61 74 65 2c 20 62 72 22ip, deflate, br"
    000000e02c 20 0a 20 20 20 20 22 41 63 63 65 70 74 2d 4c, . "Accept-L
    000000f061 6e 67 75 61 67 65 22 3a 20 22 7a 68 2d 43 4eanguage": "zh-CN
    000001002c 7a 68 3b 71 3d 30 2e 39 22 2c 20 0a 20 20 20,zh;q=0.9", .
    0000011020 22 43 61 63 68 65 2d 43 6f 6e 74 72 6f 6c 22"Cache-Control"
    000001203a 20 22 6d 61 78 2d 61 67 65 3d 30 22 2c 20 0a: "max-age=0", .
    0000013020 20 20 20 22 43 6f 6e 74 65 6e 74 2d 4c 65 6e"Content-Len
    0000014067 74 68 22 3a 20 22 30 22 2c 20 0a 20 20 20 20gth": "0", .
    0000015022 46 6f 72 77 61 72 64 65 64 22 3a 20 22 70 72"Forwarded": "pr
    000001606f 74 6f 3d 68 74 74 70 3b 68 6f 73 74 3d 5c 22oto=http;host=\"
    0000017031 32 37 2e 30 2e 30 2e 31 3a 38 31 38 31 5c 22127.0.0.1:8181\"
    000001803b 66 6f 72 3d 5c 22 31 32 37 2e 30 2e 30 2e 31;for=\"127.0.0.1
    000001903a 35 32 37 39 37 5c 22 22 2c 20 0a 20 20 20 20:52797\"", .
    000001a022 48 6f 73 74 22 3a 20 22 68 74 74 70 62 69 6e"Host": "httpbin
    000001b02e 6f 72 67 22 2c 20 0a 20 20 20 20 22 55 70 67.org", . "Upg
    000001c072 61 64 65 2d 49 6e 73 65 63 75 72 65 2d 52 65rade-Insecure-Re
    000001d071 75 65 73 74 73 22 3a 20 22 31 22 2c 20 0a 20quests": "1", .
    000001e020 20 20 22 55 73 65 72 2d 41 67 65 6e 74 22 3a"User-Agent":
    000001f020 22 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 28 57"Mozilla/5.0 (W
    0000020069 6e 64 6f 77 73 20 4e 54 20 31 30 2e 30 3b 20indows NT 10.0;
    0000021057 4f 57 36 34 29 20 41 70 70 6c 65 57 65 62 4bWOW64) AppleWebK
    0000022069 74 2f 35 33 37 2e 33 36 20 28 4b 48 54 4d 4cit/537.36 (KHTML
    000002302c 20 6c 69 6b 65 20 47 65 63 6b 6f 29 20 43 68, like Gecko) Ch
    0000024072 6f 6d 65 2f 37 30 2e 30 2e 33 35 33 38 2e 32rome/70.0.3538.2
    0000025035 20 53 61 66 61 72 69 2f 35 33 37 2e 33 36 205 Safari/537.36
    0000026043 6f 72 65 2f 31 2e 37 30 2e 33 38 37 39 2e 34Core/1.70.3879.4
    0000027030 30 20 51 51 42 72 6f 77 73 65 72 2f 31 30 2e00 QQBrowser/10.
    0000028038 2e 34 35 35 32 2e 34 30 30 22 2c 20 0a 20 208.4552.400", .
    0000029020 20 22 58 2d 41 6d 7a 6e 2d 54 72 61 63 65 2d"X-Amzn-Trace-
    000002a049 64 22 3a 20 22 52 6f 6f 74 3d 31 2d 36 31 61Id": "Root=1-61a
    000002b031 38 36 64 34 2d 34 31 38 32 30 65 31 66 36 33186d4-41820e1f63
    000002c039 30 32 64 34 64 33 63 63 64 38 62 39 64 22 2c902d4d3ccd8b9d",
    000002d020 0a 20 20 20 20 22 58 2d 42 33 2d 50 61 72 65. "X-B3-Pare
    000002e06e 74 73 70 61 6e 69 64 22 3a 20 22 65 66 39 36ntspanid": "ef96
    000002f035 33 61 30 30 30 33 65 64 36 38 65 22 2c 20 0a53a0003ed68e", .
    0000030020 20 20 20 22 58 2d 42 33 2d 53 61 6d 70 6c 65"X-B3-Sample
    0000031064 22 3a 20 22 30 22 2c 20 0a 20 20 20 20 22 58d": "0", . "X
    000003202d 42 33 2d 53 70 61 6e 69 64 22 3a 20 22 38 32-B3-Spanid": "82
    0000033062 36 61 30 32 30 32 64 63 31 35 36 36 62 22 2cb6a0202dc1566b",
    0000034020 0a 20 20 20 20 22 58 2d 42 33 2d 54 72 61 63. "X-B3-Trac
    0000035065 69 64 22 3a 20 22 65 66 39 36 35 33 61 30 30eid": "ef9653a00
    0000036030 33 65 64 36 38 65 22 2c 20 0a 20 20 20 20 2203ed68e", . "
    0000037058 2d 46 6f 72 77 61 72 64 65 64 2d 48 6f 73 74X-Forwarded-Host
    0000038022 3a 20 22 31 32 37 2e 30 2e 30 2e 31 3a 38 31": "127.0.0.1:81
    0000039038 31 22 2c 20 0a 20 20 20 20 22 58 2d 46 6f 7281", . "X-For
    000003a077 61 72 64 65 64 2d 50 72 65 66 69 78 22 3a 20warded-Prefix":
    000003b022 2f 74 65 73 74 2d 73 73 22 0a 20 20 7d 2c 20"/test-ss". },
    000003c00a 20 20 22 6a 73 6f 6e 22 3a 20 6e 75 6c 6c 2c. "json": null,
    000003d020 0a 20 20 22 6d 65 74 68 6f 64 22 3a 20 22 47. "method": "G
    000003e045 54 22 2c 20 0a 20 20 22 6f 72 69 67 69 6e 22ET", . "origin"
    000003f03a 20 22 31 32 37 2e 30 2e 30 2e 31 2c 20 35 39: "127.0.0.1, 59
    000004002e 31 35 32 2e 32 35 34 2e 32 33 38 22 2c 20 0a.152.254.238", .
    0000041020 20 22 75 72 6c 22 3a 20 22 68 74 74 70 3a 2f"url": "http:/
    000004202f 31 32 37 2e 30 2e 30 2e 31 3a 38 31 38 31 2f/127.0.0.1:8181/
    0000043061 6e 79 74 68 69 6e 67 22 0a 7d 0aanything".}.

    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：

    spring-cloud
    已注销
    71 声望21 粉丝

    Mycat和java jfr unit的核心贡献者，贡献过OpenJDK，Spring Cloud. Apache Bookkeeper. Apache RocketMQ等项目，后台leader

    « 上一篇
    SpringCloud升级之路2020.0.x版-41. SpringCloudGateway 基本流程讲解(3)
    下一篇 »
    SpringCloud升级之路2020.0.x版-43.为何 SpringCloudGateway 中会有链路信息丢失

    引用和评论

    推荐阅读
    头像
    我所使用的生产 Java 17 启动参数

    已注销阅读 2.3k

    0 条评论
    得票最新