--- title: SpringのWebClientのHTTP Request/Responseログを出力するメモ tags: ["Reactor", "Reactor Netty", "Netty", "Spring 5", "Spring WebFlux", "Java"] categories: ["Programming", "Java", "org", "springframework", "web", "reactive"] date: 2021-01-02T17:08:03Z updated: 2021-01-03T17:24:26Z --- SpringのHTTPクライアントの`WebClient`でHTTP Request/Responseログを出力する方法のメモ。 * Spring Boot 2.4.1 * Spring Framework 5.3.2 で検証 **目次** ### ビルトインのログ出力機能 Spring Bootではビルトインで`WebClient`のログ出力機能が用意されています。`application.properties`に次の設定をします。 ```properties logging.level.org.springframework.web.reactive.function.client.ExchangeFunctions=TRACE spring.codec.log-request-details=true ``` 次の`CommandLineRunner`を実行すると、 ```java package com.example.demowebclient; import java.util.Map; import com.fasterxml.jackson.databind.JsonNode; import org.springframework.boot.CommandLineRunner; import org.springframework.http.MediaType; import org.springframework.stereotype.Component; import org.springframework.web.reactive.function.client.WebClient; @Component public class CLR implements CommandLineRunner { private final WebClient webClient; public CLR(WebClient.Builder builder) { this.webClient = builder.build(); } @Override public void run(String... args) throws Exception { this.webClient.post() .uri("https://jsonplaceholder.typicode.com/posts") .contentType(MediaType.APPLICATION_JSON) .bodyValue(Map.of("title", "Hello", "body", "Hello World!", "userId", 100)) .header("X-Foo", "bar") .retrieve() .bodyToFlux(JsonNode.class) .subscribe(); } } ``` 次のようなログが出力されます。 ``` 2021-01-03 01:55:29.169 TRACE 61822 --- [ main] o.s.w.r.f.client.ExchangeFunctions : [60859f5a] HTTP POST https://jsonplaceholder.typicode.com/posts, headers=[Content-Type:"application/json", X-Foo:"bar"] 2021-01-03 01:55:29.896 TRACE 61822 --- [ctor-http-nio-3] o.s.w.r.f.client.ExchangeFunctions : [60859f5a] Response 201 CREATED, headers=[Date:"Sat, 02 Jan 2021 16:55:29 GMT", Content-Type:"application/json; charset=utf-8", Content-Length:"78", Connection:"keep-alive", Set-Cookie:"__cfduid=d7a94ae7ef5a10409c7d3d3bffce8579f1609606529; expires=Mon, 01-Feb-21 16:55:29 GMT; path=/; domain=.typicode.com; HttpOnly; SameSite=Lax", X-Powered-By:"Express", X-Ratelimit-Limit:"1000", X-Ratelimit-Remaining:"997", X-Ratelimit-Reset:"1609606558", Vary:"Origin, X-HTTP-Method-Override, Accept-Encoding", Access-Control-Allow-Credentials:"true", Cache-Control:"no-cache", Pragma:"no-cache", Expires:"-1", Access-Control-Expose-Headers:"Location", Location:"http://jsonplaceholder.typicode.com/posts/101", X-Content-Type-Options:"nosniff", Etag:"W/"4e-NuP9BtNO7iOKJDctnDWGVR38ZkU"", Via:"1.1 vegur", CF-Cache-Status:"DYNAMIC", cf-request-id:"07659f99d100000aacf7878000000001", Expect-CT:"max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"", Report-To:"{"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=%2FSnHUi5Q3P5LFtktS1ycMXx6X5gz2%2BF4funFUjUDjxqzxfqbhWbkTbCR8kBi8qwAf7jD6iy7PL5Ip8t%2FmWX3HNrXmHD9O8SWfH%2Fqegb%2BrN7QYIyJWD2pwky2ik%2Fy"}],"group":"cf-nel","max_age":604800}", NEL:"{"report_to":"cf-nel","max_age":604800}", Server:"cloudflare", CF-RAY:"60b602094bf80aac-NRT"] ``` HTTPヘッダーやステータスコードが出力されます。ビルトイン機能なので、簡単に使えますが、ログが一行にまとまっていて読みづらいです。また、リクエストボディ、レスポンスボディは出力されません。 ### ExchangeFilterFunctionでログ出力機能を実装 ビルトイン機能を使わず、ログ出力を実装します。実装すべき箇所は`org.springframework.web.reactive.function.client.ExchangeFilterFunction`です。 [OkHttp](https://square.github.io/okhttp/)のようなログをイメージして、次のように実装します。 ```java package lol.maki.lab.http; import java.net.URI; import java.nio.charset.StandardCharsets; import java.util.concurrent.atomic.AtomicLong; import java.util.function.Supplier; import org.reactivestreams.Publisher; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import reactor.core.publisher.Flux; import reactor.core.publisher.Mono; import org.springframework.core.io.buffer.DataBuffer; import org.springframework.core.io.buffer.DataBufferFactory; import org.springframework.core.io.buffer.DataBufferUtils; import org.springframework.http.HttpCookie; import org.springframework.http.HttpHeaders; import org.springframework.http.HttpMethod; import org.springframework.http.client.reactive.ClientHttpRequest; import org.springframework.util.MultiValueMap; 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.ClientResponse.Headers; import org.springframework.web.reactive.function.client.ExchangeFilterFunction; import org.springframework.web.reactive.function.client.ExchangeFunction; import org.springframework.web.reactive.function.client.WebClientResponseException; public class LoggingExchangeFilterFunction implements ExchangeFilterFunction { private final Logger log = LoggerFactory.getLogger(LoggingExchangeFilterFunction.class); private final boolean includeBody; public LoggingExchangeFilterFunction(boolean includeBody) { this.includeBody = includeBody; } @Override public Mono filter(ClientRequest clientRequest, ExchangeFunction exchangeFunction) { final AtomicLong begin = new AtomicLong(); final ClientRequest request; if (log.isDebugEnabled()) { log.debug("--> {} {}", clientRequest.method(), clientRequest.url()); clientRequest.headers().forEach((k, v) -> { log.debug("{}: {}", k, String.join(",", v)); }); final BodyInserter bodyInserter = clientRequest.body(); if (this.includeBody) { request = ClientRequest.from(clientRequest) .body((outputMessage, context) -> bodyInserter.insert(new LoggingClientHttpRequest(outputMessage), context) .doOnTerminate(() -> { if (log.isDebugEnabled()) { log.debug("--> END {}", clientRequest.method()); } })) .build(); } else { request = clientRequest; if (log.isDebugEnabled()) { log.debug("--> END {}", clientRequest.method()); } } begin.set(System.currentTimeMillis()); } else { request = clientRequest; } return exchangeFunction.exchange(request) .doOnNext(clientResponse -> { if (log.isDebugEnabled()) { final long elapsed = System.currentTimeMillis() - begin.get(); log.debug("<-- {} {} ({}ms)", clientResponse.statusCode(), clientRequest.url(), elapsed); clientResponse.headers().asHttpHeaders().forEach((k, v) -> { log.debug("{}: {}", k, String.join(",", v)); }); } }) .doOnCancel(() -> { final long elapsed = System.currentTimeMillis() - begin.get(); log.debug("<-- CANCELED {} ({}ms)", clientRequest.url(), elapsed); }) .doOnError(e -> { if (log.isDebugEnabled()) { final long elapsed = System.currentTimeMillis() - begin.get(); final Object status = (e instanceof WebClientResponseException) ? ((WebClientResponseException) e).getStatusCode() : "000"; log.debug("<-- {} {} ({}ms)", status, clientRequest.url(), elapsed); } }) .flatMap(clientResponse -> { final Headers headers = clientResponse.headers(); if (!log.isDebugEnabled() || !this.includeBody || headers.contentLength().isPresent() && headers.contentLength().getAsLong() == 0L) { return Mono.just(clientResponse); } return clientResponse.bodyToMono(String.class) .doOnNext(r -> { log.debug(""); log.debug("{}", r); }) .map(body -> clientResponse.mutate().body(body).build()); }) .doOnTerminate(() -> log.debug("<-- END HTTP")); } class LoggingClientHttpRequest implements ClientHttpRequest { private final ClientHttpRequest delegate; LoggingClientHttpRequest(ClientHttpRequest delegate) { this.delegate = delegate; } @Override public HttpHeaders getHeaders() { return this.delegate.getHeaders(); } @Override public DataBufferFactory bufferFactory() { return this.delegate.bufferFactory(); } @Override public void beforeCommit(Supplier> action) { this.delegate.beforeCommit(action); } @Override public boolean isCommitted() { return this.delegate.isCommitted(); } @Override public Mono writeWith(Publisher body) { return log.isDebugEnabled() ? this.delegate.writeWith(DataBufferUtils.join(body) .doOnNext(data -> { log.debug(""); log.debug("{}", data.toString(StandardCharsets.UTF_8)); })) : this.delegate.writeWith(body); } @Override public Mono writeAndFlushWith(Publisher> body) { return log.isDebugEnabled() ? this.delegate.writeAndFlushWith(Flux.from(body) .map(b -> DataBufferUtils.join(b).doOnNext(data -> { log.debug(""); log.debug("{}", data.toString(StandardCharsets.UTF_8)); }))) : this.delegate.writeAndFlushWith(body); } @Override public Mono setComplete() { return this.delegate.setComplete(); } @Override public HttpMethod getMethod() { return this.delegate.getMethod(); } @Override public URI getURI() { return this.delegate.getURI(); } @Override public MultiValueMap getCookies() { return this.delegate.getCookies(); } @Override public T getNativeRequest() { return this.delegate.getNativeRequest(); } } } ``` この`ExchangeFilterFunction`を使用するために次のようなBean定義を行います。 ```java @Bean public WebClientCustomizer webClientCustomizer() { return builder -> builder .filter(new LoggingExchangeFilterFunction(false /* リクエストボディ・レスポンスボディを出力する場合はtrue */)); } ``` また、`application.properties`に次の設定を行います。 ```properties logging.level.lol.maki.lab.http.LoggingExchangeFilterFunction=DEBUG ``` リクエストボディ・レスポンスボディを出力しない場合は、次のような出力になります。 ``` 2021-01-03 01:56:17.216 DEBUG 61831 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : --> POST https://jsonplaceholder.typicode.com/posts 2021-01-03 01:56:17.217 DEBUG 61831 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : Content-Type: application/json 2021-01-03 01:56:17.217 DEBUG 61831 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : X-Foo: bar 2021-01-03 01:56:17.963 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : <-- 201 CREATED https://jsonplaceholder.typicode.com/posts (745ms) 2021-01-03 01:56:17.964 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Date: Sat, 02 Jan 2021 16:56:17 GMT 2021-01-03 01:56:17.964 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Content-Type: application/json; charset=utf-8 2021-01-03 01:56:17.964 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Content-Length: 78 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Connection: keep-alive 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Set-Cookie: __cfduid=d763e9bae4ed9e298827a9546097985031609606577; expires=Mon, 01-Feb-21 16:56:17 GMT; path=/; domain=.typicode.com; HttpOnly; SameSite=Lax 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Powered-By: Express 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Limit: 1000 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Remaining: 998 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Reset: 1609606618 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Vary: Origin, X-HTTP-Method-Override, Accept-Encoding 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Access-Control-Allow-Credentials: true 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Cache-Control: no-cache 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Pragma: no-cache 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Expires: -1 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Access-Control-Expose-Headers: Location 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Location: http://jsonplaceholder.typicode.com/posts/101 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Content-Type-Options: nosniff 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Etag: W/"4e-NuP9BtNO7iOKJDctnDWGVR38ZkU" 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Via: 1.1 vegur 2021-01-03 01:56:17.965 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : CF-Cache-Status: DYNAMIC 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : cf-request-id: 0765a055870000f8a7a40fc000000001 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct" 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=5p8HN1cpCcud7eDur2A1%2B0%2B0oDhD3VBsoSTOom5xvs0kPTo7xL7jkAfF2sC%2Bs7I4UDCQdKEPP9i8L2xMPtT7b5YIgDdzYwyw7nbwquU8V0hZ1T%2B5864Cs8mFZhma"}],"group":"cf-nel","max_age":604800} 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : NEL: {"report_to":"cf-nel","max_age":604800} 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Server: cloudflare 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : CF-RAY: 60b60335afe3f8a7-NRT 2021-01-03 01:56:17.966 DEBUG 61831 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : <-- END HTTP ``` リクエストボディ・レスポンスボディを出力する場合は、次のような出力になります。 ``` 2021-01-03 01:59:13.895 DEBUG 61870 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : --> POST https://jsonplaceholder.typicode.com/posts 2021-01-03 01:59:13.896 DEBUG 61870 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : Content-Type: application/json 2021-01-03 01:59:13.896 DEBUG 61870 --- [ main] l.m.l.h.LoggingExchangeFilterFunction : X-Foo: bar 2021-01-03 01:59:14.259 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : 2021-01-03 01:59:14.259 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : {"body":"Hello World!","title":"Hello","userId":100} 2021-01-03 01:59:14.264 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : --> END POST 2021-01-03 01:59:14.669 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : <-- 201 CREATED https://jsonplaceholder.typicode.com/posts (772ms) 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Date: Sat, 02 Jan 2021 16:59:14 GMT 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Content-Type: application/json; charset=utf-8 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Content-Length: 78 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Connection: keep-alive 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Set-Cookie: __cfduid=d890332771aeab1e198814a223b5686341609606754; expires=Mon, 01-Feb-21 16:59:14 GMT; path=/; domain=.typicode.com; HttpOnly; SameSite=Lax 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Powered-By: Express 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Limit: 1000 2021-01-03 01:59:14.671 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Remaining: 999 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Ratelimit-Reset: 1609606798 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Vary: Origin, X-HTTP-Method-Override, Accept-Encoding 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Access-Control-Allow-Credentials: true 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Cache-Control: no-cache 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Pragma: no-cache 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Expires: -1 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Access-Control-Expose-Headers: Location 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Location: http://jsonplaceholder.typicode.com/posts/101 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : X-Content-Type-Options: nosniff 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Etag: W/"4e-MZfXcTxvX0tqm39p2c/xvBLKthY" 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Via: 1.1 vegur 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : CF-Cache-Status: DYNAMIC 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : cf-request-id: 0765a307c700000aacff9e7000000001 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct" 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=WpnhFfkHiXW3QbXD5%2FBkXQM5sArQkynUxrZdD534S81O80ZShZ1EZiBUYMEGeGFIXtSSTM7lrL1B01G%2BLGKwjzwy7irRgI570z2WBppLDJhlSn8uo78T7C5kCiu%2B"}],"group":"cf-nel","max_age":604800} 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : NEL: {"report_to":"cf-nel","max_age":604800} 2021-01-03 01:59:14.672 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : Server: cloudflare 2021-01-03 01:59:14.673 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : CF-RAY: 60b607860a620aac-NRT 2021-01-03 01:59:14.681 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : 2021-01-03 01:59:14.681 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : { "body": "Hello World!", "title": "Hello", "userId": 100, "id": 101 } 2021-01-03 01:59:14.683 DEBUG 61870 --- [ctor-http-nio-3] l.m.l.h.LoggingExchangeFilterFunction : <-- END HTTP ``` リクエストボディ・レスポンスボディを出力する場合の実装には副作用があるため、デバッグ用途のみで利用し、プロダクションでは絶対に使わないでください。