SpringのWebClientのリトライ機能を試してみました。

試してみましたブログです。

背景

仕事で数秒おきにWebのリクエストをリトライするような機能が必要になり、数秒待つのにスレッドを消費させたくないのでどうしたもんかなと思ってたところ、SpringのWebClientが使っているReactorの機能にリトライがあり、これを使えばスレッドを消費しなくて済みそうなので *1 どういう風に動くのか検証してみました。

検証したサンプルのソースコードはGitHubに置いています。 github.com

その1 : 単純なリトライ

まずはMono#retryWhenを使ったシンプルなリトライを試してみます。

呼び出し側のコード

@GetMapping("/test1")
Mono<ResponseEntity<String>> test1() {
    return webClient.post()
            .uri("http://localhost:8080/error")
            .retrieve()
            .toEntity(String.class)
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)));
}

retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)) で1秒おきに3回リトライしています。

呼び出される側（エラーを起こす側）のコード

@PostMapping("/error")
ResponseEntity<String> error() {
    System.out.println("/error " + LocalDateTime.now());
    return ResponseEntity.status(HttpStatus.SERVICE_UNAVAILABLE).build();
}

現在時刻を表示した後、固定で503エラーを返しています。

実行結果

curlコマンド実行するとエラーが返ってきました。

% curl localhost:8080/test1
{"timestamp":"2022-12-21T11:55:49.153+00:00","path":"/test1","status":500,"error":"Internal Server Error","requestId":"9fdfe798-13"}

サーバ側のコンソールには次のように出力されています。

/error 2022-12-21T21:00:15.500676
/error 2022-12-21T21:00:16.538485
/error 2022-12-21T21:00:17.543379
/error 2022-12-21T21:00:18.549469
2022-12-21T21:00:18.565+09:00 ERROR 7455 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [53110703-1]  500 Server Error for HTTP GET "/test1"

reactor.core.Exceptions$RetryExhaustedException: Retries exhausted: 3/3
    at reactor.core.Exceptions.retryExhausted(Exceptions.java:306) ~[reactor-core-3.5.0.jar:3.5.0]
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    *__checkpoint ⇢ Handler ninja.cero.example.webflux.retry.TestController#test1() [DispatcherHandler]
    *__checkpoint ⇢ HTTP GET "/test1" [ExceptionHandlingWebHandler]
Original Stack Trace:
        at reactor.core.Exceptions.retryExhausted(Exceptions.java:306) ~[reactor-core-3.5.0.jar:3.5.0]
        at reactor.util.retry.RetryBackoffSpec.lambda$static$0(RetryBackoffSpec.java:68) ~[reactor-core-3.5.0.jar:3.5.0]
        at reactor.util.retry.RetryBackoffSpec.lambda$null$4(RetryBackoffSpec.java:560) ~[reactor-core-3.5.0.jar:3.5.0]
(略)
Caused by: org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error
    at org.springframework.web.reactive.function.client.WebClientResponseException.create(WebClientResponseException.java:337) ~[spring-webflux-6.0.2.jar:6.0.2]
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    *__checkpoint ⇢ 503 SERVICE_UNAVAILABLE from POST http://localhost:8080/error [DefaultWebClient]
Original Stack Trace:
        at org.springframework.web.reactive.function.client.WebClientResponseException.create(WebClientResponseException.java:337) ~[spring-webflux-6.0.2.jar:6.0.2]
(略)

まず /error で始まるメッセージのタイムスタンプが1秒ちょいおきになっており、きちんと間をおいてリクエストされていることが分かります。

またそのメッセージが4回出力されており、リトライ「3」回というのは、リクエスト「4」回になっていることが分かります。リクエストが3回って言ってるのに4回リクエストすると怒る人も世の中にいるので、リトライの話をする時にはリトライ回数なのかリクエスト回数なのか厳密に確認すると良いでしょう。

そして最終的に RetryExhaustedException: Retries exhausted: 3/3 として、3回リトライしたけどダメだった的な例外が発生して、スタックトレースが表示されています。おおむね想定通りです。

その2 : 失敗した後のリトライで成功する

続いて、リトライした後に成功するパターンを試してみます。

呼び出し側のコード

@GetMapping("/test2")
Mono<ResponseEntity<String>> test2() {
    return webClient.post()
            .uri("http://localhost:8080/error_twice")
            .retrieve()
            .toEntity(String.class)
            .doOnSuccess(r -> System.out.println(Thread.currentThread() + " Success " + LocalDateTime.now() + " " + r))
            .doOnError(th -> System.out.println(Thread.currentThread() + " Error " + LocalDateTime.now() + " " + th))
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)));
}

先ほどとほとんど変わらないコードですが doOnSuccess と doOnError で、成功時・失敗時にそれぞれメッセージを出力するようにしました。

呼び出される側（エラーを起こす側）のコード

int counter = 0;

@PostMapping("/error_twice")
ResponseEntity<String> errorTwice() {
    counter++;
    System.out.println(counter + " /error_twice " + LocalDateTime.now());
    if (counter % 3 == 0) {
        return ResponseEntity.ok("OK");
    }

    return ResponseEntity.status(HttpStatus.SERVICE_UNAVAILABLE).build();
}

カウンターを作って、カウンターが3で割りきれる時だけ成功するようにしました。カウンターは最初AtomicIntegerで書いていたんですが、別にサンプルコードだしintで良いかとなってintにしました。良い子は真似しないでください。

実行結果

curlコマンド実行すると今度は正しくメッセージが返ってきました。

curl localhost:8080/test2
OK

サーバ側のコンソールには次のように出力されています。

1 /error_twice 2022-12-21T21:06:03.317283
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T21:06:03.348214 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_twice

2 /error_twice 2022-12-21T21:06:04.356433
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T21:06:04.357669 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_twice

3 /error_twice 2022-12-21T21:06:05.364996
Thread[reactor-http-nio-3,5,main] Success 2022-12-21T21:06:05.379515 <200 OK OK,OK,[Content-Type:"text/plain;charset=UTF-8", Content-Length:"2"]>

（読みやすいよう執筆時に空行を入れました）

カウンターが1と2の時はそれぞれ503が返り、3の時には200 OKを返していることが分かります。返却したメッセージも OK という文字列だったため、ちょっとメッセージ内に OK が多めに並んでいます。OK牧場。

最終的に成功しているので例外が返ることはありません。逆に言えば、途中で例外が発生したことについて何か処理を入れたいのであれば doOnError の中で処理をきちんと書くことになります。

その3 : サーバからのレスポンスが1秒以上かかる

リトライ間隔は1秒としていますが、この1秒というのはリクエスト開始したタイミングから1秒なのか、レスポンスが返ってきてからの1秒なのか、もちろん後者だとは思いますが念のために確認しておきます。

呼び出し側のコード

@GetMapping("/test3")
Mono<ResponseEntity<String>> test3() {
    return webClient.post()
            .uri("http://localhost:8080/error_twice_await")
            .retrieve()
            .toEntity(String.class)
            .doOnSuccess(r -> System.out.println(Thread.currentThread() + " Success " + LocalDateTime.now() + " " + r))
            .doOnError(th -> System.out.println(Thread.currentThread() + " Error " + LocalDateTime.now() + " " + th))
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)));
}

先ほどと呼び出しURL以外は変わっていません。

呼び出される側（エラーを起こす側）のコード

@PostMapping("/error_twice_await")
ResponseEntity<String> errorTwiceAwait() throws InterruptedException {
    Thread.sleep(2000L);

    counter++;
    System.out.println(counter + " /error_twice_await " + LocalDateTime.now());
    if (counter % 3 == 0) {
        return ResponseEntity.ok("OK");
    }

    return ResponseEntity.status(HttpStatus.SERVICE_UNAVAILABLE).build();
}

Thread.sleep(2000L) で2秒のスリープを入れています。Spring WebFlux（Netty）上でブロッキングなスリープをするという悪魔超人的な残虐行為ですが、検証なので問題ありません。良い子は真似しないでください。

実行結果

curlコマンド実行すると正しくメッセージが返ってきます。

curl localhost:8080/test3
OK

サーバ側のコンソールには次のように出力されています。

4 /error_twice_await 2022-12-21T21:21:30.103523
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T21:21:30.106357 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_twice_await

5 /error_twice_await 2022-12-21T21:21:33.110745
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T21:21:33.113291 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_twice_await

6 /error_twice_await 2022-12-21T21:21:36.119666
Thread[reactor-http-nio-3,5,main] Success 2022-12-21T21:21:36.122306 <200 OK OK,OK,[Content-Type:"text/plain;charset=UTF-8", Content-Length:"2"]>

ここで見るべきはメッセージが出力された時間で、ちょうど3秒ちょいおきに呼び出されていることが分かります。

サーバ側で2秒待ってからレスポンスを返し、そこから1秒待ってリトライしているので、合計3秒になるわけですね。これも想定通りです。問題ありません。

その4 : 最終的な失敗の時に処理を入れる

途中で失敗した場合には doOnError で処理ができると書きましたが、最終的な失敗にだけ処理を書きたい場合もあると思います。それも試してみました。

呼び出し側のコード

@GetMapping("/test4")
Mono<ResponseEntity<String>> test4() {
    return webClient.post()
            .uri("http://localhost:8080/error")
            .retrieve()
            .toEntity(String.class)
            .doOnError(th -> System.out.println(Thread.currentThread() + " Error1 " + LocalDateTime.now() + " " + th))
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)))
            .doOnError(th -> System.out.println(Thread.currentThread() + " Error2 " + LocalDateTime.now() + " " + th));
}

doOnError を retryWhen の前後で2回書いています。前のほうは Error1 という文字列、後のほうは Error2 という文字列を入れて出力しています。

とりあえず動かして結果を見てから説明しましょう。

実行結果

curlコマンド実行するとエラーが発生します。

curl localhost:8080/test4
{"timestamp":"2022-12-21T12:28:45.122+00:00","path":"/test4","status":500,"error":"Internal Server Error","requestId":"990c29b5-9"}

サーバ側のコンソールには次のように出力されています。

/error 2022-12-21T21:28:42.086369
Thread[reactor-http-nio-3,5,main] Error1 2022-12-21T21:28:42.087464 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error

/error 2022-12-21T21:28:43.094621
Thread[reactor-http-nio-3,5,main] Error1 2022-12-21T21:28:43.096406 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error

/error 2022-12-21T21:28:44.103211
Thread[reactor-http-nio-3,5,main] Error1 2022-12-21T21:28:44.104817 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error

/error 2022-12-21T21:28:45.107813
Thread[reactor-http-nio-3,5,main] Error1 2022-12-21T21:28:45.109541 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error

Thread[reactor-http-nio-3,5,main] Error2 2022-12-21T21:28:45.110772 reactor.core.Exceptions$RetryExhaustedException: Retries exhausted: 3/3
2022-12-21T21:28:45.125+09:00 ERROR 8812 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [990c29b5-9]  500 Server Error for HTTP GET "/test4"

reactor.core.Exceptions$RetryExhaustedException: Retries exhausted: 3/3
(略)

まず Error1 を含んだメッセージが WebClientResponseException$ServiceUnavailable という例外とともに4回出力されています。これがそれぞれのリクエストが失敗した際の処理です。

その後 Error2 を含んだメッセージが RetryExhaustedException とともに1回だけ出力されています。これが最終的に失敗した際の処理です。何か後処理を入れたければこの最後の doOnError に入れれば良いことが分かりました。

その5 : 最終的な失敗の時に例外をハンドリングする

最終的な失敗の時に例外を返すのではなく、任意のレスポンスを返したい場合もあると思います。そのパターンも試してみます。

呼び出し側のコード

@GetMapping("/test5")
Mono<ResponseEntity<String>> test5() {
    return webClient.post()
            .uri("http://localhost:8080/error")
            .retrieve()
            .toEntity(String.class)
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1)))
            .onErrorReturn(ResponseEntity.status(HttpStatus.SERVICE_UNAVAILABLE).body("リトライオーバー"));
}

最後の doOnError の代わりに onErrorReturn を使って503エラーのレスポンスオブジェクトを返すようにしました。これで例外をスローする代わりにオブジェクトを返すことができます。他にも発生した例外を元にして Function を書くことができる onErrorResume など、いくつかのエラーハンドリング用のメソッドが用意されています。

実行結果

curlコマンド実行するとエラーが発生します。

curl localhost:8080/test5 -i 
HTTP/1.1 503 Service Unavailable
Content-Type: text/plain;charset=UTF-8
Content-Length: 24

リトライオーバー

レスポンスのメッセージだけだとエラーだと分かりにくいので curl コマンドに -i オプションをつけて実行してステータスとヘッダを表示するようにしました。HTTPステータスが503となっており、上の onErrorReturn で作成したレスポンスオブジェクトの通りとなっていることが分かります。

サーバ側のコンソールには次のように出力されています。

/error 2022-12-21T21:45:07.584994
/error 2022-12-21T21:45:08.588875
/error 2022-12-21T21:45:09.598151
/error 2022-12-21T21:45:10.605840

例外は onErrorReturn でハンドリングされたため、スタックトレースなどは表示されていません。

その6 : 任意のHTTPステータスだけリトライする

ここまではWebClientのどのようなエラーでもリトライしていましたが、特定のエラー（503など）のみリトライしたい場合もよくあると思います。最後にそれを試してみます。

呼び出し側のコード

@GetMapping("/test6")
Mono<ResponseEntity<String>> test6() {
    return webClient.post()
            .uri("http://localhost:8080/error_503_404")
            .retrieve()
            .toEntity(String.class)
            .doOnError(th -> System.out.println(Thread.currentThread() + " Error " + LocalDateTime.now() + " " + th))
            .retryWhen(Retry.fixedDelay(3, Duration.ofSeconds(1))
                    .filter(th -> {
                        if (th instanceof WebClientResponseException ex) {
                            return ex.getStatusCode().value() == 503;
                        }
                        return false;
                    }));
}

Retry#filter メソッドを使い、リトライする条件を指定しています。filter に渡した Predicate が true を返したときはリトライして false を返した時にはリトライしないという挙動になります。ここでは発生した例外が WebClientResponseException であり、そのHTTPステータスコードが503の時だけ true を返すようにしています。

呼び出される側（エラーを起こす側）のコード

@PostMapping("/error_503_404")
ResponseEntity<String> errorTwice503() {
    counter++;
    System.out.println(counter + " /error_503_404 " + LocalDateTime.now());
    if (counter % 3 == 0) {
        return ResponseEntity.status(HttpStatus.NOT_FOUND).build();
    }

    return ResponseEntity.status(HttpStatus.SERVICE_UNAVAILABLE).build();
}

カウンターが3で割りきれる場合だけ 404 を返し、それ以外は 503 を返すという処理にしています。503 だったからリトライし続けて、成功したと思ったら 404 ってちょっと絶望しますけどね。まぁ内容は気にしないでください。

実行結果

curlコマンド実行するとエラーが発生します。

curl localhost:8080/test6
{"timestamp":"2022-12-21T13:01:31.209+00:00","path":"/test6","status":500,"error":"Internal Server Error","requestId":"9cb1d7f4-1"}

サーバ側のコンソールには次のように出力されています。

7 /error_503_404 2022-12-21T22:01:29.151704
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T22:01:29.181986 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_503_404

8 /error_503_404 2022-12-21T22:01:30.187425
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T22:01:30.189003 org.springframework.web.reactive.function.client.WebClientResponseException$ServiceUnavailable: 503 Service Unavailable from POST http://localhost:8080/error_503_404

9 /error_503_404 2022-12-21T22:01:31.196340
Thread[reactor-http-nio-3,5,main] Error 2022-12-21T22:01:31.198393 org.springframework.web.reactive.function.client.WebClientResponseException$NotFound: 404 Not Found from POST http://localhost:8080/error_503_404
2022-12-21T22:01:31.212+09:00 ERROR 12778 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [9cb1d7f4-1]  500 Server Error for HTTP GET "/test6"

org.springframework.web.reactive.function.client.WebClientResponseException$NotFound: 404 Not Found from POST http://localhost:8080/error_503_404
(略)

2回の503エラーが発生した後、3回目のリクエストで404エラーが返ってきていることが分かります。

そして3回目のリクエストではリトライをせず、そこで諦めてエラーで終了となっているため RetryExhaustedException は発生せず、代わりに最後に発生した WebClientResponseException$NotFound をスローした形となりました。

所感

全体的にナルホドナという挙動であり、違和感はありませんでした。

本当はもっと大量にリクエストを投げつけて、スレッドを消費せずにリトライ間隔を待ち受けできてるなーというのを確認したかったのですが、いったんここで力尽きたのでした。どうせだいたい動くっしょ。

そんなわけで、WebClientのリトライ機能について試してみたことは以上です。

いかがでしたか？

*1:スレッドを消費しないことは未検証です