spring - 使用Spring WebClient读取HTTP请求的可读调试日志

Question

我正在使用Spring响应式(Reactive)WebClient向HTTP服务器发送请求。为了查看正在发送的基础请求和响应，我为reactor.ipc.netty包启用了调试日志记录。

可以正常查看传出请求的 header 。

我正在通过http发送和接收纯文本，日志中包含以下格式的请求和响应(十六进制)？

我不确定如何以一种易于理解的方式查看记录的数据。更好地以一种易于理解的方式记录请求和响应

这是已记录数据的一个片段

         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 53 65 61 72 63 68 5f 47 43 2e 61 |GET /Search_GC.a|
|00000010| 73 70 78 20 48 54 54 50 2f 31 2e 31 0d 0a 75 73 |spx HTTP/1.1..us|
|00000020| 65 72 2d 61 67 65 6e 74 3a 20 52 65 61 63 74 6f |er-agent: Reacto|
|00000030| 72 4e 65 74 74 79 2f 30 2e 37 2e 32 2e 52 45 4c |rNetty/0.7.2.REL|
|00000040| 45 41 53 45 0d 0a 68 6f 73 74 3a 20 63 65 6f 6b |EASE..host: ceok|
|00000050| 61 72 6e 61 74 61 6b 61 2e 6b 61 72 2e 6e 69 63 |arnataka.kar.nic|
|00000060| 2e 69 6e 0d 0a 61 63 63 65 70 74 3a 20 2a 2f 2a |.in..accept: */*|
|00000070| 0d 0a 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e |..accept-encodin|
|00000080| 67 3a 20 67 7a 69 70 0d 0a 63 6f 6e 74 65 6e 74 |g: gzip..content|
|00000090| 2d 6c 65 6e 67 74 68 3a 20 30 0d 0a 0d 0a       |-length: 0....  |
+--------+-------------------------------------------------+----------------+

发现了由于相同的库而导致必须解决的未解决问题: Reading a HttpContent that has a PooledUnsafeDirectByteBuf

提出了一个问题 here

在传统的观点看来，响应式(Reactive)客户端不需要调试。这是一个完全没有意义的参数，因为我们使用 rest client， postman， curl， httpie等工具来发送请求和查看响应

Answer 1

在我升级到reactor.netty.http.client.HttpClient之后，他们更改了 io.projectreactor.netty:reactor-netty-http:1.0.5 类，以下代码可编译，并且可以完成您期望的工作。 (我不确定哪个是最低版本，我是从较旧的版本升级的，但是我猜它是1.0.0。这是一个传递性依赖项，我将spring-boot-starter-webflux从2.3.4.RELEASE升级到2.4.4。)
关键部分是 wiretap() 的调用:

wiretap("reactor.netty.http.client.HttpClient", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL, StandardCharsets.UTF_8)

它还记录请求和响应的 header 和正文。
整个上下文是这样的:

package com.example;

import io.netty.handler.logging.LogLevel;
import lombok.AllArgsConstructor;
import lombok.Builder;
import lombok.Data;
import lombok.NoArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.springframework.http.HttpMethod;
import org.springframework.http.MediaType;
import org.springframework.http.client.reactive.ReactorClientHttpConnector;
import org.springframework.web.reactive.function.BodyInserters;
import org.springframework.web.reactive.function.client.WebClient;
import reactor.core.publisher.Mono;
import reactor.netty.http.client.HttpClient;
import reactor.netty.transport.logging.AdvancedByteBufFormat;

import java.nio.charset.StandardCharsets;

@Slf4j
class RestClientTest {
    private WebClient createWebClient() {
        final HttpClient httpClient = HttpClient.create()
                .wiretap(HttpClient.class.getCanonicalName(), LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL, StandardCharsets.UTF_8);
        return WebClient.builder()
                .clientConnector(new ReactorClientHttpConnector(httpClient))
                .build();
    }

    @Data
    @Builder
    @NoArgsConstructor
    @AllArgsConstructor
    private static class User {
        int id;
        int userId;
        String title;
        String body;
    }

    @Test
    void createUsersReactive() {
        final WebClient webClient = createWebClient();
        final String url = "http://jsonplaceholder.typicode.com/posts";
        final Mono<User> userMono = webClient.method(HttpMethod.POST)
                .uri(url)
                .contentType(MediaType.APPLICATION_JSON_UTF8)
                .header("X-My-Header", "MyValue1", "MyValue2")
                .body(BodyInserters.fromValue(User.builder().userId(1).title("foo").body("bar").build()))
                .retrieve()
                .bodyToMono(User.class);
        final User user = userMono.block();
        log.info("Created user: " + user);
    }
}

根据您的要求，日志的输出是人类可读的:

... reactor.netty.http.client.HttpClient     : [id:e7d7ed93] REGISTERED
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93] CONNECT: jsonplaceholder.typicode.com/<unresolved>:80
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93] ACTIVE
... r.netty.http.client.HttpClientConnect    : [id:e7d7ed93-1] Handler is being applied: {uri=http://jsonplaceholder.typicode.com/posts, method=POST}
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93-1] WRITE: 217B POST /posts HTTP/1.1
user-agent: ReactorNetty/1.0.5
host: jsonplaceholder.typicode.com
accept: */*
Content-Type: application/json;charset=UTF-8
X-My-Header: MyValue1
X-My-Header: MyValue2
content-length: 46


... reactor.netty.http.client.HttpClient     : [id:e7d7ed93-1] WRITE: 46B {"id":0,"userId":1,"title":"foo","body":"bar"}
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93-1] FLUSH
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93-1] READ: 1347B HTTP/1.1 201 Created
Date: Tue, 13 Apr 2021 12:49:33 GMT
Content-Type: application/json; charset=utf-8
Content-Length: 65
X-Powered-By: Express
X-Ratelimit-Limit: 1000
X-Ratelimit-Remaining: 999
X-Ratelimit-Reset: 1618318233
Vary: Origin, X-HTTP-Method-Override, Accept-Encoding
Access-Control-Allow-Credentials: true
Cache-Control: no-cache
Pragma: no-cache
Expires: -1
Access-Control-Expose-Headers: Location
Location: http://jsonplaceholder.typicode.com/posts/101
X-Content-Type-Options: nosniff
Etag: W/"41-0LtsWqhuQ7Zsjlj0tYnOrT/Vw5o"
Via: 1.1 vegur
CF-Cache-Status: DYNAMIC
cf-request-id: 096ce0bd560000736722853000000001
Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=laAKjgGcoi8SLu%2F6VX5pQIAksdmj9xi31elC5Ld97eljznKIpYjdkQsittoMJp3lJoQIwOACmj89bKSa%2Ff15gRHRmyasV2Xcl%2FmVjJBJm7ytbWocp39UBd90JwVM"}],"max_age":604800,"group":"cf-nel"}
NEL: {"max_age":604800,"report_to":"cf-nel"}
Server: cloudflare
CF-RAY: 63f4d0a88ed07367-CPH
alt-svc: h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400
Proxy-Connection: Keep-Alive
Connection: Keep-Alive
Set-Cookie: __cfduid=d11c86fbd953f7cf768cf7db0c346f22b1618318173; expires=Thu, 13-May-21 12:49:33 GMT; path=/; domain=.typicode.com; HttpOnly; SameSite=Lax

{
  "id": 101,
  "userId": 1,
  "title": "foo",
  "body": "bar"
}
... r.n.http.client.HttpClientOperations     : [id:e7d7ed93-1] Received response (auto-read:false) : [Date=Tue, 13 Apr 2021 12:49:33 GMT, Content-Type=application/json; charset=utf-8, X-Powered-By=Express, X-Ratelimit-Limit=1000, X-Ratelimit-Remaining=999, X-Ratelimit-Reset=1618318233, Vary=Origin, X-HTTP-Method-Override, Accept-Encoding, Access-Control-Allow-Credentials=true, Cache-Control=no-cache, Pragma=no-cache, Expires=-1, Access-Control-Expose-Headers=Location, Location=http://jsonplaceholder.typicode.com/posts/101, X-Content-Type-Options=nosniff, Etag=W/"41-0LtsWqhuQ7Zsjlj0tYnOrT/Vw5o", Via=1.1 vegur, CF-Cache-Status=DYNAMIC, cf-request-id=096ce0bd560000736722853000000001, Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=laAKjgGcoi8SLu%2F6VX5pQIAksdmj9xi31elC5Ld97eljznKIpYjdkQsittoMJp3lJoQIwOACmj89bKSa%2Ff15gRHRmyasV2Xcl%2FmVjJBJm7ytbWocp39UBd90JwVM"}],"max_age":604800,"group":"cf-nel"}, NEL={"max_age":604800,"report_to":"cf-nel"}, Server=cloudflare, CF-RAY=63f4d0a88ed07367-CPH, alt-svc=h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400, Proxy-Connection=Keep-Alive, Connection=Keep-Alive, Set-Cookie=__cfduid=d11c86fbd953f7cf768cf7db0c346f22b1618318173; expires=Thu, 13-May-21 12:49:33 GMT; path=/; domain=.typicode.com; HttpOnly; SameSite=Lax, content-length=65]
... r.n.http.client.HttpClientOperations     : [id:e7d7ed93-1] Received last HTTP packet
... reactor.netty.http.client.HttpClient     : [id:e7d7ed93] READ COMPLETE
... com.example.RestClientTest              : Created user: RestClientIT.User(id=101, userId=1, title=foo, body=bar)