Spring BootのGraceful Shutdownを試す

$ java --version
openjdk 11.0.11 2021-04-20
OpenJDK Runtime Environment (build 11.0.11+9-Ubuntu-0ubuntu2.20.04)
OpenJDK 64-Bit Server VM (build 11.0.11+9-Ubuntu-0ubuntu2.20.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.8.3 (ff8e977a158738155dc465c6a97ffaf31982d739)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 11.0.11, vendor: Ubuntu, runtime: /usr/lib/jvm/java-11-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-88-generic", arch: "amd64", family: "unix"

プロジェクト作成

Spring Initializrで、プロジェクトを作成します。

$ curl -s https://start.spring.io/starter.tgz \
  -d bootVersion=2.5.5 \
  -d javaVersion=11 \
  -d name=container-graceful-shutdown \
  -d groupId=org.littlewings \
  -d artifactId=container-graceful-shutdown \
  -d version=0.0.1-SNAPSHOT \
  -d packageName=org.littlewings.spring \
  -d dependencies=web \
  -d baseDir=container-graceful-shutdown | tar zxvf -

作成したプロジェクト内に移動。

$ cd container-graceful-shutdown

依存関係は、これだけです。今回はspring-boot-starter-webでデフォルトで組み込まれているTomcatで試すことにします。

 <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

生成されているソースコードは、いったん削除。

$ rm src/main/java/org/littlewings/spring/ContainerGracefulShutdownApplication.java src/test/java/org/littlewings/spring/ContainerGracefulShutdownApplicationTests.java

起動クラス＋RestControllerを作成する

起動クラスは、こちら。

src/main/java/org/littlewings/spring/App.java

package org.littlewings.spring;

import java.util.concurrent.TimeUnit;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

@RestController
@SpringBootApplication
public class App {
    Logger logger = LoggerFactory.getLogger(App.class);

    public static void main(String... args) {
        SpringApplication.run(App.class, args);
    }

    @GetMapping("hello")
    public String hello(@RequestParam(defaultValue = "10") int sleepTime) throws InterruptedException {
        logger.info("accept, sleep time = {} sec", sleepTime);

        TimeUnit.SECONDS.sleep(sleepTime);

        return "Hello World!!";
    }
}

RestControllerは、/helloでHello World!!を返しつつ、間にスリープする実装にしています。

    @GetMapping("hello")
    public String hello(@RequestParam(defaultValue = "10") int sleepTime) throws InterruptedException {
        logger.info("accept, sleep time = {} sec", sleepTime);

        TimeUnit.SECONDS.sleep(sleepTime);

        return "Hello World!!";
    }

スリープする時間は、デフォルトでは10秒としています。

Immediate Shutdown（デフォルト）で確認する

最初は、Immediate Shutdown（デフォルト）で確認してみましょう。

まずはパッケージング。

$ mvn package

起動。

$ java -jar target/container-graceful-shutdown-0.0.1-SNAPSHOT.jar

確認。

$ time curl localhost:8080/hello
Hello World!!
real    0m10.271s
user    0m0.006s
sys 0m0.011s

レスポンスが返ってくるまでに、10秒かかります。

再度、リクエストを投げてみます。

$ time curl localhost:8080/hello

ここでレスポンスが返ってくるまでに、killしてみます。

$ kill `ps -ef | grep 'java -jar' | grep -v grep | awk '{print $2}'`

curlにはレスポンスが返ってきませんでした。

$ time curl localhost:8080/hello
curl: (52) Empty reply from server

real    0m4.709s
user    0m0.008s
sys 0m0.000s

そして、アプリケーション側はkillした時点で停止します。

これが通常の動きですね。

Graceful Shutdownを有効にする

では、Graceful Shutdownを有効にしてみます。application.propertiesでserver.shutdownをgracefulと設定。

src/main/resources/application.properties

server.shutdown=graceful
spring.lifecycle.timeout-per-shutdown-phase=15s

spring.lifecycle.timeout-per-shutdown-phaseは15秒とします。

パッケージングして

$ mvn package

実行。

$ java -jar target/container-graceful-shutdown-0.0.1-SNAPSHOT.jar

とりあえず、確認してみます。

$ time curl localhost:8080/hello
Hello World!!
real    0m10.129s
user    0m0.010s
sys 0m0.000s

次に、リクエストを投げて

$ time curl localhost:8080/hello

裏でアプリケーションをkill。

$ kill `ps -ef | grep 'java -jar' | grep -v grep | awk '{print $2}'`

すると、アプリケーション側ではGraceful Shutdownが始まります。

2021-10-08 23:46:57.524  INFO 22386 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete

アプリケーションは停止せず、レスポンスはクライアントに返ってきます。

$ time curl localhost:8080/hello
Hello World!!
real    0m10.013s
user    0m0.010s
sys 0m0.000s

そして、アプリケーションが停止します。

2021-10-08 23:47:05.753  INFO 22386 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown complete

Graceful Shutdownにより、現在処理しているリクエストを待ってからアプリケーションが終了することが確認できました。

次は、Graceful Shutdownの猶予期間中に処理が終わらないリクエストも含めてみます。

起動。

$ java -jar target/container-graceful-shutdown-0.0.1-SNAPSHOT.jar

リクエストを2つ投げておきます。

# 1 request
$ time curl localhost:8080/hello


# 2 request
$ time curl localhost:8080/hello?sleepTime=30

片方は、猶予時間である15秒よりも長くスリープさせます（30秒）。

そしてkill。

$ kill `ps -ef | grep 'java -jar' | grep -v grep | awk '{print $2}'`

Graceful Shutdownが始まります。

2021-10-08 23:56:56.188  INFO 22669 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete

10秒スリープの方は、レスポンスが返ってきます。

# 1 response
$ time curl localhost:8080/hello
Hello World!!
real    0m10.153s
user    0m0.010s
sys 0m0.000s

30秒スリープさせる方は待ちきれず、アプリケーション側がシャットダウンします。

2021-10-08 23:57:11.189  INFO 22669 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to shut down 1 bean with phase value 2147483647 within timeout of 15000ms: [webServerGracefulShutdown]
2021-10-08 23:57:11.231  INFO 22669 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown aborted with one or more requests still active

この時、処理中のBeanがあるとログに記録されていますね。

クライアント側にも、レスポンスは返りません。

# 2 response
$ time curl localhost:8080/hello?sleepTime=30
curl: (52) Empty reply from server

real    0m18.422s
user    0m0.006s
sys 0m0.006s

最後に、アプリケーションのシャットダウンが始まった後にリクエストを投げるパターンも実行してみます。

まずは起動。

$ java -jar target/container-graceful-shutdown-0.0.1-SNAPSHOT.jar

先ほどと同じように、リクエストを2つ（片方は猶予時間中に終わらないもの）を投げておきます。

# 1 request
$ time curl localhost:8080/hello


# 2 request
$ time curl localhost:8080/hello?sleepTime=30

kill。

$ kill `ps -ef | grep 'java -jar' | grep -v grep | awk '{print $2}'`

Graceful Shutdownが始まります。

2021-10-09 00:05:34.746  INFO 23531 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete

この状態で、次のリクエストを投げようとすると、拒否されることが確認できます。

# 3 request
$ time curl localhost:8080/hello
curl: (7) Failed to connect to localhost port 8080: 接続を拒否されました

real    0m0.009s
user    0m0.009s
sys 0m0.000s

ひとつ目のリクエストは、レスポンスが得られます。

# 1 response
$ time curl localhost:8080/hello
Hello World!!
real    0m10.135s
user    0m0.005s
sys 0m0.005s

そして、アプリケーションは2つ目のリクエストの終了を待ちきれず、停止。

2021-10-09 00:05:49.747  INFO 23531 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to shut down 1 bean with phase value 2147483647 within timeout of 15000ms: [webServerGracefulShutdown]
2021-10-09 00:05:49.789  INFO 23531 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown aborted with one or more requests still active

2つ目のリクエストは、レスポンスが得られませんでした。

$ time curl localhost:8080/hello?sleepTime=30
curl: (52) Empty reply from server

real    0m18.848s
user    0m0.006s
sys 0m0.006s

これで、Graceful Shutdownに関するおよその振る舞いは確認できたかなと思います。

少し実装を見る

Graceful Shutdownは、SmartLifecycleインターフェースの実装である、WebServerGracefulShutdownLifecycleクラスが
アプリケーションの停止時にGraceful Shutdown用の処理を呼び出すことで行われます。

https://github.com/spring-projects/spring-framework/blob/v5.3.10/spring-context/src/main/java/org/springframework/context/SmartLifecycle.java

https://github.com/spring-projects/spring-boot/blob/v2.5.5/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/web/context/WebServerGracefulShutdownLifecycle.java#L62

ここで出てくるWebServerというのが、各組み込みサーバー向けの実装を抽象するインターフェースとなります。

各組み込みサーバーの実装と、Graceful Shutdownの処理を実装しているクラスは、以下のようになっています。

Tomcat
- TomcatWebServer
- GracefulShutdown.java
Undertow
- UndertowWebServer.java
  - Reactive向け
- UndertowServletWebServer.java
  - Servlet向け
Jetty
- JettyWebServer.java
- GracefulShutdown.java
Reactor Netty
- NettyWebServer.java
- GracefulShutdown.java

いずれもGraceful Shutdown用のクラスが切り出されて存在するのですが、UndertowはReactive向けに実装されている
UndertowWebServer内にGraceful Shutdownの処理が組み込まれています。また、UndertowServletWebServerは
サーブレット（Spring MVC）向けの組み込みWebサーバーになりますが、これはUndertowWebServerの
サブクラスとなるため、Graceful Shutdownの処理はReactiveと同じになりますね。

また、そもそもGraceful Shutdownはどのようにして呼び出されるのでしょう？

仕組みとしては、Shutdown Hookを使っているようです。

SpringApplicationで、SpringApplicationShutdownHookをShutdown Hookとして登録します。

https://github.com/spring-projects/spring-boot/blob/v2.5.5/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java#L432

SpringApplicationShutdownHookでは、JavaVMの停止が始まると各ApplicationContextのクローズを順次行います。

https://github.com/spring-projects/spring-boot/blob/v2.5.5/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplicationShutdownHook.java#L106

そして、SmartLifecycleインターフェースが実装されているものに関しては、SmartLifecycle#stopが呼び出されます。

https://github.com/spring-projects/spring-framework/blob/v5.3.10/spring-context/src/main/java/org/springframework/context/support/DefaultLifecycleProcessor.java#L234-L240

あとはWebServerインターフェースを介して、Graceful Shutdownが行われるという仕掛けです。

https://github.com/spring-projects/spring-boot/blob/v2.5.5/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/web/context/WebServerGracefulShutdownLifecycle.java#L62

もちろん、Graceful Shutdownが行われるのはserver.shutdownプロパティがgracefulに設定されていれば、ですが。
これは、各WebServerの実装が判定します。たとえば、Tomcatであれば以下になります。

https://github.com/spring-projects/spring-boot/blob/v2.5.5/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/web/embedded/tomcat/TomcatWebServer.java#L103