Spring+Resilience4jを触ってみる

Java Advent Calendar 2021の21日目になります。

今回の環境

• Java17
• SpringBoot2.6.1
• resilience4j-spring-boot2 1.7.1
• Gradle

事前準備

Resilience4jをSpringBootから使うための事前準備になります。

以下のライブラリを依存関係に追加します。

• spring-boot-starter-actuator
• spring-boot-starter-aop
• resilience4j-spring-boot2

build.gradle

dependencies {
  implementation 'org.springframework.boot:spring-boot-starter-web'
  implementation 'org.springframework.boot:spring-boot-starter-actuator'
  implementation 'org.springframework.boot:spring-boot-starter-aop'
  implementation 'io.github.resilience4j:resilience4j-spring-boot2:1.7.1'
}

以下application.ymlで共通で利用する部分を作成しておきます。

application.yml

server:
  application.name: resilience4j-client
  port : 8080

management.endpoints.web.exposure.include: '*'
management.endpoint.health.show-details: always

management.health.diskspace.enabled: false
management.health.circuitbreakers.enabled: true
management.health.ratelimiters.enabled: false

info:
  name: ${spring.application.name}
  description: resilience4j demo
  environment: ${spring.profiles.active}
  version: 0.0.1

management.metrics.tags.application: ${spring.application.name}
management.metrics.distribution.percentiles-histogram.http.server.requests: true
management.metrics.distribution.percentiles-histogram.resilience4j.circuitbreaker.calls: true

接続先システムのコード

この先Resilience4jを試すために接続先のシステムを別で用意しました。
参考としてコードを記載しておきます。

この接続先システムは8081ポートで受けるように設定しています。

HelloController.java

@RestController
@RequestMapping("/")
public class HelloController {
  @GetMapping("hello")
  public String hello() {
    return "Server Hello!";
  }

  @GetMapping("failure")
  public String failure() {
    throw new RuntimeException("error");
  }

  @GetMapping("delay/{second}")
  public String delay(@PathVariable("second") Integer second) {
    try {
      Thread.sleep(second * 1_000);
    } catch (InterruptedException e) {
    }
    return "delay!";
  }
}

CircuitBreaker

CircuitBreakerは接続先のシステムがダウン状態などで接続エラーが多発する際に、一定期間接続をさせずにそのままエラーを返すような仕組みを提供します。
接続先システムの状態をステータス管理しており、通常時はCLOSE, 接続エラーが一定割合を超えて発生するとOPEN, OPENから一定期間経つと接続先システムにつながるかを確かめるためのステータスHALF_OPEN状態になります。HALF_OPEN状態の時に一定割合を超えたエラーが継続する場合はOPENに、改善された場合はCLOSE状態に戻ります。

http://resilience4j.github.io/resilience4j/より引用

コード

まずapplication.ymlに

application.yml

resilience4j.circuitbreaker:
  instances:
    backendA: # 設定したい接続先システムを指定
      # ヘルスチェックエンドでサーキットブレーカーのステータスが確認可能になる
      registerHealthIndicator: true
      # slidingWindowTypeをカウントベースにする
      slidingWindowType: COUNT_BASED
      # ここで指定した数のコール数を保持してエラーレートの計算に利用する
      slidingWindowSize: 3
      # エラーレートを計算するのに必要な最小のコール数
      minimumNumberOfCalls: 1
      # HALF_OPENの時に許可される呼び出しの数
      permittedNumberOfCallsInHalfOpenState: 3 
      # trueだと自動でHALF_OPENに移行する
      automaticTransitionFromOpenToHalfOpenEnabled: true
      # OPENからHALF_OPENに移行する前に待機する時間
      waitDurationInOpenState: 10s
      # 失敗率の閾値。この数値を超えて失敗しているとOPENに移行する
      failureRateThreshold: 50
      # ここで指定したExceptionが発生すると失敗としてカウントする
      recordExceptions:
        - org.springframework.web.client.HttpServerErrorException

コントローラを用意します。
/circuitbreaker/success をリクエストした場合は成功、/circuitbreaker/failure をリクエストした場合は失敗させるようにします。

CircuitBreakerController.java

@Service
public class CircuitBreakerService {
  private BackendARepository backendARepository;
  private Logger logger;

  public CircuitBreakerService(BackendARepository backendARepository, Logger logger) {
    this.backendARepository = backendARepository;
    this.logger = logger;
  }

  @CircuitBreaker(name = "backendA")
  public String success() {
    logger.info("CircuitBreaker success method start");
    return backendARepository.hello();
  }

  @CircuitBreaker(name = "backendA")
  public String failure() {
    logger.info("CircuitBreaker failure method start");
    return backendARepository.failure();
  }
}

続いてサービスを書きます。
ここがサーキットブレーカーの設定を行う部分です。
CircuitBreaker アノテーションにapplication.ymlで設定した接続先システムの名称を指定します。

CircuitBreakerService.java

@Service
public class CircuitBreakerService {
  private BackendARepository backendARepository;

  public CircuitBreakerService(BackendARepository backendARepository) {
    this.backendARepository = backendARepository;
  }

  @CircuitBreaker(name = "backendA")
  public String success() {
    return backendARepository.hello();
  }

  @CircuitBreaker(name = "backendA")
  public String failure() {
    return backendARepository.failure();
  }
}

最後に実際の接続処理を作成します。
ここの処理はサーキットブレーカー以外の場所でも使いまわします。

BackendARepository.java

@Component
public class BackendARepository {
  private RestTemplate restTemplate;

  public BackendARepository(RestTemplate restTemplate) {
    this.restTemplate = restTemplate;
  }

  public String hello() {
    return restTemplate.getForObject("http://localhost:8081/hello", String.class);
  }

  public String failure() {
    return restTemplate.getForObject("http://localhost:8081/failure", String.class);
  }

  public String delay(int delaySecond) {
    return restTemplate.getForObject("http://localhost:8081/delay" + delaySecond, String.class);
  }
}

テストする

まず成功パターンを試して、その後2回失敗させます。その後続けて成功パターンを試します。
すると1回目のsuccess呼び出しでは成功しますが、その後の3回は全て失敗します。

curlテスト

$ curl localhost:8080/circuitbreaker/success
Server Hello!
$ curl localhost:8080/circuitbreaker/failure
{"timestamp":"2021-12-19T14:48:24.216+00:00","status":500,"error":"Internal Server Error","path":"/circuitbreaker/failure"}
$ curl localhost:8080/circuitbreaker/failure
{"timestamp":"2021-12-19T14:48:25.893+00:00","status":500,"error":"Internal Server Error","path":"/circuitbreaker/failure"}
 curl localhost:8080/circuitbreaker/success
{"timestamp":"2021-12-19T14:48:27.580+00:00","status":500,"error":"Internal Server Error","path":"/circuitbreaker/success"}

続けてログを確認します。
最初のsuccess呼び出しではエラーは発生せずCircuitBreaker success method startのログが出力されています。
続いてのfailure呼び出しではエラーは発生しますがCircuitBreaker failure method startのログが出力されているため呼び出されていることがわかります。
その後のsuccess, failure呼び出しではどちらもmethod startのログは出力せずにCallNotPermittedExceptionのエラーが出ていることから、サーキットブレーカーが発動して呼び出しを止めている状態となりました。

ログ

2021-12-19 23:48:22.583  INFO 5112 --- [nio-8080-exec-1] c.e.r.service.CircuitBreakerService      : CircuitBreaker success method start
2021-12-19 23:48:24.188  INFO 5112 --- [nio-8080-exec-2] c.e.r.service.CircuitBreakerService      : CircuitBreaker failure method start
2021-12-19 23:48:24.208 ERROR 5112 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2021-12-19T14:48:24.195+00:00","status":500,"error":"Internal Server Error","path":"/failure"}"] with root cause

-- HttpServerErrorExceptionのスタックトレースが出力(省略)

2021-12-19 23:48:25.891 ERROR 5112 --- [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is io.github.resilience4j.circuitbreaker.CallNotPermittedException: CircuitBreaker 'backendA' is OPEN and does not permit further calls] with root cause

-- CallNotPermittedExceptionのスタックトレースが出力(省略)

2021-12-19 23:48:27.579 ERROR 5112 --- [nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is io.github.resilience4j.circuitbreaker.CallNotPermittedException: CircuitBreaker 'backendA' is OPEN and does not permit further calls] with root cause

-- CallNotPermittedExceptionのスタックトレースが出力(省略)

この時のヘルスチェックの状態を確認してみると、circuitBreakersのbackendAのstatusがCIRCUIT_OPENになっていることからもサーキットブレーカーが発動したことがわかります。

ヘルスチェック

$ curl localhost:8080/actuator/health | jq
{
  "status": "UP",
  "components": {
    "circuitBreakers": {
      "status": "UNKNOWN",
      "details": {
        "backendA": {
          "status": "CIRCUIT_OPEN",
          "details": {
            "failureRate": "100.0%",
            "failureRateThreshold": "50.0%",
            "slowCallRate": "0.0%",
            "slowCallRateThreshold": "100.0%",
            "bufferedCalls": 1,
            "slowCalls": 0,
            "slowFailedCalls": 0,
            "failedCalls": 1,
            "notPermittedCalls": 0,
            "state": "OPEN"
          }
        }
      }
    },
    "ping": {
      "status": "UP"
    }
  }
}

この状態で一定期間経ってから再度ヘルスチェックを確認すると、CIRCUIT_HALF_OPENになりました。

$ curl localhost:8080/actuator/health | jq
{
  "status": "UP",
  "components": {
    "circuitBreakers": {
      "status": "UNKNOWN",
      "details": {
        "backendA": {
          "status": "CIRCUIT_HALF_OPEN",
          "details": {
            "failureRate": "-1.0%",
            "failureRateThreshold": "50.0%",
            "slowCallRate": "-1.0%",
            "slowCallRateThreshold": "100.0%",
            "bufferedCalls": 0,
            "slowCalls": 0,
            "slowFailedCalls": 0,
            "failedCalls": 0,
            "notPermittedCalls": 0,
            "state": "HALF_OPEN"
          }
        }
      }
    },
    "ping": {
      "status": "UP"
    }
  }
}

この状態でsuccessを呼び出すと無事レスポンスが返ってきて、ログもCircuitBreaker success method start が返却されました。

curl

$ curl localhost:8080/circuitbreaker/success
Server Hello!

ログ

2021-12-19 23:59:30.796  INFO 5112 --- [io-8080-exec-10] c.e.r.service.CircuitBreakerService      : CircuitBreaker success method start

Bulkhead

バルクヘッドは同時に実行可能を制限する機能です。
試してみます。

コード

application.ymlです。
maxConcurrentCallsに同時実行可能な数を指定します。

application.yml

resilience4j.bulkhead:
  instances:
    backendA:
      maxConcurrentCalls: 1

コントローラです。

BulkheadController.java

@RestController
@RequestMapping("/bulkhead")
public class BulkheadController {
  private BulkheadService bulkheadService;

  public BulkheadController(BulkheadService bulkheadService) {
    this.bulkheadService = bulkheadService;
  }

  @GetMapping
  public String index() {
    return bulkheadService.delay();
  }
}

最後にサービスです。
今回はdelayエンドポイントを呼び出しています。
レスポンスが返却されるまでに5秒待ち状態を作成しました。

BulkheadService.java

@Service
public class BulkheadService {
  private BackendARepository backendARepository;
  private Logger logger;

  public BulkheadService(BackendARepository backendARepository, Logger logger) {
    this.backendARepository = backendARepository;
    this.logger = logger;
  }

  @Bulkhead(name = "backendA")
  public String delay() {
    logger.info("delay method start");
    return backendARepository.delay(5);
  }
}

テストする

続けて2回呼び出すテストを行います。

1つ目のターミナル

$ curl localhost:8080/bulkhead
delay!

2つ目のターミナル

$ curl localhost:8080/bulkhead
{"timestamp":"2021-12-20T04:40:05.714+00:00","status":500,"error":"Internal Server Error","path":"/bulkhead"}

同時実行可能数を1に設定したので、2つ目のcurlが失敗していることがわかります。

アプリケーションのログも確認してみます。

ログ

2021-12-20 13:40:04.469  INFO 2517 --- [nio-8080-exec-1] c.e.r.service.BulkheadService            : delay method start
2021-12-20 13:40:05.704 ERROR 2517 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is io.github.resilience4j.bulkhead.BulkheadFullException: Bulkhead 'backendA' is full and does not permit further calls] with root cause

-- BulkheadFullExceptionのスタックトレースが出力(省略)

このような形で同時実行数を制限することができました。

Retry

続いてRetryになります。
こちらは実行に失敗した際に再度実行する設定を行います。

コード

application.ymlの設定です。
maxAttemptsにRetryする回数、waitDurationに失敗してからretryするまで待つ時間を設定します。

application.yml

resilience4j.retry:
  instances:
    backendA:
      maxAttempts: 2 # 最大試行回数
      waitDuration: 2s # 再試行する前に待つ時間
      retryExceptions:
        - org.springframework.web.client.HttpServerErrorException

コントローラです。

RetryController.java

@RestController
@RequestMapping("/retry")
public class RetryController {
  private RetryService retryService;

  public RetryController(RetryService retryService) {
    this.retryService = retryService;
  }

  @GetMapping
  public String index() {
    return retryService.retry();
  }
}

サービスになります。

RetryController.java

@Service
public class RetryService {
  private BackendARepository backendARepository;
  private Logger logger;

  public RetryService(BackendARepository backendARepository, Logger logger) {
    this.backendARepository = backendARepository;
    this.logger = logger;
  }

  @Retry(name = "backendA")
  public String retry() {
    logger.info("retry method start");
    return backendARepository.failure();
  }
}

テスト

ではcurlしてみます。

$ curl localhost:8080/retry
{"timestamp":"2021-12-20T04:44:33.729+00:00","status":500,"error":"Internal Server Error","path":"/retry"}

レスポンスの内容からはわからないのでログを見てみます。
するとretry method startが2回出力していることから2回処理が実行されたことがわかると思います。

アプリケーションログ

2021-12-20 13:44:31.631  INFO 2517 --- [nio-8080-exec-3] c.e.r.service.RetryService               : retry method start
2021-12-20 13:44:33.715  INFO 2517 --- [nio-8080-exec-3] c.e.r.service.RetryService               : retry method start
2021-12-20 13:44:33.727 ERROR 2517 --- [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2021-12-20T04:44:33.721+00:00","status":500,"error":"Internal Server Error","path":"/failure"}"] with root cause

-- HttpServerErrorException$InternalServerErrorのスタックトレースが出力(省略)

RateLimiter

続いてはRateLimiterです。
こちらは一定期間に実行可能な回数が指定されます。
その回数を超えた場合には、指定した時間待ちが発生し、待ちの後に受け入れ可能数に空きがあれば処理を行う、ない場合はエラーを返すものになります。

コード

application.ymlです。

application.yml

resilience4j.ratelimiter:
  instances:
    backendA:
      limitForPeriod: 1 # 指定した期間の間に呼び出し可能な回数
      limitRefreshPeriod: 10s # 計測する期間
      timeoutDuration: 5s # スレッドが待機するデフォルトの時間
      registerHealthIndicator: true
      eventConsumerBufferSize: 100

コントローラです。

RateLimiterController.java

@RestController
@RequestMapping("/rateLimiter")
public class RateLimiterController {
  private RateLimiterService rateLimiterService;

  public RateLimiterController(RateLimiterService rateLimiterService) {
    this.rateLimiterService = rateLimiterService;
  }

  @GetMapping
  public String index() {
    return rateLimiterService.rateLimit();
  }
}

最後にサービスです。

RateLimiterService.java

@Service
public class RateLimiterService {
  private BackendARepository backendARepository;
  private Logger logger;

  public RateLimiterService(BackendARepository backendARepository, Logger logger) {
    this.backendARepository = backendARepository;
    this.logger = logger;
  }

  @RateLimiter(name = "backendA")
  public String rateLimit() {
    logger.info("rateLimit method start");
    return backendARepository.hello();
  }
}

テスト

ではテストしてみます。
すると1回目の呼び出しは成功しましたが、2回目の呼び出しの際には何秒かたってからエラーが返却されました。
続けて再度呼び出すと少しだけ待ってからレスポンスが正常に返りました。

$ curl localhost:8080/rateLimiter
Server Hello!
$ $ curl localhost:8080/rateLimiter
{"timestamp":"2021-12-20T04:52:50.536+00:00","status":500,"error":"Internal Server Error","path":"/rateLimiter"}
$ curl localhost:8080/rateLimiter
Server Hello!

アプリケーションログです。
2回rateLimit method startが呼び出されていて、間の1回は処理を実行せずにRequestNotPermittedのエラーが発生しています。

ログ

2021-12-20 13:52:35.147  INFO 2831 --- [nio-8080-exec-1] c.e.r.service.RateLimiterService         : rateLimit method start
2021-12-20 13:52:40.842 ERROR 2831 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is io.github.resilience4j.ratelimiter.RequestNotPermitted: RateLimiter 'backendA' does not permit further calls] with root cause

-- RequestNotPermittedのスタックトレースが出力(省略)

2021-12-20 13:52:43.785  INFO 2831 --- [nio-8080-exec-3] c.e.r.service.RateLimiterService         : rateLimit method start

TimeLimiter

最後TimeLimiterです。

こちらはメソッドに対してタイムアウトを設定することができます。

コード

application.ymlです。

application.yml

resilience4j.timelimiter:
  instances:
    backendA:
      timeoutDuration: 4s # タイムアウトする時間の設定
      cancelRunningFuture: false # タイムアウト時に処理をキャンセルするか

コントローラです。
TimeLimiter はCompletableFutureで受け取る必要があるため、コントローラの戻りもCompletableFutureにしています。

TimeLimiterController.java

@RestController
@RequestMapping("/timeLimiter")
public class TimeLimiterController {
  private TimeLimiterService timeLimiterService;

  public TimeLimiterController(TimeLimiterService timeLimiterService) {
    this.timeLimiterService = timeLimiterService;
  }

  @GetMapping("success")
  public CompletableFuture<String> success() {
    return timeLimiterService.success();
  }

  @GetMapping("timeout")
  public CompletableFuture<String> timeout() {
    return timeLimiterService.timeout();
  }
}

サービスになります。
successメソッドはタイムアウトにならない3秒、timeoutメソッドはタイムアウトになる5秒を設定しています。

TimeLimiterService.java

@Component
public class TimeLimiterService {
  private BackendARepository backendARepository;
  private Logger logger;

  public TimeLimiterService(BackendARepository backendARepository, Logger logger) {
    this.backendARepository = backendARepository;
    this.logger = logger;
  }

  @TimeLimiter(name = "backendA")
  public CompletableFuture<String> success() {
    logger.info("TimeLimiter success method start");
    return CompletableFuture.supplyAsync(() -> backendARepository.delay(3));
  }

  @TimeLimiter(name = "backendA")
  public CompletableFuture<String> timeout() {
    logger.info("TimeLimiter timeout method start");
    return CompletableFuture.supplyAsync(() -> backendARepository.delay(5));
  }
}

テスト

curl

$ curl localhost:8080/timeLimiter/success
delay!
$ curl localhost:8080/timeLimiter/timeout
{"timestamp":"2021-12-20T05:33:41.863+00:00","status":500,"error":"Internal Server Error","path":"/timeLimiter/timeout"}

ログ

2021-12-20 14:40:42.202  INFO 3551 --- [nio-8080-exec-5] c.e.r.service.TimeLimiterService         : TimeLimiter success method start
2021-12-20 14:40:47.465  INFO 3551 --- [nio-8080-exec-7] c.e.r.service.TimeLimiterService         : TimeLimiter timeout method start
2021-12-20 14:40:51.470 ERROR 3551 --- [nio-8080-exec-8] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] threw exception

-- TimeoutExceptionのスタックトレースが出力(省略)

参考

Resilience4j Guide
GitHub resilience4j-spring-boot2-demo