how to log Spring 5 WebClient call

Question

I'm trying to log a request using Spring 5 WebClient. Do you have any idea how could I achieve that?

(I'm using Spring 5 and Spring boot 2)

The code looks like this at the moment:

try {
    return webClient.get().uri(url, urlParams).exchange().flatMap(response -> response.bodyToMono(Test.class))
            .map(test -> xxx.set(test));
} catch (RestClientException e) {
    log.error("Cannot get counter from opus", e);
    throw e;
}

Answer 1

You don't necessarily need to roll your own logger, reactor.ipc.netty.channel.ChannelOperationsHandler does it for you. Just configure your logging system for that class to log at DEBUG level:

2017-11-23 12:52:04.562 DEBUG 41449 --- [ctor-http-nio-5] r.i.n.channel.ChannelOperationsHandler   : [id: 0x9183d6da, L:/127.0.0.1:57681 - R:localhost/127.0.0.1:8000] Writing object DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeHeapByteBuf(ridx: 0, widx: 0, cap: 0))
GET /api/v1/watch/namespaces/default/events HTTP/1.1
user-agent: ReactorNetty/0.7.1.RELEASE
host: localhost:8000
accept-encoding: gzip
Accept: application/json
content-length: 0

One way to have fewer bugs is to not write code whenever possible.

Nov 2018:

With spring-webflux:5.1.2.RELEASE, the above no longer works. Use the following instead:

logging.level.org.springframework.web.reactive.function.client.ExchangeFunctions=DEBUG
...
2018-11-06 20:58:58.181 DEBUG 20300 --- [           main] o.s.w.r.f.client.ExchangeFunctions       : [2026fbff] HTTP GET http://localhost:8080/stocks/search?symbol=AAPL
2018-11-06 20:58:58.451 DEBUG 20300 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [2026fbff] Response 400 BAD_REQUEST

To log headers or form body, set the above to TRACE level; however, that's not enough:

ExchangeStrategies exchangeStrategies = ExchangeStrategies.withDefaults();
exchangeStrategies
    .messageWriters().stream()
    .filter(LoggingCodecSupport.class::isInstance)
    .forEach(writer -> ((LoggingCodecSupport)writer).setEnableLoggingRequestDetails(true));

client = WebClient.builder()
    .exchangeStrategies(exchangeStrategies)

Mar 2019:

In response to a question in the comment that asked how to log request and response body, I don’t know if Spring has such a logger but WebClient is built on Netty, so enabling debug logging for package reactor.ipc.netty should work, along with this answer.

Answer 2

You can have netty do logging of the request/responses with by asking it todo wiretaping, if you create your Spring WebClient like this then it enables the wiretap option.

        WebClient webClient = WebClient.builder()
            .clientConnector(new ReactorClientHttpConnector(
                HttpClient.create().wiretap(true)
            ))
            .build()

and then have your logging setup:

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

this will log everything for the request/response (including bodies), but the format is not specific to HTTP so not very readable.

Answer 3

You can easily do it using ExchangeFilterFunction

Just add the custom logRequest filter when you create your WebClient using WebClient.Builder.

Here is the example of such filter and how to add it to the WebClient.

@Slf4j
@Component
public class MyClient {

    private final WebClient webClient;

    // Create WebClient instance using builder.
    // If you use spring-boot 2.0, the builder will be autoconfigured for you
    // with the "prototype" scope, meaning each injection point will receive
    // a newly cloned instance of the builder.
    public MyClient(WebClient.Builder webClientBuilder) {
        webClient = webClientBuilder // you can also just use WebClient.builder()
                .baseUrl("https://httpbin.org")
                .filter(logRequest()) // here is the magic
                .build();
    }

    // Just example of sending request
    public void send(String path) {
        ClientResponse clientResponse = webClient
                .get().uri(uriBuilder -> uriBuilder.path(path)
                        .queryParam("param", "value")
                        .build())
                .exchange()
                .block();
        log.info("Response: {}", clientResponse.toEntity(String.class).block());
    }

    // This method returns filter function which will log request data
    private static ExchangeFilterFunction logRequest() {
        return ExchangeFilterFunction.ofRequestProcessor(clientRequest -> {
            log.info("Request: {} {}", clientRequest.method(), clientRequest.url());
            clientRequest.headers().forEach((name, values) -> values.forEach(value -> log.info("{}={}", name, value)));
            return Mono.just(clientRequest);
        });
    }

}

Then just call myClient.send("get"); and log messages should be there.

Output example:

Request: GET https://httpbin.org/get?param=value
header1=value1
header2=value2

Answer 4

@Matthew Buckett answer shows you how to get Netty wire logging. However, the format is not very fancy (it includes hex dump). But it can be easily customized via extending io.netty.handler.logging.LoggingHandler

public class HttpLoggingHandler extends LoggingHandler {

    @Override
    protected String format(ChannelHandlerContext ctx, String event, Object arg) {
        if (arg instanceof ByteBuf) {
            ByteBuf msg = (ByteBuf) arg;
            return msg.toString(StandardCharsets.UTF_8);
        }
        return super.format(ctx, event, arg);
    }
}

Then include it in your WebClient configuration:

HttpClient httpClient = HttpClient.create()
    .tcpConfiguration(tcpClient ->
        tcpClient.bootstrap(bootstrap ->
            BootstrapHandlers.updateLogSupport(bootstrap, new HttpLoggingHandler())));

WebClient
    .builder()
    .clientConnector(new ReactorClientHttpConnector(httpClient))
    .build()

Example:

webClient.post()
    .uri("https://postman-echo.com/post")
    .syncBody("{\"foo\" : \"bar\"}")
    .accept(MediaType.APPLICATION_JSON)
    .exchange()
    .block();

2019-09-22 18:09:21.477 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb] REGISTERED
2019-09-22 18:09:21.489 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb] CONNECT: postman-echo.com/35.170.134.160:443
2019-09-22 18:09:21.701 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] ACTIVE
2019-09-22 18:09:21.836 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] READ COMPLETE
2019-09-22 18:09:21.905 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] READ COMPLETE
2019-09-22 18:09:22.036 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
2019-09-22 18:09:22.082 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : POST /post HTTP/1.1
user-agent: ReactorNetty/0.8.11.RELEASE
host: postman-echo.com
Accept: application/json
Content-Type: text/plain;charset=UTF-8
content-length: 15

{"foo" : "bar"}
2019-09-22 18:09:22.083 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] FLUSH
2019-09-22 18:09:22.086 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] READ COMPLETE
2019-09-22 18:09:22.217 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Sun, 22 Sep 2019 15:09:22 GMT
ETag: W/"151-Llbe8OYGC3GeZCxttuAH3BOYBKA"
Server: nginx
set-cookie: sails.sid=s%3APe39li6V8TL8FOJOzSINZRkQlZ7HFAYi.UkLZjfajJqkq9fUfF2Y8N4JOInHNW5t1XACu3fhQYSc; Path=/; HttpOnly
Vary: Accept-Encoding
Content-Length: 337
Connection: keep-alive

{"args":{},"data":"{\"foo\" : \"bar\"}","files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"postman-echo.com","content-length":"15","accept":"application/json","content-type":"text/plain;charset=UTF-8","user-agent":"ReactorNetty/0.8.11.RELEASE","x-forwarded-port":"443"},"json":null,"url":"https://postman-echo.com/post"}
2019-09-22 18:09:22.243 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] READ COMPLETE

If you want to suppress useless (for you) log entries like (note ACTIVE at the end):

2019-09-22 18:09:21.701 DEBUG   --- [ctor-http-nio-4] c.e.w.c.e.logging.HttpLoggingHandler     : [id: 0x505be2bb, L:/192.168.100.35:55356 - R:postman-echo.com/35.170.134.160:443] ACTIVE

You can override channelActive and others like so:

@Override
public void channelActive(ChannelHandlerContext ctx) {
    ctx.fireChannelActive();
}

The answer is based on https://www.baeldung.com/spring-log-webclient-calls

Answer 5

If you don't want to log the body, then this is really easy.

Spring Boot >= 2.1.0

Add the following to application.properties:

logging.level.org.springframework.web.reactive.function.client.ExchangeFunctions=TRACE
spring.http.log-request-details=true

The second line causes headers to be included in the log.

Spring Boot < 2.1.0

Add the following to application.properties:

logging.level.org.springframework.web.reactive.function.client.ExchangeFunctions=TRACE

Instead of the second line above, you need to declare a class like this:

@Configuration
static class LoggingCodecConfig {

    @Bean
    @Order(0)
    public CodecCustomizer loggingCodecCustomizer() {
        return (configurer) -> configurer.defaultCodecs()
                .enableLoggingRequestDetails(true);
    }

}

Courtesy of this Brian Clozel answer