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;
}
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 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.
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.
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.
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
@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.
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":[.....
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();
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>
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()
);
}
}
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
}
