Logging Spring WebClient Calls. https://www.baeldung.com/spring-log-webclient-calls

2020-10-18.netty-client.log

2020-10-18 15:26:10,784 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee] REGISTERED
2020-10-18 15:26:10,788 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee] CONNECT: httpbin.org/52.6.34.179:443
2020-10-18 15:26:11,150 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] ACTIVE
2020-10-18 15:26:11,409 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] READ COMPLETE
2020-10-18 15:26:11,482 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] READ COMPLETE
2020-10-18 15:26:11,711 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
2020-10-18 15:26:11,728 DEBUG reactor.netty.http.client.HttpClientConnect :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] Handler is being applied: {uri=https://httpbin.org/post, method=POST}
2020-10-18 15:26:11,766 DEBUG reactor.netty.http.client.HttpClient :  POST /post HTTP/1.1
user-agent: ReactorNetty/0.9.4.RELEASE
host: httpbin.org
accept: */*
Content-Type: text/plain;charset=UTF-8
content-length: 37

{"title":"Test","body":"","userId":3}
2020-10-18 15:26:11,767 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] FLUSH
2020-10-18 15:26:11,773 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] READ COMPLETE
2020-10-18 15:26:12,014 DEBUG reactor.netty.http.client.HttpClient :  HTTP/1.1 200 OK
Date: Sun, 18 Oct 2020 12:26:11 GMT
Content-Type: application/json
Content-Length: 516
Connection: keep-alive
Server: gunicorn/19.9.0
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true

{
  "args": {}, 
  "data": "{\"title\":\"Test\",\"body\":\"\",\"userId\":3}", 
  "files": {}, 
  "form": {}, 
  "headers": {
    "Accept": "*/*", 
    "Content-Length": "37", 
    "Content-Type": "text/plain;charset=UTF-8", 
    "Host": "httpbin.org", 
    "User-Agent": "ReactorNetty/0.9.4.RELEASE", 
    "X-Amzn-Trace-Id": "Root=1-5f8c3463-57089374447053665d7d887e"
  }, 
  "json": {
    "body": "", 
    "title": "Test", 
    "userId": 3
  }, 
  "origin": "195.72.142.152", 
  "url": "https://httpbin.org/post"
}

2020-10-18 15:26:12,026 DEBUG reactor.netty.http.client.HttpClientOperations :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] Received response (auto-read:false) : [Date=Sun, 18 Oct 2020 12:26:11 GMT, Content-Type=application/json, Content-Length=516, Connection=keep-alive, Server=gunicorn/19.9.0, Access-Control-Allow-Origin=*, Access-Control-Allow-Credentials=true]
2020-10-18 15:26:12,034 DEBUG reactor.netty.http.client.HttpClientOperations :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] Received last HTTP packet
2020-10-18 15:26:12,037 DEBUG reactor.netty.http.client.HttpClient :  [id: 0x779c09ee, L:/192.168.1.116:39582 - R:httpbin.org/52.6.34.179:443] READ COMPLETE

CustomLogger.java

package ru.tkachenko.logger;

import io.netty.buffer.ByteBuf;
import io.netty.channel.ChannelHandlerContext;
import io.netty.handler.logging.LoggingHandler;

import java.nio.charset.Charset;

import static io.netty.util.internal.PlatformDependent.allocateUninitializedArray;
import static java.lang.Math.max;
import static java.nio.charset.Charset.defaultCharset;

/**
 * https://www.baeldung.com/spring-log-webclient-calls
 */
public class CustomLogger extends LoggingHandler {

    public CustomLogger(Class<?> clazz) {
        super(clazz);
    }

    @Override
    protected String format(ChannelHandlerContext ctx, String event, Object arg) {
        if (arg instanceof ByteBuf) {
            ByteBuf msg = (ByteBuf) arg;
            return decode(msg, msg.readerIndex(), msg.readableBytes(), defaultCharset());
        }
        return super.format(ctx, event, arg);
    }

    private String decode(ByteBuf src, int readerIndex, int len, Charset charset) {
        if (len != 0) {
            byte[] array;
            int offset;
            if (src.hasArray()) {
                array = src.array();
                offset = src.arrayOffset() + readerIndex;
            } else {
                array = allocateUninitializedArray(max(len, 1024));
                offset = 0;
                src.getBytes(readerIndex, array, 0, len);
            }
            return new String(array, offset, len, charset);
        }
        return "";
    }

}

logback.groovy

// src/test/resources/logback.groovy

def LOG_PATH = "./logs"
def PATTERN = "%d %-5level %logger : %X %msg%n"

appender("netty-client", RollingFileAppender) {
    rollingPolicy(TimeBasedRollingPolicy) {
        fileNamePattern = "${LOG_PATH}/%d{yyyy-MM-dd}.netty-client.log"
    }
    encoder(PatternLayoutEncoder) {
        pattern = PATTERN
    }
}
logger("reactor.netty.http.client", DEBUG, ["netty-client"], false)

WebClientConfigurationTest.groovy

package ru.tkachenko.logger

import ch.qos.logback.classic.Logger
import ch.qos.logback.classic.spi.LoggingEvent
import ch.qos.logback.core.Appender
import com.fasterxml.jackson.annotation.JsonAutoDetect
import com.fasterxml.jackson.annotation.PropertyAccessor
import com.fasterxml.jackson.databind.DeserializationFeature
import com.fasterxml.jackson.databind.ObjectMapper
import lombok.AllArgsConstructor
import lombok.Data
import org.mockito.ArgumentMatchers
import org.mockito.Mockito
import org.slf4j.LoggerFactory
import org.springframework.http.client.reactive.ReactorClientHttpConnector
import org.springframework.web.reactive.function.client.WebClient
import reactor.netty.channel.BootstrapHandlers
import reactor.netty.http.client.HttpClient
import ru.tkachenko.logger.CustomLogger
import spock.lang.Specification

/**
 * @author d.tkachenko
 */
class WebClientConfigurationTest extends Specification {

    @Data
    @AllArgsConstructor
    class Post {
        String title
        String body
        int userId
    }

    Appender nettyAppender

    static final String SAMPLE_URL = "https://httpbin.org/post"

    static final String NETTY_LOGGER = "reactor.netty.http.client"

    Post post

    String responseBody

    HttpClient httpClient

    def setup() {
        post = new Post(
                title: "Test",
                body: "",
                userId: 3
        )
        responseBody = mapper().writeValueAsString(post)
        addNettyAppender()
        createHttpClient()
    }

    def addNettyAppender() {
        def netty = (Logger) LoggerFactory.getLogger(NETTY_LOGGER)
        nettyAppender = Mockito.mock(Appender)
        Mockito.when(nettyAppender.getName()).thenReturn(NETTY_LOGGER)
        netty.addAppender(nettyAppender)
    }

    def mapper() {
        def mapper = new ObjectMapper()
        mapper.configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false)
        mapper.findAndRegisterModules()
        mapper.setVisibility(PropertyAccessor.FIELD, JsonAutoDetect.Visibility.ANY)
        mapper
    }

    def createHttpClient() {
        httpClient = HttpClient
                .create()
                .tcpConfiguration {
                    tc ->
                        tc.bootstrap {
                            b -> BootstrapHandlers.updateLogSupport(b, new CustomLogger(HttpClient))
                        }
                }
    }

    def makePost() {
        WebClient.builder()
                .clientConnector(new ReactorClientHttpConnector(httpClient))
                .build()
                .post()
                .uri(SAMPLE_URL)
                .bodyValue(responseBody)
                .exchange()
                .block()
    }


    def "test netty webClient logger"() {
        expect:
        makePost()

        Mockito.verify(nettyAppender).doAppend(ArgumentMatchers.argThat {
            ((LoggingEvent) it).getFormattedMessage().contains(responseBody)
        })
    }

}