12

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

Ashok Koyi
  • 5,327
  • 8
  • 41
  • 50
  • You could put a proxy like MembraneSoa in between – Marged Dec 01 '17 at 15:56
  • Not sure how useful it would be to debug an application request via special proxies – Ashok Koyi Dec 01 '17 at 16:15
  • Possible duplicate of [How to log request and response bodies in Spring WebFlux](https://stackoverflow.com/questions/45240005/how-to-log-request-and-response-bodies-in-spring-webflux) – Abhijit Sarkar Jan 02 '18 at 04:21
  • 1
    Did you find a good solution? – membersound Jul 11 '19 at 11:16
  • @membersound Yes, I found a good solution, see my answer. – Honza Zidek Apr 09 '21 at 19:15
  • 1
    @AbhijitSarkar, I do not agree with you, the question you are referring to is about general mechanism of intercepting request/response and/or implementing any user-defined logging, whilst this question is about how to configure the format of a built-in low-level logging mechanism. – Honza Zidek Apr 09 '21 at 20:31

3 Answers3

5

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)
Honza Zidek
  • 9,204
  • 4
  • 72
  • 118
  • is there a way to access the data which wiretap is writing to the console? I need to save the response to my DB – Maxi Dec 06 '21 at 08:15
0

You can do it with doOnNext(), if you use DataBuffer as your reader:

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

This is probably not the best way to do it, it would of course be a nice feature, if netty would provide different ways of logging the payload. Hex does have its benefits, depending on what you need to debug.

Frischling
  • 2,100
  • 14
  • 34
-4

Seems like the responding server is returning gzipped content, so it makes sense that you're not able to read it.

If you really want to intercept at the raw HTTP level, ensure your request header does not specify it can accept GZipped content (accept-encoding: gzip).

Another alternative may be to log the request at another layer, when it's already been unzipped from the raw data stream, but not yet processed by your application code - not sure how this would work in Reactive webclient though ;)

  • 1
    No, even my request body which is plain text is in that format. – Ashok Koyi Dec 01 '17 at 15:53
  • The body you provide it may be in plain text, but the Spring client will apply some magic to it before it's put on the wire to minimize overhead/bandwidth. Not sure if you can disable GZipping – Frederik Heremans Dec 01 '17 at 15:57
  • 1
    Here we are using spring on the clientside. Can a client send the data in gzip format, without knowing server capabilities? or is it even allowed for client send request in gzip format? I dont think gzip is the issue here. My assumption is that they are printing it some hex format to cover both binary & text request body usescases – Ashok Koyi Dec 02 '17 at 10:49
  • This is not compressed - this is just the request displayed in both ascii and hex formats... – Brian Clozel Feb 24 '18 at 18:18