how to log Spring 5 WebClient call

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;
}
109298 次浏览
小开
最佳答案

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. This method is NOT part of the answer
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

Edit

Some people pointed out in comments that block() is bad practice etc. I want to clarify: block() call here is just for demo purposes. The request logging filter will work anyway. You will not need to add block() to your code to make ExchangeFilterFunction work. You can use WebClient to perform a http-call in a usual way, chaining methods and returning Mono up the stack until someone will subscribe to it. The only relevant part of the answer is logRequest() filter. You can ignore send() method altogether - it is not part of the solution - it just demonstrates that filter works.

Some people also asked how to log the response. To log the response you can write another ExchangeFilterFunction and add it to WebClient. You can use ExchangeFilterFunction.ofResponseProcessor helper for this purpose just the same way as ExchangeFilterFunction.ofRequestProcessor is used. You can use methods of ClientResponse to get headers/cookies etc.

    // This method returns filter function which will log response data
private static ExchangeFilterFunction logResponse() {
return ExchangeFilterFunction.ofResponseProcessor(clientResponse -> {
log.info("Response status: {}", clientResponse.statusCode());
clientResponse.headers().asHttpHeaders().forEach((name, values) -> values.forEach(value -> log.info("{}={}", name, value)));
return Mono.just(clientResponse);
});
}

Don't forget to add it to your WebClient:

.filter(logResponse())

But be careful and do not try to read the response body here in the filter. Because of the stream nature of it, the body can be consumed only once without some kind of buffering wrapper. So, if you will read it in the filter, you will not be able to read it in the subscriber.

If you really need to log the body, you can make the underlying layer (Netty) to do this. See Matthew Buckett's answer to get the idea.

小开

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.

小开

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

小开

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.

小开

@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

小开

An update of Feb 2020 for Spring Boot 2.2.4 and Spring 5.2.3:

I did not manage to get spring.http.log-request-details=true doing its job, and current Spring WebFlux reference suggests that some coding needs be done to have headers logged, though the code example uses deprecated exchangeStrategies() method.

There is still a replacement for the deprecated method, so a compact piece of code for getting headers logged at WebClient level may look like this:

WebClient webClient = WebClient.builder()
.codecs(configurer -> configurer.defaultCodecs().enableLoggingRequestDetails(true))
.build();

with further

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

It should be noted though that not all of the headers are available (do exist) at WebFlux ExchangeFunctions level, so some more logging at Netty HttpClient level may be essential too, as per @Matthew's suggestion:

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

with further

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

This will get bodies logged too.

小开

If you are looking to log the serialized version of the JSON in the request or response, you can create your own Json Encoder/Decoder classes that wrap the defaults and log the JSON. Specifically you would subclass the Jackson2JsonEncoder and Jackson2JsonDecoder classes and override the methods that expose the serial data.

This is explained here: https://andrew-flower.com/blog/webclient-body-logging

The approach shown above is focused mainly on non-streaming data. Doing it for streaming data might be more challenging.

It's obviously not recommended to do this in a Prod environment due to extra memory / processing required, but configuring it for development environments is useful.

小开

@StasKolodyuk's answer elaborates on the solution from baeldung for logging the response body of a reactive WebClient. Note that

tc.bootstrap(...)

is deprecated in

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

Another non-deprecated way to add your custom LoggingHandler is (Kotlin)

val httpClient: HttpClient = HttpClient.create().mapConnect { conn, b ->
BootstrapHandlers.updateLogSupport(b, CustomLogger(HttpClient::class.java))
conn
}
小开

In Spring Boot 2.4.0, the HttpClient's wiretap() method has additional parameters you can pass to show full request/response headers and body in normal human readable format. Use format (AdvancedByteBufFormat.TEXTUAL).

HttpClient httpClient = HttpClient.create()
.wiretap(this.getClass().getCanonicalName(), LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL);
ClientHttpConnector conn = new ReactorClientHttpConnector(httpClient);


WebClient client =  WebClient.builder()
.clientConnector(conn)
.build();

Result:

POST /score HTTP/1.1
Host: localhost:8080
User-Agent: insomnia/2020.5.2
Content-Type: application/json
access_:
Authorization: Bearer eyJ0e....
Accept: application/json
content-length: 4506


WRITE: 4506B {"body":{"invocations":[{"id":....




READ: 2048B HTTP/1.0 200 OK
Content-Type: application/json
Content-Length: 2271
Server: Werkzeug/1.0.1 Python/3.7.7
Date: Fri, 29 Jan 2021 18:49:53 GMT


{"body":{"results":[.....
小开

Spoiler: So far the custom logging with the ExchangeFilterFunction does not support to log the body.

In my case the best logging is achieved with the solution from Bealdung (see this).

Therefore I setup a default builder so the different APIs share this.

@Bean
public WebClient.Builder defaultWebClient() {
final var builder = WebClient.builder();
if (LOG.isDebugEnabled()) {
builder.clientConnector(new ReactorClientHttpConnector(
HttpClient.create().wiretap("reactor.netty.http.client.HttpClient",
LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)
));
}
return builder;
}

In the concrete API configuration I can then configure specific things:

@Bean
public SpecificApi bspApi(@Value("${specific.api.url}") final String baseUrl,
final WebClient.Builder builder) {
final var webClient = builder.baseUrl(baseUrl).build();
return new SpecificApi(webClient);
}

And then I have to set the following property:

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

Then the request log looks like:

021-03-03 12:56:34.589 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8] REGISTERED
2021-03-03 12:56:34.590 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8] CONNECT: /192.168.01:80
2021-03-03 12:56:34.591 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] ACTIVE
2021-03-03 12:56:34.591 DEBUG 20464 --- [ctor-http-nio-2] r.netty.http.client.HttpClientConnect    : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] Handler is being applied: {uri=http://192.168.01/user, method=GET}
2021-03-03 12:56:34.592 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] WRITE: 102B GET /user HTTP/1.1
user-agent: ReactorNetty/1.0.3
host: 192.168.01
accept: */*


<REQUEST_BODY>


2021-03-03 12:56:34.592 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] FLUSH
2021-03-03 12:56:34.592 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] WRITE: 0B
2021-03-03 12:56:34.592 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] FLUSH
2021-03-03 12:56:34.594 DEBUG 20464 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient     : [id: 0xe75a7fb8, L:/192.168.04:56774 - R:/192.168.01:80] READ: 2048B HTTP/1.1 200
Server: nginx/1.16.1
Date: Wed, 03 Mar 2021 11:56:31 GMT
Content-Type: application/json
Content-Length: 4883
Connection: keep-alive
Access-Control-Allow-Origin: *
Content-Range: items 0-4/4


<RESPONSE_BODY>
小开

This is what worked for me in 2021 :)

HttpClient httpClient = HttpClient
.create()
.wiretap(this.getClass().getCanonicalName(),
LogLevel.INFO, AdvancedByteBufFormat.TEXTUAL);


WebClient client = WebClient.builder()
.baseUrl("https://example.com")
.clientConnector(new ReactorClientHttpConnector(httpClient))
.build();
小开

If you are going to implement CustomLoggerHandler, don't forget to implement equals() and hashCode(), otherwise will be a memory leak https://github.com/reactor/reactor-netty/issues/988#issuecomment-582489035

小开

There is a way to log request and response body using only ExchangeFilterFunction. It is independent of the underlying ClientHttpConnector and supports tailor-made output. The actual output isn't included in the implementation. Instead the lines where request and response body can be accessed contain explanatory comments. Add the following class instance to the WebClient filter list:

import org.reactivestreams.Publisher;
import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.http.client.reactive.ClientHttpRequest;
import org.springframework.http.client.reactive.ClientHttpRequestDecorator;
import org.springframework.web.reactive.function.BodyInserter;
import org.springframework.web.reactive.function.client.ClientRequest;
import org.springframework.web.reactive.function.client.ClientResponse;
import org.springframework.web.reactive.function.client.ExchangeFilterFunction;
import org.springframework.web.reactive.function.client.ExchangeFunction;
import reactor.core.publisher.BaseSubscriber;
import reactor.core.publisher.Mono;


import java.util.concurrent.atomic.AtomicBoolean;


public class LoggingExchangeFilterFunction implements ExchangeFilterFunction {


@Override
public Mono<ClientResponse> filter(ClientRequest request, ExchangeFunction next) {
BodyInserter<?, ? super ClientHttpRequest> originalBodyInserter = request.body();
ClientRequest loggingClientRequest = ClientRequest.from(request)
.body((outputMessage, context) -> {
ClientHttpRequestDecorator loggingOutputMessage = new ClientHttpRequestDecorator(outputMessage) {


private final AtomicBoolean alreadyLogged = new AtomicBoolean(false); // Not sure if thread-safe is needed...


@Override
public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
boolean needToLog = alreadyLogged.compareAndSet(false, true);
if (needToLog) {
// use `body.toString(Charset.defaultCharset())` to obtain request body
}
return super.writeWith(body);
}


@Override
public Mono<Void> writeAndFlushWith(Publisher<? extends Publisher<? extends DataBuffer>> body) {
boolean needToLog = alreadyLogged.compareAndSet(false, true);
if (needToLog) {
BaseSubscriber<Publisher<? extends DataBuffer>> bodySubscriber = new BaseSubscriber<Publisher<? extends DataBuffer>>() {
@Override
protected void hookOnNext(Publisher<? extends DataBuffer> next) {
// use `next.toString(Charset.defaultCharset())` to obtain request body element
}
};
body.subscribe(bodySubscriber);
bodySubscriber.request(Long.MAX_VALUE);
}
return super.writeAndFlushWith(body);
}


@Override
public Mono<Void> setComplete() { // This is for requests with no body (e.g. GET).
boolean needToLog = alreadyLogged.compareAndSet(false, true);
if (needToLog) {
// A request with no body, could log `request.method()` and `request.url()`.
}
return super.setComplete();
}
};
return originalBodyInserter.insert(loggingOutputMessage, context);
})
.build();
return next.exchange(loggingClientRequest)
.map(
clientResponse -> clientResponse.mutate()
.body(f -> f.map(dataBuffer -> {
// Use `dataBuffer.toString(Charset.defaultCharset())` to obtain response body.
return dataBuffer;
}))
.build()
);
}


}
小开

Based on Stanislav Burov's answer I made this logger, that logs all request/response headers, method, url and body.

public class WebClientLogger implements ExchangeFilterFunction {


@Override
public Mono<ClientResponse> filter(ClientRequest request, ExchangeFunction next) {
// Log url using 'request.url()'
// Log method using 'request.method()'
// Log request headers using 'request.headers().entrySet().stream().map(Object::toString).collect(joining(","))'


BodyInserter<?, ? super ClientHttpRequest> originalBodyInserter = request.body();


ClientRequest loggingClientRequest = ClientRequest.from(request)
.body((outputMessage, context) -> {
ClientHttpRequestDecorator loggingOutputMessage = new ClientHttpRequestDecorator(outputMessage) {
private final AtomicBoolean alreadyLogged = new AtomicBoolean(false);


@Override
public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
boolean needToLog = alreadyLogged.compareAndSet(false, true);
if (needToLog) {


body = DataBufferUtils.join(body)
.doOnNext(content -> {
// Log request body using 'content.toString(StandardCharsets.UTF_8)'
});
}
return super.writeWith(body);
}


@Override
public Mono<Void> setComplete() { // This is for requests with no body (e.g. GET).
boolean needToLog = alreadyLogged.compareAndSet(false, true);
if (needToLog) {
                            

}
return super.setComplete();
}
};


return originalBodyInserter.insert(loggingOutputMessage, context);
})
.build();


return next.exchange(loggingClientRequest)
.map(clientResponse -> {
// Log response status using 'clientResponse.statusCode().value())'
// Log response headers using 'clientResponse.headers().asHttpHeaders().entrySet().stream().map(Object::toString).collect(joining(","))'


return clientResponse.mutate()
.body(f -> f.map(dataBuffer -> {
// Log response body using 'dataBuffer.toString(StandardCharsets.UTF_8)'
return dataBuffer;
}))
.build();
}
);


}

}

小开

Here's my snippet based on excellent Stanislav Burov's answer. I extracted some lambdas to standalone classes to make code more readable for me and I also implemented a limited UTF-8 aware decoder. I'm using some Guava and Java 17 features, but this code could be easily ported to early versions. I don't buffer the whole request/response body, but rather log buffers as they come in a separate calls, so it does not use excessive RAM or writes extremely long lines.

package kz.doubleservices.healthbus.util;


import org.reactivestreams.Publisher;
import org.slf4j.Logger;
import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.http.client.reactive.ClientHttpRequest;
import org.springframework.http.client.reactive.ClientHttpRequestDecorator;
import org.springframework.lang.NonNull;
import org.springframework.web.reactive.function.BodyInserter;
import org.springframework.web.reactive.function.client.ClientRequest;
import org.springframework.web.reactive.function.client.ClientResponse;
import org.springframework.web.reactive.function.client.ExchangeFilterFunction;
import org.springframework.web.reactive.function.client.ExchangeFunction;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;


import java.util.HexFormat;
import java.util.List;
import java.util.Locale;
import java.util.concurrent.ThreadLocalRandom;
import java.util.function.Function;


import static com.google.common.io.BaseEncoding.base32;


public class LoggingExchangeFilterFunction implements ExchangeFilterFunction {
private final Logger logger;


public LoggingExchangeFilterFunction(Logger logger) {
this.logger = logger;
}


@Override
@NonNull
public Mono<ClientResponse> filter(@NonNull ClientRequest request, @NonNull ExchangeFunction next) {
if (!logger.isDebugEnabled()) {
return next.exchange(request);
}


String requestId = generateRequestId();


if (logger.isTraceEnabled()) {
var message = new StringBuilder();
message.append("HTTP request start; request-id=").append(requestId).append('\n')
.append(request.method()).append(' ').append(request.url());
request.headers().forEach((String name, List<String> values) -> {
for (String value : values) {
message.append('\n').append(name).append(": ").append(value);
}
});
logger.trace(message.toString());
} else {
logger.debug("HTTP request; request-id=" + requestId + '\n' +
request.method() + ' ' + request.url());
}


if (logger.isTraceEnabled()) {
var bodyInserter = new LoggingBodyInserter(logger, requestId, request.body());
request = ClientRequest.from(request).body(bodyInserter).build();
}


return next.exchange(request).map(new LoggingClientResponseTransformer(logger, requestId));
}


private static String generateRequestId() {
var bytes = new byte[5];
ThreadLocalRandom.current().nextBytes(bytes);
return base32().encode(bytes).toLowerCase(Locale.ROOT);
}


private static class LoggingBodyInserter implements BodyInserter<Object, ClientHttpRequest> {
private final Logger logger;
private final String requestId;
private final BodyInserter<?, ? super ClientHttpRequest> originalBodyInserter;


private LoggingBodyInserter(Logger logger, String requestId,
BodyInserter<?, ? super ClientHttpRequest> originalBodyInserter) {
this.logger = logger;
this.requestId = requestId;
this.originalBodyInserter = originalBodyInserter;
}


@Override
@NonNull
public Mono<Void> insert(@NonNull ClientHttpRequest outputMessage, @NonNull Context context) {
var loggingOutputMessage = new LoggingClientHttpRequestDecorator(outputMessage, logger, requestId);
return originalBodyInserter.insert(loggingOutputMessage, context);
}
}


private static class LoggingClientHttpRequestDecorator extends ClientHttpRequestDecorator {
private final Logger logger;
private final String requestId;


public LoggingClientHttpRequestDecorator(ClientHttpRequest delegate, Logger logger, String requestId) {
super(delegate);
this.logger = logger;
this.requestId = requestId;
}


@Override
@NonNull
public Mono<Void> writeWith(@NonNull Publisher<? extends DataBuffer> body) {
Flux<? extends DataBuffer> loggingBody = Flux.from(body)
.doOnNext(this::logDataBuffer)
.doOnComplete(this::logComplete)
.doOnError(this::logError);
return super.writeWith(loggingBody);
}


@Override
@NonNull
public Mono<Void> setComplete() {
logger.trace("HTTP request end; request-id=" + requestId);
return super.setComplete();
}


private void logDataBuffer(DataBuffer dataBuffer) {
int readPosition = dataBuffer.readPosition();
byte[] data = new byte[dataBuffer.readableByteCount()];
dataBuffer.read(data);
dataBuffer.readPosition(readPosition);
logger.trace("HTTP request data; request-id=" + requestId + '\n' + bytesToString(data));
}


private void logComplete() {
logger.trace("HTTP request end; request-id=" + requestId);
}


private void logError(Throwable exception) {
logger.trace("HTTP request error; request-id=" + requestId, exception);
}
}


private static class LoggingClientResponseTransformer implements Function<ClientResponse, ClientResponse> {
private final Logger logger;
private final String requestId;


private LoggingClientResponseTransformer(Logger logger, String requestId) {
this.logger = logger;
this.requestId = requestId;
}


@Override
public ClientResponse apply(ClientResponse clientResponse) {
if (logger.isTraceEnabled()) {
var message = new StringBuilder();
message.append("HTTP response start; request-id=").append(requestId).append('\n')
.append("HTTP ").append(clientResponse.statusCode());
clientResponse.headers().asHttpHeaders().forEach((String name, List<String> values) -> {
for (String value : values) {
message.append('\n').append(name).append(": ").append(value);
}
});
logger.trace(message.toString());
} else {
logger.debug("HTTP response; request-id=" + requestId + '\n' +
"HTTP " + clientResponse.statusCode());
}


return clientResponse.mutate()
.body(new ClientResponseBodyTransformer(logger, requestId))
.build();
}
}


private static class ClientResponseBodyTransformer implements Function<Flux<DataBuffer>, Flux<DataBuffer>> {
private final Logger logger;
private final String requestId;
private boolean completed = false;


private ClientResponseBodyTransformer(Logger logger, String requestId) {
this.logger = logger;
this.requestId = requestId;
}


@Override
public Flux<DataBuffer> apply(Flux<DataBuffer> body) {
return body
.doOnNext(this::logDataBuffer)
.doOnComplete(this::logComplete)
.doOnError(this::logError);
}


private void logDataBuffer(DataBuffer dataBuffer) {
int readPosition = dataBuffer.readPosition();
byte[] data = new byte[dataBuffer.readableByteCount()];
dataBuffer.read(data);
dataBuffer.readPosition(readPosition);
logger.trace("HTTP response data; request-id=" + requestId + '\n' + bytesToString(data));
}


private void logComplete() {
if (!completed) {
logger.trace("HTTP response end; request-id=" + requestId);
completed = true;
}
}


private void logError(Throwable exception) {
logger.trace("HTTP response error; request-id=" + requestId, exception);
}
}


private static String bytesToString(byte[] bytes) {
var string = new StringBuilder(bytes.length);
for (int i = 0; i < bytes.length; i++) {
byte b1 = bytes[i];
if (b1 >= 0) {
if (32 <= b1 && b1 < 127) { // ordinary ASCII characters
string.append((char) b1);
} else {  // control characters
switch (b1) {
case '\t' -> string.append("\\t");
case '\n' -> string.append("\\n");
case '\r' -> string.append("\\r");
default -> {
string.append("\\x");
HexFormat.of().toHexDigits(string, b1);
}
}
}
continue;
}
if ((b1 & 0xe0) == 0xc0) { // UTF-8 first byte of 2-bytes sequence
i++;
if (i < bytes.length) {
byte b2 = bytes[i];
if ((b2 & 0xc0) == 0x80) { // UTF-8 second byte of 2-bytes sequence
char c = (char) ((b1 & 0x1f) << 6 | b2 & 0x3f);
if (Character.isLetter(c)) {
string.append(c);
continue;
}
}
string.append("\\x");
HexFormat.of().toHexDigits(string, b1);
string.append("\\x");
HexFormat.of().toHexDigits(string, b2);
continue;
}
}
string.append("\\x");
HexFormat.of().toHexDigits(string, b1);
}
return string.toString();
}
}
小开

Getting request/response logging right is somehow really difficult when it comes to Spring's reactive WebClient.

I had the following requirements:

  • Log request and response including bodies in one log statement (it's so much more convenient to have it all in one statement if you scroll through hundreds of logs in AWS cloudwatch)
  • Filter sensitiv data such as personal data or financial data from the logs to be compliant with GDPR and PCI

Wiretapping Netty or using custom Jackson en-/decoders was therefore not an option.

Here's my take on the problem (again based on Stanislav's excellent answer).

(The following code uses Lombok annotation processing, which you probably want to use as well, if you don't use it yet. Otherwise it should be easy to de-lombok)

import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.reactivestreams.Publisher;
import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.http.client.reactive.ClientHttpRequest;
import org.springframework.http.client.reactive.ClientHttpRequestDecorator;
import org.springframework.lang.NonNull;
import org.springframework.util.StopWatch;
import org.springframework.web.reactive.function.BodyInserter;
import org.springframework.web.reactive.function.client.ClientRequest;
import org.springframework.web.reactive.function.client.ClientResponse;
import org.springframework.web.reactive.function.client.ExchangeFilterFunction;
import org.springframework.web.reactive.function.client.ExchangeFunction;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;


import java.util.concurrent.atomic.AtomicBoolean;


import static java.lang.Math.min;
import static java.util.UUID.randomUUID;
import static net.logstash.logback.argument.StructuredArguments.v;


@Slf4j
@RequiredArgsConstructor
public class RequestLoggingFilterFunction implements ExchangeFilterFunction {


private static final int MAX_BYTES_LOGGED = 4_096;


private final String externalSystem;


@Override
@NonNull
public Mono<ClientResponse> filter(@NonNull ClientRequest request, @NonNull ExchangeFunction next) {
if (!log.isDebugEnabled()) {
return next.exchange(request);
}


var clientRequestId = randomUUID().toString();


var requestLogged = new AtomicBoolean(false);
var responseLogged = new AtomicBoolean(false);


var capturedRequestBody = new StringBuilder();
var capturedResponseBody = new StringBuilder();


var stopWatch = new StopWatch();
stopWatch.start();


return next
.exchange(ClientRequest.from(request).body(new BodyInserter<>() {


@Override
@NonNull
public Mono<Void> insert(@NonNull ClientHttpRequest req, @NonNull Context context) {
return request.body().insert(new ClientHttpRequestDecorator(req) {


@Override
@NonNull
public Mono<Void> writeWith(@NonNull Publisher<? extends DataBuffer> body) {
return super.writeWith(Flux.from(body).doOnNext(data -> capturedRequestBody.append(extractBytes(data)))); // number of bytes appended is maxed in real code
}


}, context);
}
}).build())
.doOnNext(response -> {
if (!requestLogged.getAndSet(true)) {
log.debug("| >>---> Outgoing {} request [{}]\n{} {}\n{}\n\n{}\n",
v("externalSystem", externalSystem),
v("clientRequestId", clientRequestId),
v("clientRequestMethod", request.method()),
v("clientRequestUrl", request.url()),
v("clientRequestHeaders", request.headers()), // filtered in real code
v("clientRequestBody", capturedRequestBody.toString()) // filtered in real code
);
}
}
)
.doOnError(error -> {
if (!requestLogged.getAndSet(true)) {
log.debug("| >>---> Outgoing {} request [{}]\n{} {}\n{}\n\nError: {}\n",
v("externalSystem", externalSystem),
v("clientRequestId", clientRequestId),
v("clientRequestMethod", request.method()),
v("clientRequestUrl", request.url()),
v("clientRequestHeaders", request.headers()), // filtered in real code
error.getMessage()
);
}
})
.map(response -> response.mutate().body(transformer -> transformer
.doOnNext(body -> capturedResponseBody.append(extractBytes(body))) // number of bytes appended is maxed in real code
.doOnTerminate(() -> {
if (stopWatch.isRunning()) {
stopWatch.stop();
}
})
.doOnComplete(() -> {
if (!responseLogged.getAndSet(true)) {
log.debug("| <---<< Response for outgoing {} request [{}] after {}ms\n{} {}\n{}\n\n{}\n",
v("externalSystem", externalSystem),
v("clientRequestId", clientRequestId),
v("clientRequestExecutionTimeInMillis", stopWatch.getTotalTimeMillis()),
v("clientResponseStatusCode", response.statusCode().value()),
v("clientResponseStatusPhrase", response.statusCode().getReasonPhrase()),
v("clientResponseHeaders", response.headers()), // filtered in real code
v("clientResponseBody", capturedResponseBody.toString()) // filtered in real code
);
}
})
.doOnError(error -> {
if (!responseLogged.getAndSet(true)) {
log.debug("| <---<< Error parsing response for outgoing {} request [{}] after {}ms\n{}",
v("externalSystem", externalSystem),
v("clientRequestId", clientRequestId),
v("clientRequestExecutionTimeInMillis", stopWatch.getTotalTimeMillis()),
v("clientErrorMessage", error.getMessage())
);
}
}
)
).build()
);
}


private static String extractBytes(DataBuffer data) {
int currentReadPosition = data.readPosition();
var numberOfBytesLogged = min(data.readableByteCount(), MAX_BYTES_LOGGED);
var bytes = new byte[numberOfBytesLogged];
data.read(bytes, 0, numberOfBytesLogged);
data.readPosition(currentReadPosition);
return new String(bytes);
}


}

Log entries look like this for successful exchanges:

2021-12-07 17:14:04.029 DEBUG --- [ctor-http-nio-3] RequestLoggingFilterFunction        : | >>---> Outgoing SnakeOil request [6abd0170-d682-4ca6-806c-bbb3559998e8]
POST https://localhost:8101/snake-oil/oauth/token
Content-Type: application/x-www-form-urlencoded


grant_type=client_credentials&client_id=*****&client_secret=*****

2021-12-07 17:14:04.037 DEBUG --- [ctor-http-nio-3] RequestLoggingFilterFunction        : | <---<< Response for outgoing SnakeOil request [6abd0170-d682-4ca6-806c-bbb3559998e8] after 126ms
200 OK
Content-Type: application/json
Vary: [Accept-Encoding, User-Agent]
Transfer-Encoding: chunked


{"access_token":"*****","expires_in":"3600","token_type":"BearerToken"}

Error conditions are handled gracefully as well, of course.

小开

You can do trace webclient logs including request and response body payload with some manipulations using filter function:

public class TracingExchangeFilterFunction implements ExchangeFilterFunction {




return next.exchange(buildTraceableRequest(request))
.flatMap(response ->
response.body(BodyExtractors.toDataBuffers())
.next()
.doOnNext(dataBuffer -> traceResponse(response, dataBuffer))
.thenReturn(response)) ;
}


private ClientRequest buildTraceableRequest(
final ClientRequest clientRequest) {
return ClientRequest.from(clientRequest).body(
new BodyInserter<>() {
@Override
public Mono<Void> insert(
final ClientHttpRequest outputMessage,
final Context context) {
return clientRequest.body().insert(
new ClientHttpRequestDecorator(outputMessage) {
@Override
public Mono<Void> writeWith(final Publisher<? extends DataBuffer> body) {
return super.writeWith(
from(body).doOnNext(buffer ->
traceRequest(clientRequest, buffer)));
}
}, context);
}
}).build();
}


private void traceRequest(ClientRequest clientRequest, DataBuffer buffer) {
final ByteBuf byteBuf = NettyDataBufferFactory.toByteBuf(buffer);
final byte[] bytes = ByteBufUtil.getBytes(byteBuf);
// do some tracing
}




private void traceResponse(ClientResponse response, DataBuffer dataBuffer) {
final byte[] bytes = new byte[dataBuffer.readableByteCount()];
dataBuffer.read(bytes);
// do some tracing
}

}

小开

For those asking about the same with WebTestClient the answer is very similar:

final HttpClient httpClient = HttpClient
.create()
.wiretap(
this.getClass().getCanonicalName(),
LogLevel.INFO,
AdvancedByteBufFormat.TEXTUAL);


final WebTestClient webTestClient = WebTestClient
.bindToServer(new ReactorClientHttpConnector(httpClient))
.build();

提交答案