使用 spring webclient 对 http 请求进行可读的调试日志记录

Posted 2023-02-27

【中文标题】使用 spring webclient 对 http 请求进行可读的调试日志记录

【英文标题】：Readable debug logging for http requests with spring webclient

【发布时间】：2018-05-15 17:55:20

【问题描述】：

我正在使用 Spring 反应式 WebClient 向 http 服务器发送请求。为了查看正在发送的底层请求和响应，我为 reactor.ipc.netty 包启用了调试日志记录。

外发请求的header可以正常查看。

虽然我通过 http 发送和接收纯文本，但日志包含以下格式的请求和响应（是十六进制吗？）

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

这是记录数据的 sn-p

         +-------------------------------------------------+
         |  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

似乎有一种正统观点认为反应式客户端不需要调试。这是一个完全没有意义的论点，因为我们使用rest client、postman、curl、httpie 等工具来发送请求和查看响应

【问题讨论】：

你可以在中间放置一个像 MembraneSoa 这样的代理

不确定通过特殊代理调试应用程序请求会有多大用处

How to log request and response bodies in Spring WebFlux的可能重复

找到好的解决方案了吗？

@AbhijitSarkar，我不同意你的观点，你所指的问题是关于拦截请求/响应和/或实现任何用户定义日志记录的一般机制，而这个问题是关于如何配置内置低级日志记录机制的格式。

【参考方案1】：

他们更改了reactor.netty.http.client.HttpClient 类，在我升级到io.projectreactor.netty:reactor-netty-http:1.0.5 之后，以下代码是可编译的，并且可以满足您的期望。 （我不确定哪个是 minimal 版本，我是从旧版本升级的，但我猜是 1.0.0。这是一个传递依赖，我将 spring-boot-starter-webflux 从 2.3.4.RELEASE 升级到 @987654328 @.)

关键部分是wiretap()的调用：

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

它还记录请求和响应的标头和正文。

整个上下文是这样的：

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)

【讨论】：

有没有办法访问窃听器正在写入控制台的数据？我需要将响应保存到我的数据库

【参考方案2】：

如果您使用 DataBuffer 作为阅读器，您可以使用 doOnNext() 来完成：

public Mono<ServerResponse> selectByPost(ServerRequest request) 
  Flux<DataBuffer> requestBodyFlux = request.bodyToFlux(DataBuffer.class)
    .doOnNext(dataBuffer -> 
      if (debug ) 
        log.debug(new String(dataBuffer.asByteBuffer().array()));
      
      Scannable.from(dataBuffer).tags().forEach(System.out::println);
    );

这可能不是最好的方法，如果 netty 提供不同的方式来记录有效负载，它当然是一个不错的功能。 Hex 确实有它的好处，具体取决于您需要调试的内容。

【讨论】：

现在netty 确实提供了更优雅的方式，请看我的回答。

【参考方案3】：

似乎响应服务器正在返回 gzip 压缩的内容，因此您无法阅读它是有道理的。

如果您真的想在原始 HTTP 级别拦截，请确保您的请求标头未指定它可以接受 GZipped 内容 (accept-encoding: gzip)。

另一种选择可能是在另一层记录请求，此时它已经从原始数据流中解压缩，但尚未由您的应用程序代码处理 - 虽然不确定这在 Reactive webclient 中如何工作;)

【讨论】：

不，即使我的纯文本请求正文也是这种格式。

您提供的正文可能是纯文本，但 Spring 客户端会在它被连接到网络之前对其应用一些魔法，以最大限度地减少开销/带宽。不确定是否可以禁用 GZipping

这里我们在客户端使用spring。客户端可以在不知道服务器功能的情况下以 gzip 格式发送数据吗？或者甚至允许客户端以 gzip 格式发送请求？我不认为 gzip 是这里的问题。我的假设是他们正在打印一些十六进制格式以涵盖二进制和文本请求正文用例

这不是压缩的 - 这只是以 ascii 和 hex 格式显示的请求...