Code address of this series: https://github.com/JoJoTec/spring-cloud-parent
As the gateway is the entrance to all external user requests, it is very important to record the elements we need in these requests for online monitoring and business problem location. Moreover, among these elements, link information is also very important. Through the link information, we can find the log related to the request to call the whole link. Moreover, the gateway is also the starting point of most request links. While recording the elements in the request, it should also bring the link information.
We need to record the of each request at the gateway:
- HTTP related elements:
- URL related information
- Request information, such as HTTP HEADER, request time, etc
- Some types of request bodies
- Response information, such as response code
- Response body for certain types of responses
- Link information
Existing logs available for analysis and defects
First, let's look at the logs that we can use in the Spring Cloud Gateway. Spring Cloud Gateway is based on spring Webflux, which is based on Project Reactor. We do not add additional Web container dependencies to the gateway, so the Web container uses the default Web container based on reactor netty of Project Reactor.
netty packet capture log
Using netty, we can think of netty's packet capture log. Spring Cloud Gateway encapsulates this function and exposes the configuration. Spring Cloud Gateway is a gateway. It not only accepts HTTP requests as an HTTP server, but also forwards requests to downstream microservices as an HTTP client. Therefore, there are two kinds of packet capture logs. One is the request and response received by the HTTP server, and the other is the request and response sent by the HTTP client. Corresponding to two configurations:
spring.cloud.gateway: httpserver: wiretap: true httpclient: wiretap: true
There are often private letters from readers. I ask how to view the configuration of spring cloud. The official documents are not clear and comprehensive enough. I usually look at the source code, but since many people don't have the energy to study the source code, a lazy way is to look at spring-configuration-metadata.json in the jar package. It contains relatively complete configurations and configuration classes (if any), which is very convenient. For example, the two configurations here correspond in this 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" },
It can be seen that spring.cloud.gateway.httpclient.wiretap corresponds to the configuration class org.springframework.cloud.gateway.config.HttpClientProperties (the configuration in this configuration class will be used later, and the configuration items will be analyzed in detail at that time). The default is false. spring.cloud.gateway.httpserver.wiretap has no configuration class. It is used directly. The corresponding source code is as follows:
@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); } }; }
After adding these two configurations to true, add the log output configuration. I use log4j2 here (in fact, set the log level of reactor.netty.http.server.HttpServer and reactor.netty.http.server.HttpClient to 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>
Then, request the gateway we implemented earlier again, and you can see a log similar to the following:
2021-11-27 01:16:06,262 DEBUG [sports,,] [10632] [reactor-http-nio-2][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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 | +--------+-------------------------------------------------+----------------+ |00000000| 47 45 54 20 2f 74 65 73 74 2d 73 73 2f 61 6e 79 |GET /test-ss/any| |00000010| 74 68 69 6e 67 20 48 54 54 50 2f 31 2e 31 0d 0a |thing HTTP/1.1..| |00000020| 48 6f 73 74 3a 20 31 32 37 2e 30 2e 30 2e 31 3a |Host: 127.0.0.1:| |00000030| 38 31 38 31 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e |8181..Connection| |00000040| 3a 20 6b 65 65 70 2d 61 6c 69 76 65 0d 0a 43 61 |: keep-alive..Ca| |00000050| 63 68 65 2d 43 6f 6e 74 72 6f 6c 3a 20 6d 61 78 |che-Control: max| |00000060| 2d 61 67 65 3d 30 0d 0a 55 70 67 72 61 64 65 2d |-age=0..Upgrade-| |00000070| 49 6e 73 65 63 75 72 65 2d 52 65 71 75 65 73 74 |Insecure-Request| |00000080| 73 3a 20 31 0d 0a 55 73 65 72 2d 41 67 65 6e 74 |s: 1..User-Agent| |00000090| 3a 20 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 28 57 |: Mozilla/5.0 (W| |000000a0| 69 6e 64 6f 77 73 20 4e 54 20 31 30 2e 30 3b 20 |indows NT 10.0; | |000000b0| 57 4f 57 36 34 29 20 41 70 70 6c 65 57 65 62 4b |WOW64) AppleWebK| |000000c0| 69 74 2f 35 33 37 2e 33 36 20 28 4b 48 54 4d 4c |it/537.36 (KHTML| |000000d0| 2c 20 6c 69 6b 65 20 47 65 63 6b 6f 29 20 43 68 |, like Gecko) Ch| |000000e0| 72 6f 6d 65 2f 37 30 2e 30 2e 33 35 33 38 2e 32 |rome/70.0.3538.2| |000000f0| 35 20 53 61 66 61 72 69 2f 35 33 37 2e 33 36 20 |5 Safari/537.36 | |00000100| 43 6f 72 65 2f 31 2e 37 30 2e 33 38 37 39 2e 34 |Core/1.70.3879.4| |00000110| 30 30 20 51 51 42 72 6f 77 73 65 72 2f 31 30 2e |00 QQBrowser/10.| |00000120| 38 2e 34 35 35 32 2e 34 30 30 0d 0a 41 63 63 65 |8.4552.400..Acce| |00000130| 70 74 3a 20 74 65 78 74 2f 68 74 6d 6c 2c 61 70 |pt: text/html,ap| |00000140| 70 6c 69 63 61 74 69 6f 6e 2f 78 68 74 6d 6c 2b |plication/xhtml+| |00000150| 78 6d 6c 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2f |xml,application/| |00000160| 78 6d 6c 3b 71 3d 30 2e 39 2c 69 6d 61 67 65 2f |xml;q=0.9,image/| |00000170| 77 65 62 70 2c 69 6d 61 67 65 2f 61 70 6e 67 2c |webp,image/apng,| |00000180| 2a 2f 2a 3b 71 3d 30 2e 38 0d 0a 41 63 63 65 70 |*/*;q=0.8..Accep| |00000190| 74 2d 45 6e 63 6f 64 69 6e 67 3a 20 67 7a 69 70 |t-Encoding: gzip| |000001a0| 2c 20 64 65 66 6c 61 74 65 2c 20 62 72 0d 0a 41 |, deflate, br..A| |000001b0| 63 63 65 70 74 2d 4c 61 6e 67 75 61 67 65 3a 20 |ccept-Language: | |000001c0| 7a 68 2d 43 4e 2c 7a 68 3b 71 3d 30 2e 39 0d 0a |zh-CN,zh;q=0.9..| |000001d0| 0d 0a |.. | +--------+-------------------------------------------------+----------------+ 2021-11-27 01:16:06,262 DEBUG [sports,,] [10632] [reactor-http-nio-2][reactor.util.Loggers$Slf4JLogger:249]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[id:6666c1d1] REGISTERED 2021-11-27 01:16:06,437 DEBUG [sports,,] [10632] [reactor-http-nio-6][io.netty.util.internal.logging.AbstractInternalLogger:145]:[id:6666c1d1] CONNECT: httpbin.org/18.232.227.86:80 2021-11-27 01:16:06,656 DEBUG [sports,,] [10632] [reactor-http-nio-6][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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 | +--------+-------------------------------------------------+----------------+ |00000000| 47 45 54 20 2f 61 6e 79 74 68 69 6e 67 20 48 54 |GET /anything HT| |00000010| 54 50 2f 31 2e 31 0d 0a 43 61 63 68 65 2d 43 6f |TP/1.1..Cache-Co| |00000020| 6e 74 72 6f 6c 3a 20 6d 61 78 2d 61 67 65 3d 30 |ntrol: max-age=0| |00000030| 0d 0a 55 70 67 72 61 64 65 2d 49 6e 73 65 63 75 |..Upgrade-Insecu| |00000040| 72 65 2d 52 65 71 75 65 73 74 73 3a 20 31 0d 0a |re-Requests: 1..| |00000050| 55 73 65 72 2d 41 67 65 6e 74 3a 20 4d 6f 7a 69 |User-Agent: Mozi| |00000060| 6c 6c 61 2f 35 2e 30 20 28 57 69 6e 64 6f 77 73 |lla/5.0 (Windows| |00000070| 20 4e 54 20 31 30 2e 30 3b 20 57 4f 57 36 34 29 | NT 10.0; WOW64)| |00000080| 20 41 70 70 6c 65 57 65 62 4b 69 74 2f 35 33 37 | AppleWebKit/537| |00000090| 2e 33 36 20 28 4b 48 54 4d 4c 2c 20 6c 69 6b 65 |.36 (KHTML, like| |000000a0| 20 47 65 63 6b 6f 29 20 43 68 72 6f 6d 65 2f 37 | Gecko) Chrome/7| |000000b0| 30 2e 30 2e 33 35 33 38 2e 32 35 20 53 61 66 61 |0.0.3538.25 Safa| |000000c0| 72 69 2f 35 33 37 2e 33 36 20 43 6f 72 65 2f 31 |ri/537.36 Core/1| |000000d0| 2e 37 30 2e 33 38 37 39 2e 34 30 30 20 51 51 42 |.70.3879.400 QQB| |000000e0| 72 6f 77 73 65 72 2f 31 30 2e 38 2e 34 35 35 32 |rowser/10.8.4552| |000000f0| 2e 34 30 30 0d 0a 41 63 63 65 70 74 3a 20 74 65 |.400..Accept: te| |00000100| 78 74 2f 68 74 6d 6c 2c 61 70 70 6c 69 63 61 74 |xt/html,applicat| |00000110| 69 6f 6e 2f 78 68 74 6d 6c 2b 78 6d 6c 2c 61 70 |ion/xhtml+xml,ap| |00000120| 70 6c 69 63 61 74 69 6f 6e 2f 78 6d 6c 3b 71 3d |plication/xml;q=| |00000130| 30 2e 39 2c 69 6d 61 67 65 2f 77 65 62 70 2c 69 |0.9,image/webp,i| |00000140| 6d 61 67 65 2f 61 70 6e 67 2c 2a 2f 2a 3b 71 3d |mage/apng,*/*;q=| |00000150| 30 2e 38 0d 0a 41 63 63 65 70 74 2d 45 6e 63 6f |0.8..Accept-Enco| |00000160| 64 69 6e 67 3a 20 67 7a 69 70 2c 20 64 65 66 6c |ding: gzip, defl| |00000170| 61 74 65 2c 20 62 72 0d 0a 41 63 63 65 70 74 2d |ate, br..Accept-| |00000180| 4c 61 6e 67 75 61 67 65 3a 20 7a 68 2d 43 4e 2c |Language: zh-CN,| |00000190| 7a 68 3b 71 3d 30 2e 39 0d 0a 46 6f 72 77 61 72 |zh;q=0.9..Forwar| |000001a0| 64 65 64 3a 20 70 72 6f 74 6f 3d 68 74 74 70 3b |ded: proto=http;| |000001b0| 68 6f 73 74 3d 22 31 32 37 2e 30 2e 30 2e 31 3a |host="127.0.0.1:| |000001c0| 38 31 38 31 22 3b 66 6f 72 3d 22 31 32 37 2e 30 |8181";for="127.0| |000001d0| 2e 30 2e 31 3a 35 32 37 39 37 22 0d 0a 58 2d 46 |.0.1:52797"..X-F| |000001e0| 6f 72 77 61 72 64 65 64 2d 46 6f 72 3a 20 31 32 |orwarded-For: 12| |000001f0| 37 2e 30 2e 30 2e 31 0d 0a 58 2d 46 6f 72 77 61 |7.0.0.1..X-Forwa| |00000200| 72 64 65 64 2d 50 72 6f 74 6f 3a 20 68 74 74 70 |rded-Proto: http| |00000210| 0d 0a 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 72 |..X-Forwarded-Pr| |00000220| 65 66 69 78 3a 20 2f 74 65 73 74 2d 73 73 0d 0a |efix: /test-ss..| |00000230| 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 6f 72 74 |X-Forwarded-Port| |00000240| 3a 20 38 31 38 31 0d 0a 58 2d 46 6f 72 77 61 72 |: 8181..X-Forwar| |00000250| 64 65 64 2d 48 6f 73 74 3a 20 31 32 37 2e 30 2e |ded-Host: 127.0.| |00000260| 30 2e 31 3a 38 31 38 31 0d 0a 68 6f 73 74 3a 20 |0.1:8181..host: | |00000270| 68 74 74 70 62 69 6e 2e 6f 72 67 0d 0a 58 2d 42 |httpbin.org..X-B| |00000280| 33 2d 54 72 61 63 65 49 64 3a 20 65 66 39 36 35 |3-TraceId: ef965| |00000290| 33 61 30 30 30 33 65 64 36 38 65 0d 0a 58 2d 42 |3a0003ed68e..X-B| |000002a0| 33 2d 53 70 61 6e 49 64 3a 20 38 32 62 36 61 30 |3-SpanId: 82b6a0| |000002b0| 32 30 32 64 63 31 35 36 36 62 0d 0a 58 2d 42 33 |202dc1566b..X-B3| |000002c0| 2d 50 61 72 65 6e 74 53 70 61 6e 49 64 3a 20 65 |-ParentSpanId: e| |000002d0| 66 39 36 35 33 61 30 30 30 33 65 64 36 38 65 0d |f9653a0003ed68e.| |000002e0| 0a 58 2d 42 33 2d 53 61 6d 70 6c 65 64 3a 20 30 |.X-B3-Sampled: 0| |000002f0| 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 |..content-length| |00000300| 3a 20 30 0d 0a 0d 0a |: 0.... | +--------+-------------------------------------------------+----------------+ 2021-11-27 01:16:06,672 DEBUG [sports,,] [10632] [reactor-http-nio-6][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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 | +--------+-------------------------------------------------+----------------+ |00000000| 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d |HTTP/1.1 200 OK.| |00000010| 0a 44 61 74 65 3a 20 53 61 74 2c 20 32 37 20 4e |.Date: Sat, 27 N| |00000020| 6f 76 20 32 30 32 31 20 30 31 3a 31 36 3a 30 34 |ov 2021 01:16:04| |00000030| 20 47 4d 54 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 | GMT..Content-Ty| |00000040| 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f |pe: application/| |00000050| 6a 73 6f 6e 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65 |json..Content-Le| |00000060| 6e 67 74 68 3a 20 31 30 38 34 0d 0a 43 6f 6e 6e |ngth: 1084..Conn| |00000070| 65 63 74 69 6f 6e 3a 20 6b 65 65 70 2d 61 6c 69 |ection: keep-ali| |00000080| 76 65 0d 0a 53 65 72 76 65 72 3a 20 67 75 6e 69 |ve..Server: guni| |00000090| 63 6f 72 6e 2f 31 39 2e 39 2e 30 0d 0a 41 63 63 |corn/19.9.0..Acc| |000000a0| 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c 6c 6f |ess-Control-Allo| |000000b0| 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a 41 63 63 |w-Origin: *..Acc| |000000c0| 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c 6c 6f |ess-Control-Allo| |000000d0| 77 2d 43 72 65 64 65 6e 74 69 61 6c 73 3a 20 74 |w-Credentials: t| |000000e0| 72 75 65 0d 0a 0d 0a 7b 0a 20 20 22 61 72 67 73 |rue....{. "args| |000000f0| 22 3a 20 7b 7d 2c 20 0a 20 20 22 64 61 74 61 22 |": {}, . "data"| |00000100| 3a 20 22 22 2c 20 0a 20 20 22 66 69 6c 65 73 22 |: "", . "files"| |00000110| 3a 20 7b 7d 2c 20 0a 20 20 22 66 6f 72 6d 22 3a |: {}, . "form":| |00000120| 20 7b 7d 2c 20 0a 20 20 22 68 65 61 64 65 72 73 | {}, . "headers| |00000130| 22 3a 20 7b 0a 20 20 20 20 22 41 63 63 65 70 74 |": {. "Accept| |00000140| 22 3a 20 22 74 65 78 74 2f 68 74 6d 6c 2c 61 70 |": "text/html,ap| |00000150| 70 6c 69 63 61 74 69 6f 6e 2f 78 68 74 6d 6c 2b |plication/xhtml+| |00000160| 78 6d 6c 2c 61 70 70 6c 69 63 61 74 69 6f 6e 2f |xml,application/| |00000170| 78 6d 6c 3b 71 3d 30 2e 39 2c 69 6d 61 67 65 2f |xml;q=0.9,image/| |00000180| 77 65 62 70 2c 69 6d 61 67 65 2f 61 70 6e 67 2c |webp,image/apng,| |00000190| 2a 2f 2a 3b 71 3d 30 2e 38 22 2c 20 0a 20 20 20 |*/*;q=0.8", . | |000001a0| 20 22 41 63 63 65 70 74 2d 45 6e 63 6f 64 69 6e | "Accept-Encodin| |000001b0| 67 22 3a 20 22 67 7a 69 70 2c 20 64 65 66 6c 61 |g": "gzip, defla| |000001c0| 74 65 2c 20 62 72 22 2c 20 0a 20 20 20 20 22 41 |te, br", . "A| |000001d0| 63 63 65 70 74 2d 4c 61 6e 67 75 61 67 65 22 3a |ccept-Language":| |000001e0| 20 22 7a 68 2d 43 4e 2c 7a 68 3b 71 3d 30 2e 39 | "zh-CN,zh;q=0.9| |000001f0| 22 2c 20 0a 20 20 20 20 22 43 61 63 68 65 2d 43 |", . "Cache-C| |00000200| 6f 6e 74 72 6f 6c 22 3a 20 22 6d 61 78 2d 61 67 |ontrol": "max-ag| |00000210| 65 3d 30 22 2c 20 0a 20 20 20 20 22 43 6f 6e 74 |e=0", . "Cont| |00000220| 65 6e 74 2d 4c 65 6e 67 74 68 22 3a 20 22 30 22 |ent-Length": "0"| |00000230| 2c 20 0a 20 20 20 20 22 46 6f 72 77 61 72 64 65 |, . "Forwarde| |00000240| 64 22 3a 20 22 70 72 6f 74 6f 3d 68 74 74 70 3b |d": "proto=http;| |00000250| 68 6f 73 74 3d 5c 22 31 32 37 2e 30 2e 30 2e 31 |host=\"127.0.0.1| |00000260| 3a 38 31 38 31 5c 22 3b 66 6f 72 3d 5c 22 31 32 |:8181\";for=\"12| |00000270| 37 2e 30 2e 30 2e 31 3a 35 32 37 39 37 5c 22 22 |7.0.0.1:52797\""| |00000280| 2c 20 0a 20 20 20 20 22 48 6f 73 74 22 3a 20 22 |, . "Host": "| |00000290| 68 74 74 70 62 69 6e 2e 6f 72 67 22 2c 20 0a 20 |httpbin.org", . | |000002a0| 20 20 20 22 55 70 67 72 61 64 65 2d 49 6e 73 65 | "Upgrade-Inse| |000002b0| 63 75 72 65 2d 52 65 71 75 65 73 74 73 22 3a 20 |cure-Requests": | |000002c0| 22 31 22 2c 20 0a 20 20 20 20 22 55 73 65 72 2d |"1", . "User-| |000002d0| 41 67 65 6e 74 22 3a 20 22 4d 6f 7a 69 6c 6c 61 |Agent": "Mozilla| |000002e0| 2f 35 2e 30 20 28 57 69 6e 64 6f 77 73 20 4e 54 |/5.0 (Windows NT| |000002f0| 20 31 30 2e 30 3b 20 57 4f 57 36 34 29 20 41 70 | 10.0; WOW64) Ap| |00000300| 70 6c 65 57 65 62 4b 69 74 2f 35 33 37 2e 33 36 |pleWebKit/537.36| |00000310| 20 28 4b 48 54 4d 4c 2c 20 6c 69 6b 65 20 47 65 | (KHTML, like Ge| |00000320| 63 6b 6f 29 20 43 68 72 6f 6d 65 2f 37 30 2e 30 |cko) Chrome/70.0| |00000330| 2e 33 35 33 38 2e 32 35 20 53 61 66 61 72 69 2f |.3538.25 Safari/| |00000340| 35 33 37 2e 33 36 20 43 6f 72 65 2f 31 2e 37 30 |537.36 Core/1.70| |00000350| 2e 33 38 37 39 2e 34 30 30 20 51 51 42 72 6f 77 |.3879.400 QQBrow| |00000360| 73 65 72 2f 31 30 2e 38 2e 34 35 35 32 2e 34 30 |ser/10.8.4552.40| |00000370| 30 22 2c 20 0a 20 20 20 20 22 58 2d 41 6d 7a 6e |0", . "X-Amzn| |00000380| 2d 54 72 61 63 65 2d 49 64 22 3a 20 22 52 6f 6f |-Trace-Id": "Roo| |00000390| 74 3d 31 2d 36 31 61 31 38 36 64 34 2d 34 31 38 |t=1-61a186d4-418| |000003a0| 32 30 65 31 66 36 33 39 30 32 64 34 64 33 63 63 |20e1f63902d4d3cc| |000003b0| 64 38 62 39 64 22 2c 20 0a 20 20 20 20 22 58 2d |d8b9d", . "X-| |000003c0| 42 33 2d 50 61 72 65 6e 74 73 70 61 6e 69 64 22 |B3-Parentspanid"| |000003d0| 3a 20 22 65 66 39 36 35 33 61 30 30 30 33 65 64 |: "ef9653a0003ed| |000003e0| 36 38 65 22 2c 20 0a 20 20 20 20 22 58 2d 42 33 |68e", . "X-B3| |000003f0| 2d 53 61 6d 70 6c 65 64 22 3a 20 22 30 22 2c 20 |-Sampled": "0", | |00000400| 0a 20 20 20 20 22 58 2d 42 33 2d 53 70 61 6e 69 |. "X-B3-Spani| |00000410| 64 22 3a 20 22 38 32 62 36 61 30 32 30 32 64 63 |d": "82b6a0202dc| |00000420| 31 35 36 36 62 22 2c 20 0a 20 20 20 20 22 58 2d |1566b", . "X-| |00000430| 42 33 2d 54 72 61 63 65 69 64 22 3a 20 22 65 66 |B3-Traceid": "ef| |00000440| 39 36 35 33 61 30 30 30 33 65 64 36 38 65 22 2c |9653a0003ed68e",| |00000450| 20 0a 20 20 20 20 22 58 2d 46 6f 72 77 61 72 64 | . "X-Forward| |00000460| 65 64 2d 48 6f 73 74 22 3a 20 22 31 32 37 2e 30 |ed-Host": "127.0| |00000470| 2e 30 2e 31 3a 38 31 38 31 22 2c 20 0a 20 20 20 |.0.1:8181", . | |00000480| 20 22 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 72 | "X-Forwarded-Pr| |00000490| 65 66 69 78 22 3a 20 22 2f 74 65 73 74 2d 73 73 |efix": "/test-ss| |000004a0| 22 0a 20 20 7d 2c 20 0a 20 20 22 6a 73 6f 6e 22 |". }, . "json"| |000004b0| 3a 20 6e 75 6c 6c 2c 20 0a 20 20 22 6d 65 74 68 |: null, . "meth| |000004c0| 6f 64 22 3a 20 22 47 45 54 22 2c 20 0a 20 20 22 |od": "GET", . "| |000004d0| 6f 72 69 67 69 6e 22 3a 20 22 31 32 37 2e 30 2e |origin": "127.0.| |000004e0| 30 2e 31 2c 20 35 39 2e 31 35 32 2e 32 35 34 2e |0.1, 59.152.254.| |000004f0| 32 33 38 22 2c 20 0a 20 20 22 75 72 6c 22 3a 20 |238", . "url": | |00000500| 22 68 74 74 70 3a 2f 2f 31 32 37 2e 30 2e 30 2e |"http://127.0.0.| |00000510| 31 3a 38 31 38 31 2f 61 6e 79 74 68 69 6e 67 22 |1:8181/anything"| |00000520| 0a 7d 0a |.}. | +--------+-------------------------------------------------+----------------+ 2021-11-27 01:16:06,904 DEBUG [sports,,] [10632] [reactor-http-nio-2][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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 | +--------+-------------------------------------------------+----------------+ |00000000| 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d |HTTP/1.1 200 OK.| |00000010| 0a 44 61 74 65 3a 20 53 61 74 2c 20 32 37 20 4e |.Date: Sat, 27 N| |00000020| 6f 76 20 32 30 32 31 20 30 31 3a 31 36 3a 30 34 |ov 2021 01:16:04| |00000030| 20 47 4d 54 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 | GMT..Content-Ty| |00000040| 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f |pe: application/| |00000050| 6a 73 6f 6e 0d 0a 53 65 72 76 65 72 3a 20 67 75 |json..Server: gu| |00000060| 6e 69 63 6f 72 6e 2f 31 39 2e 39 2e 30 0d 0a 41 |nicorn/19.9.0..A| |00000070| 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c |ccess-Control-Al| |00000080| 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 2a 0d 0a 41 |low-Origin: *..A| |00000090| 63 63 65 73 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c |ccess-Control-Al| |000000a0| 6c 6f 77 2d 43 72 65 64 65 6e 74 69 61 6c 73 3a |low-Credentials:| |000000b0| 20 74 72 75 65 0d 0a 63 6f 6e 74 65 6e 74 2d 6c | true..content-l| |000000c0| 65 6e 67 74 68 3a 20 31 30 38 34 0d 0a 0d 0a |ength: 1084.... | +--------+-------------------------------------------------+----------------+ 2021-11-27 01:16:06,904 DEBUG [sports,,] [10632] [reactor-http-nio-2][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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 | +--------+-------------------------------------------------+----------------+ |00000000| 7b 0a 20 20 22 61 72 67 73 22 3a 20 7b 7d 2c 20 |{. "args": {}, | |00000010| 0a 20 20 22 64 61 74 61 22 3a 20 22 22 2c 20 0a |. "data": "", .| |00000020| 20 20 22 66 69 6c 65 73 22 3a 20 7b 7d 2c 20 0a | "files": {}, .| |00000030| 20 20 22 66 6f 72 6d 22 3a 20 7b 7d 2c 20 0a 20 | "form": {}, . | |00000040| 20 22 68 65 61 64 65 72 73 22 3a 20 7b 0a 20 20 | "headers": {. | |00000050| 20 20 22 41 63 63 65 70 74 22 3a 20 22 74 65 78 | "Accept": "tex| |00000060| 74 2f 68 74 6d 6c 2c 61 70 70 6c 69 63 61 74 69 |t/html,applicati| |00000070| 6f 6e 2f 78 68 74 6d 6c 2b 78 6d 6c 2c 61 70 70 |on/xhtml+xml,app| |00000080| 6c 69 63 61 74 69 6f 6e 2f 78 6d 6c 3b 71 3d 30 |lication/xml;q=0| |00000090| 2e 39 2c 69 6d 61 67 65 2f 77 65 62 70 2c 69 6d |.9,image/webp,im| |000000a0| 61 67 65 2f 61 70 6e 67 2c 2a 2f 2a 3b 71 3d 30 |age/apng,*/*;q=0| |000000b0| 2e 38 22 2c 20 0a 20 20 20 20 22 41 63 63 65 70 |.8", . "Accep| |000000c0| 74 2d 45 6e 63 6f 64 69 6e 67 22 3a 20 22 67 7a |t-Encoding": "gz| |000000d0| 69 70 2c 20 64 65 66 6c 61 74 65 2c 20 62 72 22 |ip, deflate, br"| |000000e0| 2c 20 0a 20 20 20 20 22 41 63 63 65 70 74 2d 4c |, . "Accept-L| |000000f0| 61 6e 67 75 61 67 65 22 3a 20 22 7a 68 2d 43 4e |anguage": "zh-CN| |00000100| 2c 7a 68 3b 71 3d 30 2e 39 22 2c 20 0a 20 20 20 |,zh;q=0.9", . | |00000110| 20 22 43 61 63 68 65 2d 43 6f 6e 74 72 6f 6c 22 | "Cache-Control"| |00000120| 3a 20 22 6d 61 78 2d 61 67 65 3d 30 22 2c 20 0a |: "max-age=0", .| |00000130| 20 20 20 20 22 43 6f 6e 74 65 6e 74 2d 4c 65 6e | "Content-Len| |00000140| 67 74 68 22 3a 20 22 30 22 2c 20 0a 20 20 20 20 |gth": "0", . | |00000150| 22 46 6f 72 77 61 72 64 65 64 22 3a 20 22 70 72 |"Forwarded": "pr| |00000160| 6f 74 6f 3d 68 74 74 70 3b 68 6f 73 74 3d 5c 22 |oto=http;host=\"| |00000170| 31 32 37 2e 30 2e 30 2e 31 3a 38 31 38 31 5c 22 |127.0.0.1:8181\"| |00000180| 3b 66 6f 72 3d 5c 22 31 32 37 2e 30 2e 30 2e 31 |;for=\"127.0.0.1| |00000190| 3a 35 32 37 39 37 5c 22 22 2c 20 0a 20 20 20 20 |:52797\"", . | |000001a0| 22 48 6f 73 74 22 3a 20 22 68 74 74 70 62 69 6e |"Host": "httpbin| |000001b0| 2e 6f 72 67 22 2c 20 0a 20 20 20 20 22 55 70 67 |.org", . "Upg| |000001c0| 72 61 64 65 2d 49 6e 73 65 63 75 72 65 2d 52 65 |rade-Insecure-Re| |000001d0| 71 75 65 73 74 73 22 3a 20 22 31 22 2c 20 0a 20 |quests": "1", . | |000001e0| 20 20 20 22 55 73 65 72 2d 41 67 65 6e 74 22 3a | "User-Agent":| |000001f0| 20 22 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 28 57 | "Mozilla/5.0 (W| |00000200| 69 6e 64 6f 77 73 20 4e 54 20 31 30 2e 30 3b 20 |indows NT 10.0; | |00000210| 57 4f 57 36 34 29 20 41 70 70 6c 65 57 65 62 4b |WOW64) AppleWebK| |00000220| 69 74 2f 35 33 37 2e 33 36 20 28 4b 48 54 4d 4c |it/537.36 (KHTML| |00000230| 2c 20 6c 69 6b 65 20 47 65 63 6b 6f 29 20 43 68 |, like Gecko) Ch| |00000240| 72 6f 6d 65 2f 37 30 2e 30 2e 33 35 33 38 2e 32 |rome/70.0.3538.2| |00000250| 35 20 53 61 66 61 72 69 2f 35 33 37 2e 33 36 20 |5 Safari/537.36 | |00000260| 43 6f 72 65 2f 31 2e 37 30 2e 33 38 37 39 2e 34 |Core/1.70.3879.4| |00000270| 30 30 20 51 51 42 72 6f 77 73 65 72 2f 31 30 2e |00 QQBrowser/10.| |00000280| 38 2e 34 35 35 32 2e 34 30 30 22 2c 20 0a 20 20 |8.4552.400", . | |00000290| 20 20 22 58 2d 41 6d 7a 6e 2d 54 72 61 63 65 2d | "X-Amzn-Trace-| |000002a0| 49 64 22 3a 20 22 52 6f 6f 74 3d 31 2d 36 31 61 |Id": "Root=1-61a| |000002b0| 31 38 36 64 34 2d 34 31 38 32 30 65 31 66 36 33 |186d4-41820e1f63| |000002c0| 39 30 32 64 34 64 33 63 63 64 38 62 39 64 22 2c |902d4d3ccd8b9d",| |000002d0| 20 0a 20 20 20 20 22 58 2d 42 33 2d 50 61 72 65 | . "X-B3-Pare| |000002e0| 6e 74 73 70 61 6e 69 64 22 3a 20 22 65 66 39 36 |ntspanid": "ef96| |000002f0| 35 33 61 30 30 30 33 65 64 36 38 65 22 2c 20 0a |53a0003ed68e", .| |00000300| 20 20 20 20 22 58 2d 42 33 2d 53 61 6d 70 6c 65 | "X-B3-Sample| |00000310| 64 22 3a 20 22 30 22 2c 20 0a 20 20 20 20 22 58 |d": "0", . "X| |00000320| 2d 42 33 2d 53 70 61 6e 69 64 22 3a 20 22 38 32 |-B3-Spanid": "82| |00000330| 62 36 61 30 32 30 32 64 63 31 35 36 36 62 22 2c |b6a0202dc1566b",| |00000340| 20 0a 20 20 20 20 22 58 2d 42 33 2d 54 72 61 63 | . "X-B3-Trac| |00000350| 65 69 64 22 3a 20 22 65 66 39 36 35 33 61 30 30 |eid": "ef9653a00| |00000360| 30 33 65 64 36 38 65 22 2c 20 0a 20 20 20 20 22 |03ed68e", . "| |00000370| 58 2d 46 6f 72 77 61 72 64 65 64 2d 48 6f 73 74 |X-Forwarded-Host| |00000380| 22 3a 20 22 31 32 37 2e 30 2e 30 2e 31 3a 38 31 |": "127.0.0.1:81| |00000390| 38 31 22 2c 20 0a 20 20 20 20 22 58 2d 46 6f 72 |81", . "X-For| |000003a0| 77 61 72 64 65 64 2d 50 72 65 66 69 78 22 3a 20 |warded-Prefix": | |000003b0| 22 2f 74 65 73 74 2d 73 73 22 0a 20 20 7d 2c 20 |"/test-ss". }, | |000003c0| 0a 20 20 22 6a 73 6f 6e 22 3a 20 6e 75 6c 6c 2c |. "json": null,| |000003d0| 20 0a 20 20 22 6d 65 74 68 6f 64 22 3a 20 22 47 | . "method": "G| |000003e0| 45 54 22 2c 20 0a 20 20 22 6f 72 69 67 69 6e 22 |ET", . "origin"| |000003f0| 3a 20 22 31 32 37 2e 30 2e 30 2e 31 2c 20 35 39 |: "127.0.0.1, 59| |00000400| 2e 31 35 32 2e 32 35 34 2e 32 33 38 22 2c 20 0a |.152.254.238", .| |00000410| 20 20 22 75 72 6c 22 3a 20 22 68 74 74 70 3a 2f | "url": "http:/| |00000420| 2f 31 32 37 2e 30 2e 30 2e 31 3a 38 31 38 31 2f |/127.0.0.1:8181/| |00000430| 61 6e 79 74 68 69 6e 67 22 0a 7d 0a |anything".}. | +--------+-------------------------------------------------+----------------+ 2021-11-27 01:16:06,909 DEBUG [sports,,] [10632] [reactor-http-nio-6][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[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][io.netty.util.internal.logging.AbstractInternalLogger:145]:[id:1277d54e-2, L:/127.0.0.1:8181 - R:/127.0.0.1:52797] FLUSH
You can see the following important information from the log:
- All contents of HTTP request and response packets can be obtained from the packet capture log.
- The log here is not wrapped by spring cloud sleuth, so the placeholder of the log itself has no relevant link information
- However, from the package, you can see the link information of spring cloud sleuth, here is: "X-B3-Parentspanid": "ef9653a0003ed68e", "X-B3-Sampled": "0", "X-B3-Spanid": "82b6a0202dc1566b", "X-B3-Traceid": "ef9653a0003ed68e",
- Netty itself has traceId, i.e. 6666c1d1 and 1277d54e here (respectively as HttpServer to accept requests and as HttpClient to forward requests to the background micro service), so that the link information of spring cloud sleuth can be combined with the link information of netty
These logs are comprehensive, but there are some problems that are not easy to use:
- You can only output the package contents of all requests and responses, and you cannot customize which contents to output. For example, for a file upload request, we don't want to see its request body, but it can't be customized here.
- Too many logs will affect our performance.
TRACE log for HttpWebHandlerAdapter
In the source code analysis of the previous articles in the series, we know that there are request and response logs in the HttpWebHandlerAdapter of the portal, which can be enabled through the following configuration:
<AsyncLogger name="org.springframework.web.server.adapter.HttpWebHandlerAdapter" level="trace" additivity="false" includeLocation="true"> <appender-ref ref="console" /> </AsyncLogger>
This enables logging similar to the following:
2021-11-27 01:25:28,472 TRACE [sports,,] [16188] [reactor-http-nio-2][org.springframework.core.log.LogFormatUtils:88]:[8d5138d1-3] HTTP GET "/test-ss/anything", headers={masked} 2021-11-27 01:25:28,696 TRACE [sports,,] [16188] [reactor-http-nio-2][org.springframework.core.log.LogFormatUtils:88]:[8d5138d1-3] Completed 200 OK, headers={masked}
How to make headers not masked can be realized through the following configuration:
spring.codec: log-request-details: true
The configuration class corresponding to this configuration is CodecProperties. We can also find from the source code that we can also limit the size of the body here:
@ConfigurationProperties(prefix = "spring.codec") public class CodecProperties { private boolean logRequestDetails; private DataSize maxInMemorySize; }
After configuration, the log is as follows:
2021-11-27 01:32:50,501 TRACE [sports,,] [17668] [reactor-http-nio-2][org.springframework.core.log.LogFormatUtils:88]:[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][org.springframework.core.log.LogFormatUtils:88]:[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"]
However, the log contains too little content, only request and response headers, and there is no spring cloud sleuth related link information.
AccessLog
The Spring Cloud Gateway uses an http server based on reactor netty. In the spring boot package, you can add a custom AccessLog by adding a NettyServerCustomizer Bean. AccessLog contains the following elements:
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(); }
It can be seen that there is no link information related to spring cloud sleuth, but we can add the link information to the Response Header through the implementation of Global Filter, and output these headers to the accesslog through the requestHeader of AccessLogArgProvider:
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() { //You need to get trace information before all filters return Ordered.HIGHEST_PRECEDENCE; } }
Then, configure the Access Log by implementing NettyServerCustomizer and registering a Bean.
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 -> { //All are printed 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; } } }
In this way, we can get the following access log:
2021-11-27 03:56:10,948 INFO [sports,,] [8536] [reactor-http-nio-2][reactor.util.Loggers$Slf4JLogger:269]: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
The accesslog cannot output the body, so we still need to customize our own log Filter.
In the next section, we will start to implement our own customized log Filter
WeChat search "my programming meow" attention to the official account, daily brush, easy to upgrade technology, and capture all kinds of offer: