Spring WebClient Body Logging
Sometimes for various reasons it’s valuable to see how a model is serialized into JSON or how a response looks before being deserialized into a Java class.
With the Spring WebClient it’s not trivial to see how to do this. For the majority of use-cases this is not a difficult thing to do and I will show how to do it for request bodies as well as response bodies.
This article is targeting the following products and versions:
| Spring Boot | 2.4.2 |
|---|---|
| Java | 11 |
| JUnit | 5 |
The accompanying source code is available here:
Custom Codecs
When building the WebClient there is an option to provide the codecs that will be used for encoding and decoding (AKA serializing/deserializing) request/responses. Because these codecs are responsible for the de/serialization stage, they have access to the raw data for/from the wire.
The principle shown here will make use of this fact by providing as codecs, wrapper classes around the default encoder and decoder. To do this, the WebClient might be created as shown below:
WebClient webClient = WebClient.builder() .baseUrl(configuration.getServerBasePath()) .codecs(codecConfigurer -> < codecConfigurer.defaultCodecs().jackson2JsonEncoder(loggingEncoder); codecConfigurer.defaultCodecs().jackson2JsonDecoder(loggingDecoder); >) .build(); Logging the Serialized Request
By default WebClient is configured with the Jackson2JsonEncoder . The method that does most of the work, which we’re interested in, is encodeValue() located in the abstract superclass AbstractJackson2Encoder .
Note: This method is called for Mono objects and for each object in a non-streaming Flux . Streaming Flux data would not be processed by this method and therefore will not work with the form of the approach shown here.
We will need to also provide a way for our encoder to send the serial data out after serialization. One way we can do this is to provide a Consumer to the class as a callback for logging. With this in mind, we could wrap the default JSON encoder in a subclass as follows:
public class LoggingJsonEncoder extends Jackson2JsonEncoder < private final ConsumerpayloadConsumer; public LoggingJsonEncoder(final Consumer payloadConsumer) < this.payloadConsumer = payloadConsumer; >@Override public DataBuffer encodeValue(final Object value, final DataBufferFactory bufferFactory, final ResolvableType valueType, @Nullable final MimeType mimeType, @Nullable final Map hints) < // Encode/Serialize data to JSON final DataBuffer data = super.encodeValue(value, bufferFactory, valueType, mimeType, hints); // Interception: Generate Signature and inject header into request bodyConsumer.accept(ByteUtils.extractBytesAndReset(data)); // Return the data as normal return data; >> The class is very simple. We wrap the encodeValue() method and delegate the encoding job to the original superclass body in Line 13. From the resulting DataBuffer we can then extract the byte data and pass it along to the interested party via the Consumer that was passed in during construction. The juice for extracting the bytes is shown below, and is defined separately as it is used in the next example too.
static byte[] extractBytesAndReset(final DataBuffer data)
The important line to note is Line 4, where the read position is reset to 0. This allows the WebClient to continue on as it usually would.
Logging the Response (Pre-deserialization)
A similar approach is used for exposing the payload data of the response in serialized form. In this case we will wrap the default decoder, Jackson2JsonDecoder .
NOTE: This example only shows the solution in the case the data is decoded to a Mono (ie. usage of bodyToMono() ) by overriding decodeToMono() on the decoder. Doing this for a Flux output is more involved and not covered right now.
Below you can see the custom decoder that exposes the response payload in serialized form (just before deserialization).
public class LoggingJsonDecoder extends Jackson2JsonDecoder < private final ConsumerpayloadConsumer; public LoggingJsonEncoder(final Consumer payloadConsumer) < this.payloadConsumer = payloadConsumer; >@Override public Mono decodeToMono(final Publisher input, final ResolvableType elementType, final MimeType mimeType, final Map hints) < // Buffer for bytes from each published DataBuffer final ByteArrayOutputStream payload = new ByteArrayOutputStream(); // Augment the Flux, and intercept each group of bytes buffered final Fluxinterceptor = Flux.from(input) .doOnNext(buffer -> bufferBytes(payload, buffer)) .doOnComplete(() -> payloadConsumer.accept(payload.toByteArray())); // Return the original method, giving our augmented Publisher return super.decodeToMono(interceptor, elementType, mimeType, hints); > private void bufferBytes(final ByteArrayOutputStream bao, final DataBuffer buffer) < try < bao.write(ByteUtils.extractBytesAndReset(buffer)); >catch (IOException e) < throw new RuntimeException(e); >> > The decodeToMono() method receives a Publisher from which the data flows from the network stream. The payload is provided in sequential DataBuffer objects. This custom decoder extracts the bytes from each of these DataBuffer objects (in the doOnNext callback) and buffers them in an array. Finally when the Publisher is finished (in the doOnComplete callback), the full byte array is sent to the provided Consumer . extractBytesAndReset() is the same as from the previous section.
Verifying with Tests
If you care whether something works, it’s best to write a test. So in order to show how to use these examples as well as verifying they work, I’ve done so with two JUnit 5 tests. Obviously in the real world you would possibly configure the WebClient as a Bean, and you wouldn’t want to be using block() in reactive code very much, but for tests this is ok.
For these tests, to make mocking responses and capturing payloads easy, we’ll use MockWebServer.
@Test @DisplayName("Should log the same JSON as received by the server for the request") public void postPayloadLoggedAfterEncoding() throws Exception < mockBackEnd.enqueue(new MockResponse().setBody("").addHeader("Content-Type", "application/json")); final StringBuffer loggedJsonBuffer = new StringBuffer(); final LoggingJsonEncoder encoder = new LoggingJsonEncoder( data ->loggedJsonBuffer.append(new String(data))); final WebClient webClient = WebClient.builder() .baseUrl("http://localhost:" + mockBackEnd.getPort() + "/") .codecs(c -> c.defaultCodecs().jackson2JsonEncoder(encoder)) .build(); webClient.post() .uri("/aa") .contentType(MediaType.APPLICATION_JSON) .body(BodyInserters.fromValue(TEST_DATA)) .exchangeToMono(r -> r.releaseBody()) .block(); final String transmittedJson = mockBackEnd.takeRequest().getBody().readString(StandardCharsets.UTF_8); assertEquals(transmittedJson, loggedJsonBuffer.toString()); >The first test tests capturing of the encoded request payload. Lines 6-7 setup our custom encoder with a Consumer that interprets the byte data as a String and saves that String to a StringBuffer which is used in the assertion later. Line 16 specifies the object to be serialized as JSON. Line 21 shows the assertion that the string data received by the mock server is the same as what was logged into the StringBuffer by our custom encoder.
@Test @DisplayName("Should log the same data as sent by the server in the response") public void responseLoggedBeforeDecoding() throws Exception < final StringBuffer loggedJsonBuffer = new StringBuffer(); final LoggingJsonDecoder decoder = new LoggingJsonDecoder( data ->loggedJsonBuffer.append(new String(data))); WebClient webClient = WebClient.builder() .baseUrl("http://localhost:" + mockBackEnd.getPort() + "/") .codecs(c -> c.defaultCodecs().jackson2JsonDecoder(decoder)) .build(); final String responseJsonStub = new ObjectMapper().writeValueAsString(TEST_DATA); mockBackEnd.enqueue(new MockResponse() .setBody(responseJsonStub) .addHeader("Content-Type", "application/json")); final TestModel parsedData = webClient.get() .uri("/aa") .accept(MediaType.APPLICATION_JSON) .exchangeToMono(r -> r.bodyToMono(TestModel.class)) .block(); mockBackEnd.takeRequest(); assertEquals(TEST_DATA, parsedData); assertEquals(responseJsonStub, loggedJsonBuffer.toString()); >The second test tests the capturing of the response data before deserialization. The mock server is setup to return a serialized form of our data (Line 13). Our decoder is created in Lines 5-6 to write the captured payload data as a String to a StringBuffer . The request is made to the WebClient, which receives a response from the mock server. We instruct the WebClient in Line 19 to convert the payload into a Mono of our model class. This will trigger the decodeToMono method in our decoder. Finally, in Line 24 we compare the logged data from our decoder with the data we gave to the mock server.
WARNING: Logging the payloads like this will have memory impact as you are buffering all the same data, as well as some performance impact. This is not recommended for Prod environments but can be very useful in development or test environments. Use your Spring @Profile s to configure WebClient with/without logging per-environment.
Summary
In the above we learned the following:
- We can get a handle on payload data by providing our own codecs to WebClient.
- This approach in the version proposed here does not work for streaming data.
- This can be configured in a Spring application to only use the custom codecs in Development or Test environments (for example, using Spring Profiles)
If this was helpful, has some issues or is lacking, please feel free to comment below!
The accompanying source code is available here:
References
About Spring WebClient
Spring is going Reactive. You only need to take one look at the talks featured at the Spring One 2020 conference to see that Reactive Web and functional programming paradigms in Java and Spring were at the forefront. One of the interesting issues with doing things in a non-blocking manner is that simple things like logging can sometimes become a little bit more complicated. Because you don’t know exactly WHEN the data will be available, you can’t really just toss it into a log the same way you’d do it with something like Spring’s RestTemplate. (Speaking of RestTemplate, it looks like it’s targeted for deprecation! https://docs.spring.io/spring-framework/docs/current/javadoc-api/index.html?org/springframework/web/client/RestTemplate.html) As per the documentation, we ought to be using org.springframework.web.reactive.client.WebClient for our outbound API calls nowadays, especially because it provides the ability for us to utilize blocking and non-blocking methods. Now anyone who has used Spring WebClient can attest to the fact that retrieving the request content or response content can sometimes be a little bit difficult, especially if you’re looking for a specific format. There’s dozens of unanswered Stack Overflow posts that have the same response, check out Baeldung’s article on the subject: https://www.baeldung.com/spring-log-webclient-calls. Now Baeldung has saved my butt more times than I can count, in side projects AND professionally. However, the article doesn’t show much more than basic implementation examples. What’s missing is the example output, and sharing the caveats that aren’t mentioned in the article. So without further ado, here’s a walk-through of the best method (in my opinion) to do request and response logging (with the HTTP body) in Spring Webclient, with examples, comments and output. Netty logging is included in Baeldung’s post but isn’t nearly as granular as the Jetty HTTP client. The very first step is adding the required dependency that will give us access to the underlying HTTP client.
The Code
# Gradle implementation group: 'org.eclipse.jetty', name: 'jetty-reactive-httpclient', version: '1.1.4' # Maven org.eclipse.jetty jetty-reactive-httpclient 1.1.4 Once we have access to the classes we need, there’s two components that need to be built. The first is our enhance method. This method takes a Request and gives a request back, allowing us to intercept and log all of the pieces we care about. Here’s an example enhance method and it’s output:
// org.eclipse.jetty.client.api.Request private Request enhance(Request inboundRequest) < StringBuilder log = new StringBuilder(); // Request Logging inboundRequest.onRequestBegin(request ->log.append("Request: \n") .append("URI: ") .append(request.getURI()) .append("\n") .append("Method: ") .append(request.getMethod())); inboundRequest.onRequestHeaders(request -> < log.append("\nHeaders:\n"); for (HttpField header : request.getHeaders()) < log.append("\t\t" + header.getName() + " : " + header.getValue() + "\n"); >>); inboundRequest.onRequestContent((request, content) -> log.append("Body: \n\t") .append(content.toString())); log.append("\n"); // Response Logging inboundRequest.onResponseBegin(response -> log.append("Response:\n") .append("Status: ") .append(response.getStatus()) .append("\n")); inboundRequest.onResponseHeaders(response -> < log.append("Headers:\n"); for (HttpField header : response.getHeaders()) < log.append("\t\t" + header.getName() + " : " + header.getValue() + "\n"); >>); inboundRequest.onResponseContent(((response, content) -> < var bufferAsString = StandardCharsets.UTF_8.decode(content).toString(); log.append("Response Body:\n" + bufferAsString); >)); // Add actual log invocation logger.info("HTTP ->\n"); inboundRequest.onRequestSuccess(request -> logger.info(log.toString())); inboundRequest.onResponseSuccess(response -> logger.info(log.toString())); // Return original request return inboundRequest; > The request object provides plenty of hooks to reach in and grab the data you are looking to log. Interface docs are here -> https://www.eclipse.org/jetty/javadoc/9.4.8.v20171121/org/eclipse/jetty/client/api/Request.html To get our enhance method executed during the invocation of our WebClient, we’re going to create our own HttpClient and use it in place of the default JettyClientHttpConnector. Here’s an example bean that provides the WebClient:
@Bean public WebClient jettyHttpClient() < SslContextFactory.Client sslContextFactory = new SslContextFactory.Client(); HttpClient httpClient = new HttpClient(sslContextFactory) < @Override public Request newRequest(URI uri) < Request request = super.newRequest(uri); return enhance(request); >>; return WebClient.builder().clientConnector(new JettyClientHttpConnector(httpClient)).build(); > The Output
Now using the WebClient that we’ve seeded with our underlying HttpClient, we get the following output:
2020-10-08 15:00:00.000 INFO 2100 --- [ @cafebabe-37] c.s.l.examples.JettyWebClient : Request: URI: http://httpbin.org/get Method: GET Headers: Accept-Encoding : gzip User-Agent : Jetty/9.4.31.v20200723 Accept : */* Host : httpbin.org Response: Status: 200 Headers: Date : Thu, 08 Oct 2020 20:24:17 GMT Content-Type : application/json Content-Length : 297 Connection : keep-alive Server : gunicorn/19.9.0 Access-Control-Allow-Origin : * Access-Control-Allow-Credentials : true Response Body: < "args": <>, "headers": < "Accept": "*/*", "Accept-Encoding": "gzip", "Host": "httpbin.org", "User-Agent": "Jetty/9.4.31.v20200723", "X-Amzn-Trace-Id": "Root=1-5f7f7571- 157328ac70a3bd900bc1c8bc" >, "origin": "12.345.678.91", "url": "http://httpbin.org/get" >