Reactor-netty: How to debug http request & responses with body in a human readable way

[thekalinga]

Currently if we try to log the request & response, the libray logs the request & response bodies in a machine readable way (I'm not sure what the format is). I am not sure which library can be used to view these logged requests & responses in a human readable way. Would be great if the request can be logged in a human readable way directly instead of using special tools.

Expected behavior

Ability to view http request & response in a readable & developer friendly way

Actual behavior

Some hex structure (not sure what this format is) is getting logged instead

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

Steps to reproduce

Enable debugging for package reactor.ipc.netty

Reactor Netty version

0.7.2.RELEASE

JVM version (e.g. java -version)

JRE: 1.8.0_152-release-1024-b6 amd64
JVM: OpenJDK 64-Bit Server VM by JetBrains s.r.o
Linux 4.4.0-34-generic

OS version (e.g. uname -a)

Linux 4.4.0-34-generic #53~14.04.1-Ubuntu SMP x86_64 x86_64 x86_64 GNU/Linux

[asarkar]

@thekalinga FWIW, if it helps, I'm doing the following:

WebClient.Builder builder = WebClient.builder()
.filter((request, next) -> {
    log.info(">> {} {}", request.method(), request.url());
    logHeadersIfDebugEnabled(request.headers(), ">>");

    return next.exchange(request)
      .doOnNext(r -> {
          log.info("<< {} {}", r.statusCode().value(), r.statusCode().getReasonPhrase());
          logHeadersIfDebugEnabled(r.headers().asHttpHeaders(), "<<");
      });
})

Put this in a WebClientFactory.

[rstoyanchev]

It's not accurate to say the output is not human readable. You can clearly see the text in the right-hand column. That said I agree there should be an intermediate level of logging, that doesn't show individual bytes, is easier to read, and more compact. The current output is very verbose and quickly fills up log files, so it should be left as the most detailed level.

[vguna]

Although it helps when debugging in detail like encoded/not visible characters, but to be honest: most of the time you don't need such details :). The simple (e.g. JSON) payload is enough most of the time. It's also cumbersome to copy&paste from such output. So I would love to have an option to simply switch.

@thekalinga : this does not log the body, right?

[thekalinga]

@vguna It does log everything as far as I remmeber

[bclozel]

I'd like to turn this "question" issue into an enhancement request.

I really like this detailed format, and I think it's the best for debugging HTTP issues. But when looking at multiple requests from the same HttpClient, it feels like this gives too much information and that we should have an intermediate level. Other people on StackOverflow are discussing this issue.

What about the following:

• keep this detailed information at the TRACE level
• have a DEBUG level logging feature that writes less detailed information

If we decide to go ahead with this, there are still a few questions to answer:

• how should we keep track of things in case of concurrent requests?
• raw HTTP info and headers should be displayed, but what about large/streaming messages?
• should there be a best-effort solution for formatting payloads (such as JSON content)?

[edeandrea]

Just to add on here as well. This type of debugging/logging is also really helpful when writing tests. For example, when using Spring's MockMvc it can print out the contents of the request/response so that its very easy to find what is causing test failures. With WebClient it doesn't seem so trivial to get similar output (maybe its there and I just don't know where it is - I'm no reactive expert by any means).

[asarkar]

@bclozel IMO

• TRACE and DEBUG: I see TRACE is rarely used. Why not use DEBUG and INFO instead?
• Concurrent requests: I think this is an important but irrelevant concern. The existing logs don't do anything special to track concurrent requests, and Sleuth or Zipkin exist to address that concern.
• Large/streaming messages: If the implementation turns out to be a logger (Interceptor), we can provide options there.
• Formatting payloads: Again, this seems to be outside the concern of the logging system.

[marchev]

Are there any plans for this enhancement to be implemented?

[violetagg]

@marchev It is scheduled for 0.8.x but for sure not for 0.8.4. Are you interested in providing a PR with that functionality?

[dharezlak]

For reactor-netty 0.8.3 the hex structure is no longer printed when I set the following in my spring boot application (only URL and headers are printed):

logging.level.reactor.netty = trace

Is it possible to still see the request and response bodies somehow?

[violetagg]

@dharezlak Use the code below

@Component
public class MyNettyWebServerCustomizer
        implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> {
    @Override
    public void customize(NettyReactiveWebServerFactory factory) {
        factory.addServerCustomizers(httpServer -> httpServer.wiretap(true));
    }
}

[developerworks]

set logging.level.reactor.netty=trace
and add above NettyWebServerCustomizer as a bean, just print the parts of headers like this in the console:

         |  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 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 |.Content-Type: a|
|00000020| 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 3b |pplication/json;|
|00000030| 63 68 61 72 73 65 74 3d 55 54 46 2d 38 0d 0a 43 |charset=UTF-8..C|
|00000040| 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 31 |ontent-Length: 1|
|00000050| 35 32 37 0d 0a 0d 0a                            |527....         |
+--------+-------------------------------------------------+----------------+

How to print full headers ?

[violetagg]

@developerworks These are all the headers. They end with 0d 0a 0d 0a (....) as by spec.

[TheConen]

How do I use this new human readable logging? I'm using Spring with WebFlux and setting

logging.level.reactor.netty.http.client.HttpClient = DEBUG

in my application.properties gives me the Hex debug with wiretap(true) on my WebClient. What do I need to change to get the new human readable logging?

[violetagg]

@TheConen You can use the code below. I'm in a process of adding an example to the reference documentation #1397

wiretap(java.lang.String category, io.netty.handler.logging.LogLevel level, AdvancedByteBufFormat format)

[TheConen]

Thank you, I got this to work with using
wiretap("reactor.netty.http.client.HttpClient", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)

Full code example in case anyone else finds this and needs it:

private WebClient webClient = WebClient.builder()
        .clientConnector(new ReactorClientHttpConnector(
                HttpClient.create().wiretap("reactor.netty.http.client.HttpClient", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)
        ))
        .baseUrl("http://example.com")
        .build();

In application.properties:
logging.level.reactor.netty.http.client.HttpClient = DEBUG

[violetagg]

@TheConen The first argument is any logger that is convenient to you it is not needed to be exactly reactor.netty.http.client.HttpClient

[lackovic]

@TheConen The first argument is any logger that is convenient to you it is not needed to be exactly reactor.netty.http.client.HttpClient

Can you make some examples? I tried with org.apache.logging.log4j.Logger and java.util.logging.Logger but neither of them produced any output.

[TheConen]

The way I understood it is that it is supposed to be the category/package where you want to enable logs - I wanted to enable logs for the HttpClient, so it is reactor.netty.http.client.HttpClient. But honestly, I have no idea, I did some trial and error, found something that worked for me and was happy with it. I was very confused about that, too, because the documentation doesn't mention what a category is supposed to be.

The Javadoc calls it category, while the documentation calls it logger-name. Since neither of them explains what it is supposed to be, at first I thought it can be anything you choose (basically, choosing a name like MyLogger), but that's obviously not the case and what you choose there seems to be directly correlated to the package that will be logged.

[violetagg]

@lackovic @TheConen
Let's take the example from the documentation
https://projectreactor.io/docs/netty/snapshot/reference/index.html#_wire_logger_2

The code is here
https://github.com/reactor/reactor-netty/blob/8a87ab297166d03cd1ab492842f11b421589f106/reactor-netty-examples/src/main/java/reactor/netty/examples/documentation/http/client/wiretap/custom/Application.java#L27

If I configure here https://github.com/reactor/reactor-netty/blob/master/reactor-netty-examples/src/main/resources/logback.xml the log level to DEBUG for this particular logger logger-name

<logger name="logger-name" level="DEBUG" />

Then I will be able to see the following when running the example

...
19:22:02.327 [reactor-http-nio-2] DEBUG logger-name - [id: 0x8f749251, L:/XXX - R:example.com/93.184.216.34:80] WRITE: 110B GET / HTTP/1.1
user-agent: ReactorNetty/1.0.4-SNAPSHOT
host: example.com
accept: */*
content-length: 0
...

[TheConen]

I'm using Spring Boot and Lombok, so I don't have a XML configuration where I define logger names (or, in fact, loggers at all). For me it came down to category / logger-name being equal to the package name of HttpClient if I want to log HttpClient stuff.

[violetagg]

@TheConen for Spring Boot you have logging.level.logger-name=DEBUG in your application.properties file.

[TheConen]

Ah, I see - I was using
logging.level.reactor.netty.http.client.HttpClient = DEBUG
and
.wiretap("reactor.netty.http.client.HttpClient", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL);

So if I were to use
logging.level.mylogger = DEBUG
and
.wiretap("mylogger", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL);

I would get the exact same result - a log of all HTTP requests made on that HttpClient?

@lackovic Does that help you?

[violetagg]

I would get the exact same result - a log of all HTTP requests made on that HttpClient?

yep

[TheConen]

Thanks a lot, now I actually understand what I did - seems like I initially got it to work just by chance and trial and error.

[lackovic]

@TheConen @violetagg that was helpful, thank you both (I am also using _Spring Boot_ and _Lombok_).

[dnedealcov]

I'm struggling to get a whole body from the requests/responses since earlier netty.HttpClient versions.

The below indeed return a body and some details.

return HttpClient.create()
        .wiretap("client-logger", LogLevel.INFO, AdvancedByteBufFormat.TEXTUAL);

But for a reason the logger splits in to parts large bodies. Is there a way to set the logger to return the whole body?

Thank you!

[violetagg]

I'm struggling to get a whole body from the requests/responses since earlier netty.HttpClient versions.

The below indeed return a body and some details.

return HttpClient.create()
        .wiretap("client-logger", LogLevel.INFO, AdvancedByteBufFormat.TEXTUAL);

But for a reason the logger splits in to parts large bodies. Is there a way to set the logger to return the whole body?

Thank you!

@dnedealcov This feature is wire logger because it logs immediately the packages received from the wire, it is not meant to collect and store the data in the memory and then to log it.

[dnedealcov]

I'm struggling to get a whole body from the requests/responses since earlier netty.HttpClient versions.
The below indeed return a body and some details.

return HttpClient.create()
        .wiretap("client-logger", LogLevel.INFO, AdvancedByteBufFormat.TEXTUAL);

But for a reason the logger splits in to parts large bodies. Is there a way to set the logger to return the whole body?
Thank you!

@dnedealcov This feature is wire logger because it logs immediately the packages received from the wire, it is not meant to collect and store the data in the memory and then to log it.

This is strange because in earlier builds (before 1.0.3) you could provide your own logger class and override the format() method, to have your own formatted output. But, for a reason I do not understand you could format only the first part for the message received, while the second was formatted by the default logger.
What I'm trying to say is that you could listen to the wire, gather the data and output it as you wish.

[dnedealcov]

And one more thing, HttpClient uses a Logger class of its own, which uses a ByteBuf (buffer), so why not have an Api to modify the buffers size/capacity?

[violetagg]

This is strange because in earlier builds (before 1.0.3) you could provide your own logger class and override the format() method, to have your own formatted output. But, for a reason I do not understand you could format only the first part for the message received, while the second was formatted by the default logger.
What I'm trying to say is that you could listen to the wire, gather the data and output it as you wish.

@dnedealcov Which release do you mean? - 0.9.x releases? or 1.0.0-1.0.2 releases?
Also did you use wiretap or you were adding your own LoggingHandler?

If you were adding your own LoggingHandler then you can still do that using doOnChannelInit callback.

[dnedealcov]

0.9.7.RELEASE to be exact.

//Client

public HttpClient httpClient() {
return HttpClient.create()
.tcpConfiguration(
tc -> tc.bootstrap(
b -> BootstrapHandlers.updateLogSupport(b, new MyHttpLogger(HttpClient.class))));
}

//Logger

public class MyHttpLogger extends LoggingHandler {

public MyHttpLogger(Class<?> clazz) {
super(clazz);
}

@Override
protected String format(ChannelHandlerContext ctx, String event, Object arg) {
if (arg instanceof ByteBuf) {
ByteBuf msg = (ByteBuf) arg;
return decode(
msg, msg.readerIndex(), msg.readableBytes(), defaultCharset());
}
return super.format(ctx, event, arg);
}

This setup results in one part of the message goes through my format method and the other through the default .log();

[violetagg]

@dnedealcov Yep definitely you have to use doOnChannelInit callback (The code below is adding a handler to the bootstrap).
https://projectreactor.io/docs/netty/release/api/reactor/netty/tcp/TcpClient.html#bootstrap-java.util.function.Function-

.tcpConfiguration(
tc -> tc.bootstrap(
b -> BootstrapHandlers.updateLogSupport(b, new MyHttpLogger(HttpClient.class))));
}

so you have to do

doOnChannelInit((observer, channel, address) -> channel.addFirst(...))

[guicalman]

@violetagg Thank you so much for this answer, I am trying to add a custom LoggingHandler, but I couldn´t find the way of using the doOnChannelInit callback, could you please help me, giving an example of the syntax to replace the deprecated code I show bellow.

HttpClient httpClient = HttpClient
                .create()
                .tcpConfiguration(
                        tc -> tc.bootstrap(
                                b -> BootstrapHandlers.updateLogSupport(b, new CustomNettyLogger(HttpClient.class))));

Thank you so much for your help

@dnedealcov Yep definitely you have to use doOnChannelInit callback (The code below is adding a handler to the bootstrap).
https://projectreactor.io/docs/netty/release/api/reactor/netty/tcp/TcpClient.html#bootstrap-java.util.function.Function-

.tcpConfiguration(
tc -> tc.bootstrap(
b -> BootstrapHandlers.updateLogSupport(b, new MyHttpLogger(HttpClient.class))));
}

so you have to do

doOnChannelInit((observer, channel, address) -> channel.addFirst(...))

[violetagg]

@guicalman With the example below

@Test
void test() {
    HttpClient.create()
        .doOnChannelInit((observer, channel, address) ->
                channel.pipeline()
                    .addFirst(new LoggingHandler("reactor.netty.mylogger")))
        .get()
        .uri("http://example.com")
        .responseContent()
        .aggregate()
        .asString()
        .block();
}

I receive such log (the logger is the one that I specified above reactor.netty.mylogger)

08:42:37.811 [reactor-http-nio-2] DEBUG reactor.netty.mylogger - [id: 0xe48a5e55, L:/XXX:64122 - R:example.com/93.184.216.34:80] WRITE: 99B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d 0a |GET / HTTP/1.1..|

[asarkar]

Something tells me that so many comments on a closed ticket = documentation needs update.

[violetagg]

@asarkar We love PRs ;)

[guicalman]

@violetagg Thank you so much for the example, it worked perfectly fine for me!!!

@guicalman With the example below

@Test
void test() {
  HttpClient.create()
      .doOnChannelInit((observer, channel, address) ->
              channel.pipeline()
                  .addFirst(new LoggingHandler("reactor.netty.mylogger")))
      .get()
      .uri("http://example.com")
      .responseContent()
      .aggregate()
      .asString()
      .block();
}

I receive such log (the logger is the one that I specified above reactor.netty.mylogger)

08:42:37.811 [reactor-http-nio-2] DEBUG reactor.netty.mylogger - [id: 0xe48a5e55, L:/XXX:64122 - R:example.com/93.184.216.34:80] WRITE: 99B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d 0a |GET / HTTP/1.1..|

[guicalman]

@violetagg I have an additional question. Now I am getting in the logs the jsons as Content-Encoding: gzip. Is ther a way to define the expected content encoding type, at the moment of creating httpClient?

@guicalman With the example below

@Test
void test() {
  HttpClient.create()
      .doOnChannelInit((observer, channel, address) ->
              channel.pipeline()
                  .addFirst(new LoggingHandler("reactor.netty.mylogger")))
      .get()
      .uri("http://example.com")
      .responseContent()
      .aggregate()
      .asString()
      .block();
}

I receive such log (the logger is the one that I specified above reactor.netty.mylogger)

08:42:37.811 [reactor-http-nio-2] DEBUG reactor.netty.mylogger - [id: 0xe48a5e55, L:/XXX:64122 - R:example.com/93.184.216.34:80] WRITE: 99B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d 0a |GET / HTTP/1.1..|

[violetagg]

@guicalman Please ask your questions on Gitter

[violetagg]

I updated the documentation with various lifecycle callbacks supported by the servers/clients #1481
https://projectreactor.io/docs/netty/snapshot/reference/index.html#_lifecycle_callbacks_4

For any further questions please use Gitter
If a clarification in the documentation is needed please open another issue.

[dnedealcov]

Hi @violetagg ,

HttpClient.create()
        .doOnChannelInit((observer, channel, address) ->
                channel.pipeline()
                    .addFirst(new LoggingHandler("reactor.netty.mylogger")))

Maybe I'm missing something, but the above does not work for me, as if the logger is not registered in the pipeline?

29-01-2021 09:51:22.754 [reactor-http-nio-2] DEBUG r.n.http.client.HttpClientOperations.debug and not .mylogger

Even if I do something like bellow, no debug logs available.

return HttpClient.create()
        .doOnChannelInit((observer, channel, address) ->
            channel.pipeline()
                .addFirst(new LoggingHandler("reactor.netty.mylogger", LogLevel.DEBUG)));

[violetagg]

@dnedealcov Please ask your questions on Gitter