BAEL-3009: Logging Spring WebClient calls

spring-5-reactive-client/pom.xml

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
-    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
+         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
     <modelVersion>4.0.0</modelVersion>
     <artifactId>spring-5-reactive-client</artifactId>
     <name>spring-5-reactive-client</name>
@@ -56,7 +56,6 @@
         </dependency>
 
         <!-- runtime and test scoped -->
-
         <dependency>
             <groupId>org.springframework.boot</groupId>
             <artifactId>spring-boot-devtools</artifactId>
@@ -89,6 +88,14 @@
             <groupId>org.projectlombok</groupId>
             <artifactId>lombok</artifactId>
         </dependency>
+
+        <!-- WebClient logging with Jetty -->
+        <dependency>
+            <groupId>org.eclipse.jetty</groupId>
+            <artifactId>jetty-reactive-httpclient</artifactId>
+            <version>${jetty-reactive-httpclient.version}</version>
+            <scope>test</scope>
+        </dependency>
     </dependencies>
 
     <build>
@@ -110,6 +117,7 @@
         <jsonb-api.version>1.0</jsonb-api.version>
         <geronimo-json_1.1_spec.version>1.0</geronimo-json_1.1_spec.version>
         <commons-collections4.version>4.1</commons-collections4.version>
+        <jetty-reactive-httpclient.version>1.0.3</jetty-reactive-httpclient.version>
     </properties>
 
 </project>

spring-5-reactive-client/src/test/java/com/baeldung/reactive/logging/WebClientLoggingIntegrationTest.java

@@ -0,0 +1,150 @@
+package com.baeldung.reactive.logging;
+
+import ch.qos.logback.classic.spi.LoggingEvent;
+import ch.qos.logback.core.Appender;
+import com.baeldung.reactive.logging.filters.LogFilters;
+import com.baeldung.reactive.logging.jetty.RequestLogEnhancer;
+import com.baeldung.reactive.logging.netty.CustomLogger;
+import com.fasterxml.jackson.databind.ObjectMapper;
+import java.net.URI;
+import lombok.AllArgsConstructor;
+import lombok.Data;
+import org.eclipse.jetty.client.api.Request;
+import org.eclipse.jetty.util.ssl.SslContextFactory;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.slf4j.LoggerFactory;
+import org.springframework.http.client.reactive.JettyClientHttpConnector;
+import org.springframework.http.client.reactive.ReactorClientHttpConnector;
+import org.springframework.web.reactive.function.BodyInserters;
+import org.springframework.web.reactive.function.client.WebClient;
+import reactor.netty.channel.BootstrapHandlers;
+import reactor.netty.http.client.HttpClient;
+
+import static org.mockito.ArgumentMatchers.argThat;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
+
+
+public class WebClientLoggingIntegrationTest {
+
+    @AllArgsConstructor
+    @Data
+    class Post {
+        private String title;
+        private String body;
+        private int userId;
+    }
+
+    private Appender jettyAppender;
+    private Appender nettyAppender;
+    private Appender mockAppender;
+    private String sampleUrl = "https://jsonplaceholder.typicode.com/posts";
+
+    private Post post;
+    private String sampleResponseBody;
+
+    @BeforeEach
+    private void setup() throws Exception {
+
+        post = new Post("Learn WebClient logging with Baeldung!", "", 1);
+        sampleResponseBody = new ObjectMapper().writeValueAsString(post);
+
+        ch.qos.logback.classic.Logger jetty = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.baeldung.reactive.logging.jetty");
+        jettyAppender = mock(Appender.class);
+        when(jettyAppender.getName()).thenReturn("com.baeldung.reactive.logging.jetty");
+        jetty.addAppender(jettyAppender);
+
+        ch.qos.logback.classic.Logger netty = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("reactor.netty.http.client");
+        nettyAppender = mock(Appender.class);
+        when(nettyAppender.getName()).thenReturn("reactor.netty.http.client");
+        netty.addAppender(nettyAppender);
+
+        ch.qos.logback.classic.Logger test = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.baeldung.reactive");
+        mockAppender = mock(Appender.class);
+        when(mockAppender.getName()).thenReturn("com.baeldung.reactive");
+        test.addAppender(mockAppender);
+
+    }
+
+    @Test
+    public void givenJettyHttpClient_whenEndpointIsConsumed_thenRequestAndResponseBodyShouldBeLogged() {
+        SslContextFactory.Client sslContextFactory = new SslContextFactory.Client();
+        org.eclipse.jetty.client.HttpClient httpClient = new org.eclipse.jetty.client.HttpClient(sslContextFactory) {
+            @Override
+            public Request newRequest(URI uri) {
+                Request request = super.newRequest(uri);
+                return new RequestLogEnhancer().enhance(request);
+            }
+        };
+
+        WebClient
+          .builder()
+          .clientConnector(new JettyClientHttpConnector(httpClient))
+          .build()
+          .post()
+          .uri(sampleUrl)
+          .body(BodyInserters.fromObject(post))
+          .retrieve()
+          .bodyToMono(String.class)
+          .block();
+
+        verify(jettyAppender).doAppend(argThat(argument -> (((LoggingEvent) argument).getFormattedMessage()).contains(sampleResponseBody)));
+    }
+
+    @Test
+    public void givenNettyHttpClientWithWiretap_whenEndpointIsConsumed_thenRequestAndResponseBodyShouldBeLogged() {
+
+        reactor.netty.http.client.HttpClient httpClient = HttpClient
+          .create()
+          .wiretap(true);
+        WebClient
+          .builder()
+          .clientConnector(new ReactorClientHttpConnector(httpClient))
+          .build()
+          .post()
+          .uri(sampleUrl)
+          .body(BodyInserters.fromObject(post))
+          .exchange()
+          .block();
+        verify(nettyAppender).doAppend(argThat(argument -> (((LoggingEvent) argument).getFormattedMessage()).contains("00000300")));
+    }
+
+    @Test
+    public void givenNettyHttpClientWithCustomLogger_whenEndpointIsConsumed_thenRequestAndResponseBodyShouldBeLogged() {
+
+        reactor.netty.http.client.HttpClient httpClient = HttpClient
+          .create()
+          .tcpConfiguration(tcpClient -> tcpClient.bootstrap(b -> BootstrapHandlers.updateLogSupport(b, new CustomLogger(HttpClient.class))));
+        WebClient
+          .builder()
+          .clientConnector(new ReactorClientHttpConnector(httpClient))
+          .build()
+          .post()
+          .uri(sampleUrl)
+          .body(BodyInserters.fromObject(post))
+          .exchange()
+          .block();
+        verify(nettyAppender).doAppend(argThat(argument -> (((LoggingEvent) argument).getFormattedMessage()).contains(sampleResponseBody)));
+    }
+
+    @Test
+    public void givenDefaultHttpClientWithString_whenEndpointIsConsumed_thenRequestAndResponseLogged() {
+        WebClient
+          .builder()
+          .filters(exchangeFilterFunctions -> {
+              exchangeFilterFunctions.addAll(LogFilters.prepareFilters());
+          })
+          .build()
+          .post()
+          .uri(sampleUrl)
+          .body(BodyInserters.fromObject(post))
+          .exchange()
+          .block();
+
+        verify(mockAppender).doAppend(argThat(argument -> (((LoggingEvent) argument).getFormattedMessage()).contains("domain=.typicode.com;")));
+    }
+
+
+}

spring-5-reactive-client/src/test/java/com/baeldung/reactive/logging/filters/LogFilters.java

@@ -0,0 +1,33 @@
+package com.baeldung.reactive.logging.filters;
+
+import java.util.Arrays;
+import java.util.List;
+import lombok.extern.slf4j.Slf4j;
+import org.springframework.web.reactive.function.client.ExchangeFilterFunction;
+import reactor.core.publisher.Mono;
+
+@Slf4j
+public class LogFilters {
+    public static List<ExchangeFilterFunction> prepareFilters(){
+        return Arrays.asList(ExchangeFilterFunction.ofRequestProcessor(clientRequest -> {
+            if ( log.isDebugEnabled()) {
+                StringBuilder sb = new StringBuilder("Request: \n").append(clientRequest.method()).append(" ").append(clientRequest.url());
+                clientRequest
+                  .headers()
+                  .forEach((name, values) -> values.forEach(value -> sb.append("\n").append(name).append(":").append(value)));
+                log.debug(sb.toString());
+            }
+            return Mono.just(clientRequest);
+        }), ExchangeFilterFunction.ofResponseProcessor(clientResponse -> {
+            if ( log.isDebugEnabled()) {
+                StringBuilder sb = new StringBuilder("Response: \n").append("Status: ").append(clientResponse.rawStatusCode());
+                clientResponse
+                  .headers()
+                  .asHttpHeaders()
+                  .forEach((key, value1) -> value1.forEach(value -> sb.append("\n").append(key).append(":").append(value)));
+                log.debug(sb.toString());
+            }
+            return Mono.just(clientResponse);
+        }));
+    }
+}

spring-5-reactive-client/src/test/java/com/baeldung/reactive/logging/jetty/RequestLogEnhancer.java

@@ -0,0 +1,88 @@
+package com.baeldung.reactive.logging.jetty;
+
+import java.nio.ByteBuffer;
+import java.nio.charset.Charset;
+import java.nio.charset.StandardCharsets;
+import java.util.Locale;
+import lombok.extern.slf4j.Slf4j;
+import org.eclipse.jetty.client.api.Request;
+import org.eclipse.jetty.http.HttpField;
+import org.eclipse.jetty.http.HttpFields;
+import org.eclipse.jetty.http.HttpHeader;
+
+@Slf4j
+public class RequestLogEnhancer {
+
+    public Request enhance(Request request) {
+        StringBuilder group = new StringBuilder();
+        request.onRequestBegin(theRequest -> group
+          .append("Request ")
+          .append(theRequest.getMethod())
+          .append(" ")
+          .append(theRequest.getURI())
+          .append("\n"));
+        request.onRequestHeaders(theRequest -> {
+            for (HttpField header : theRequest.getHeaders())
+                group
+                  .append(header)
+                  .append("\n");
+        });
+        request.onRequestContent((theRequest, content) -> group.append(toString(content, getCharset(theRequest.getHeaders()))));
+        request.onRequestSuccess(theRequest -> {
+            log.debug(group.toString());
+            group.delete(0, group.length());
+        });
+        group.append("\n");
+        request.onResponseBegin(theResponse -> {
+            group
+              .append("Response \n ")
+              .append(theResponse.getVersion())
+              .append(" ")
+              .append(theResponse.getStatus());
+            if (theResponse.getReason() != null) group
+              .append(" ")
+              .append(theResponse.getReason());
+            group.append("\n");
+        });
+        request.onResponseHeaders(theResponse -> {
+            for (HttpField header : theResponse.getHeaders())
+                group
+                  .append(header)
+                  .append("\n");
+        });
+        request.onResponseContent((theResponse, content) -> group.append(toString(content, getCharset(theResponse.getHeaders()))));
+        request.onResponseSuccess(theResponse -> {
+            log.debug(group.toString());
+        });
+        return request;
+    }
+
+
+    private String toString(ByteBuffer buffer, Charset charset)
+    {
+        byte[] bytes;
+        if (buffer.hasArray()) {
+            bytes = new byte[buffer.capacity()];
+            System.arraycopy(buffer.array(), 0, bytes, 0, buffer.capacity() );
+        }
+        else
+        {
+            bytes = new byte[buffer.remaining()];
+            buffer.get(bytes, 0, bytes.length);
+        }
+        return new String(bytes, charset);
+    }
+
+
+    private Charset getCharset(HttpFields headers) {
+        String contentType = headers.get(HttpHeader.CONTENT_TYPE);
+        if (contentType == null) return StandardCharsets.UTF_8;
+        String[] tokens = contentType
+          .toLowerCase(Locale.US)
+          .split("charset=");
+        if (tokens.length != 2) return StandardCharsets.UTF_8;
+        String encoding = tokens[1].replaceAll("[;\"]", "");
+        return Charset.forName(encoding);
+    }
+}
+

spring-5-reactive-client/src/test/java/com/baeldung/reactive/logging/netty/CustomLogger.java

@@ -0,0 +1,37 @@
+package com.baeldung.reactive.logging.netty;
+
+import io.netty.buffer.ByteBuf;
+import io.netty.channel.ChannelHandlerContext;
+import io.netty.handler.logging.LoggingHandler;
+import io.netty.util.internal.PlatformDependent;
+import java.nio.charset.Charset;
+
+public class CustomLogger extends LoggingHandler {
+    public CustomLogger(Class<?> clazz) {
+        super(clazz);
+    }
+
+    @Override
+    protected String format(ChannelHandlerContext ctx, String eventName, Object arg) {
+        if (arg instanceof ByteBuf) {
+            ByteBuf msg = (ByteBuf) arg;
+            return decodeString(msg, msg.readerIndex(), msg.readableBytes(), Charset.defaultCharset());
+        }
+        return "";
+    }
+
+    private String decodeString(ByteBuf src, int readerIndex, int len, Charset charset) {
+        if (len == 0) return "";
+        byte[] array;
+        int offset;
+        if (src.hasArray()) {
+            array = src.array();
+            offset = src.arrayOffset() + readerIndex;
+        } else {
+            array = PlatformDependent.allocateUninitializedArray(Math.max(len, 1024));
+            offset = 0;
+            src.getBytes(readerIndex, array, 0, len);
+        }
+        return new String(array, offset, len, charset);
+    }
+}

spring-5-reactive-client/src/test/resources/logback-test.xml

@@ -6,11 +6,15 @@
             <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
         </layout>
     </appender>
-    
+
     <logger name="org.springframework" level="INFO" />
 
+    <logger name="com.baeldung.reactive.logging.jetty" level="DEBUG" />
+    <logger name="reactor.netty.http.client.HttpClient" level="DEBUG" />
+    <logger name="com.baeldung.reactive.logging" level="DEBUG" />
+
     <root level="INFO">
         <appender-ref ref="stdout" />
     </root>
-    
+
 </configuration>