SpringのHTTPクライアントのWebClientでHTTP Request/Responseログを出力する方法のメモ。
- Spring Boot 2.4.1
- Spring Framework 5.3.2
で検証
目次
ビルトインのログ出力機能
Spring BootではビルトインでWebClientのログ出力機能が用意されています。application.propertiesに次の設定をします。
logging.level.org.springframework.web.reactive.function.client.ExchangeFunctions=TRACE
spring.codec.log-request-details=true
次のCommandLineRunnerを実行すると、
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のようなログをイメージして、次のように実装します。
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<ClientResponse> 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<?, ? super ClientHttpRequest> 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<? extends Mono<Void>> action) {
this.delegate.beforeCommit(action);
}
@Override
public boolean isCommitted() {
return this.delegate.isCommitted();
}
@Override
public Mono<Void> writeWith(Publisher<? extends DataBuffer> 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<Void> writeAndFlushWith(Publisher<? extends Publisher<? extends DataBuffer>> 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<Void> setComplete() {
return this.delegate.setComplete();
}
@Override
public HttpMethod getMethod() {
return this.delegate.getMethod();
}
@Override
public URI getURI() {
return this.delegate.getURI();
}
@Override
public MultiValueMap<String, HttpCookie> getCookies() {
return this.delegate.getCookies();
}
@Override
public <T> T getNativeRequest() {
return this.delegate.getNativeRequest();
}
}
}
このExchangeFilterFunctionを使用するために次のようなBean定義を行います。
@Bean
public WebClientCustomizer webClientCustomizer() {
return builder -> builder
.filter(new LoggingExchangeFilterFunction(false /* リクエストボディ・レスポンスボディを出力する場合はtrue */));
}
また、application.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
リクエストボディ・レスポンスボディを出力する場合の実装には副作用があるため、デバッグ用途のみで利用し、プロダクションでは絶対に使わないでください。