Readable debug logging for http requests with spring webclient

Question

I'm using Spring reactive WebClient for sending requests to a http server. Inorder to view the underlying request & response that's being sent, I enabled debug logging for reactor.ipc.netty package.

The headers for the outgoing requests can be viewed normally.

Tho I'm sending & receiving plain text over http, the log contains the request & responses in the below format (is it hex?)

I'm not sure how to view the logged data in a easy to understand way. Better yet log the request & response in a understandable way

Here is a snippet of the logged data

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

Found an unanswered question that must be happening because of the same library: Reading a HttpContent that has a PooledUnsafeDirectByteBuf

Raised an issue here

There seems to an orthodox view that debugging is not required for reactive clients. This is a completely pointless arguments as we use tools like rest client, postman, curl, httpie & others to send request and view response

Answer 1

They changed the reactor.netty.http.client.HttpClient class, after I upgraded to io.projectreactor.netty:reactor-netty-http:1.0.5 the following code is compilable and does what you expect. (I am not sure which is the minimal version, I upgraded from something older, but I guess it's 1.0.0. It is a transitive dependency, I upgraded spring-boot-starter-webflux from 2.3.4.RELEASE to 2.4.4.)

The crucial part is the call of wiretap():

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

It logs also the header and body of the request and of the response.

The whole context is this:

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);
    }
}

And the output to log is human readable as you request:

... 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)