CLOVER🍀

That was when it all began.

QuartzのSchedulerのシャットダウンを始めた時の、実行中のジョブの扱いを確認してみる

これは、なにをしたくて書いたもの?

以前Quartzについて調べた時に、Scheduler#shutdownを呼び出す際に引数があるものを使い、かつtrueに設定すると実行中のジョブが
ある場合は、ジョブが終了するまで待機するということを書きました。

JavaのジョブスケジューラーQuartzを試す - CLOVER🍀

確かにドキュメントにもそのように書かれているのですが、実際にどうなのか確認してみることにしました。

How-To: Shutting Down a Scheduler

Scheduler#shutdown

Schedulerのシャットダウンに関するドキュメントはこちら。

How-To: Shutting Down a Scheduler

実行中のジョブが終了するまで待つ例、待たない例がそれぞれ書かれています。

待つ場合はこちら。

//shutdown() does not return until executing Jobs complete execution
scheduler.shutdown(true);

待たない場合はこちら。

//shutdown() returns immediately, but executing Jobs continue running to completion
scheduler.shutdown();
//or
scheduler.shutdown(false);

Scheduler#shutdownの引数ありのメソッドを使い、かつtrueを指定するかどうかで動作が変わります。

こちらの動作を、スタンドアロン、クラスタリングをした時でそれぞれ見てみようと思います。

環境

今回の環境は、こちら。

$ java --version
openjdk 17.0.8.1 2023-08-24
OpenJDK Runtime Environment (build 17.0.8.1+1-Ubuntu-0ubuntu122.04)
OpenJDK 64-Bit Server VM (build 17.0.8.1+1-Ubuntu-0ubuntu122.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.9.4 (dfbb324ad4a7c8fb0bf182e6d91b0ae20e3d2dd9)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 17.0.8.1, vendor: Private Build, runtime: /usr/lib/jvm/java-17-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.15.0-84-generic", arch: "amd64", family: "unix"

クラスタリングを行う際のデータベースは、MySQLを使います。172.17.0.2で動作しているものとし、バージョンはこちら。

 MySQL  localhost:3306 ssl  practice  SQL > select version();
+-----------+
| version() |
+-----------+
| 8.0.34    |
+-----------+
1 row in set (0.0007 sec)

ユーザーおよびデータベースは作成済みとします。

準備

Maven依存関係など。

    <properties>
        <maven.compiler.source>17</maven.compiler.source>
        <maven.compiler.target>17</maven.compiler.target>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.quartz-scheduler</groupId>
            <artifactId>quartz</artifactId>
            <version>2.3.2</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>2.0.9</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-simple</artifactId>
            <version>2.0.9</version>
        </dependency>
        <dependency>
            <groupId>com.mysql</groupId>
            <artifactId>mysql-connector-j</artifactId>
            <version>8.0.33</version>
            <scope>runtime</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-shade-plugin</artifactId>
                <version>3.5.1</version>
                <executions>
                    <execution>
                        <phase>package</phase>
                        <goals>
                            <goal>shade</goal>
                        </goals>
                        <configuration>
                            <transformers>
                                <transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
                                    <mainClass>org.littlewings.quartz.shutdown.App</mainClass>
                                </transformer>
                            </transformers>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

実行可能JARとして動作させることにします。

Quartzのテーブルを作成。

$ curl -sL https://raw.githubusercontent.com/quartz-scheduler/quartz/v2.3.2/quartz-core/src/main/resources/org/quartz/impl/jdbcjobstore/tables_mysql_innodb.sql | mysqlsh kazuhira@localhost:3306/practice --sql

ソースコードを作成する

まずは、Quartzのジョブを作成します。

毎分0秒、15秒、30秒、45秒に起動するジョブを作成し、各ジョブは30秒待機するものにします。

つまり、こういうものです。

src/main/java/org/littlewings/quartz/shutdown/HelloAt0Job.java

package org.littlewings.quartz.shutdown;

import org.quartz.Job;
import org.quartz.JobExecutionContext;
import org.quartz.JobExecutionException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.concurrent.TimeUnit;

public class HelloAt0Job implements Job {
    static final DateTimeFormatter DATE_TIME_FORMATTER = DateTimeFormatter.ofPattern("uuuu-MM-dd HH:mm:ss");

    Logger logger = LoggerFactory.getLogger(HelloAt0Job.class);

    @Override
    public void execute(JobExecutionContext jobExecutionContext) throws JobExecutionException {
        logger.info("[{}] job start..., sleep 30sec", LocalDateTime.now().format(DATE_TIME_FORMATTER));

        try {
            TimeUnit.SECONDS.sleep(30L);
        } catch (InterruptedException e) { }

        logger.info("Hello from {}", getClass().getSimpleName());

        logger.info("[{}] job end", LocalDateTime.now().format(DATE_TIME_FORMATTER));
    }
}

同じ処理をするので、同じジョブを別のトリガーで登録すればいいのですが、今回はわかりやすいようにそれぞれ別のクラスにしました。

ログ出力時にわざわざ時刻を入れているのは、ログ設定を端折ってslf4j-simpleにしたからです…。

つまり、こうです。

src/main/java/org/littlewings/quartz/shutdown/HelloAt15Job.java

package org.littlewings.quartz.shutdown;

import org.quartz.Job;
import org.quartz.JobExecutionContext;
import org.quartz.JobExecutionException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.concurrent.TimeUnit;

public class HelloAt15Job implements Job {
    static final DateTimeFormatter DATE_TIME_FORMATTER = DateTimeFormatter.ofPattern("uuuu-MM-dd HH:mm:ss");

    Logger logger = LoggerFactory.getLogger(HelloAt15Job.class);

    @Override
    public void execute(JobExecutionContext jobExecutionContext) throws JobExecutionException {
        logger.info("[{}] job start..., sleep 30sec", LocalDateTime.now().format(DATE_TIME_FORMATTER));

        try {
            TimeUnit.SECONDS.sleep(30L);
        } catch (InterruptedException e) { }

        logger.info("Hello from {}", getClass().getSimpleName());

        logger.info("[{}] job end", LocalDateTime.now().format(DATE_TIME_FORMATTER));
    }
}

あと2つは省略します。

public class HelloAt30Job implements Job {
    // 省略
}


public class HelloAt45Job implements Job {
    // 省略
}

そして、mainメソッドを持ったクラス。

src/main/java/org/littlewings/quartz/shutdown/App.java

package org.littlewings.quartz.shutdown;

import org.quartz.*;
import org.quartz.impl.StdSchedulerFactory;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.io.Console;

public class App {
    public static void main(String... args) {
        Logger logger = LoggerFactory.getLogger(App.class);

        Scheduler scheduler = null;

        boolean waitForJobsToComplete;
        boolean registerSchedule;

        if (args.length > 0) {
            waitForJobsToComplete = Boolean.parseBoolean(args[0]);

            if (args.length > 1) {
                registerSchedule = Boolean.parseBoolean(args[1]);
            } else {
                registerSchedule = true;
            }
        } else {
            waitForJobsToComplete = true;
            registerSchedule = true;
        }

        try {
            scheduler = StdSchedulerFactory.getDefaultScheduler();

            if (registerSchedule) {
                logger.info("register schedule");
                registerSchedules(scheduler);
            }

            logger.info("scheduler start, wait for jobs to complete = [{}], scheduler registered = [{}]", waitForJobsToComplete, registerSchedule);
            scheduler.start();

            Console console = System.console();
            console.readLine();
        } catch (SchedulerException e) {
            e.printStackTrace();
        } finally {
            if (scheduler != null) {
                try {
                    logger.info("shutdown start...");
                    scheduler.shutdown(waitForJobsToComplete);
                    logger.info("shutdown end");
                } catch (SchedulerException e) {
                    e.printStackTrace();
                }
            }
        }
    }

    static void registerSchedules(Scheduler scheduler) throws SchedulerException {
        JobDetail jobDetail1 =
                JobBuilder
                        .newJob(HelloAt0Job.class)
                        .withIdentity("hello-at0-job", "job-group1")
                        .build();

        Trigger trigger1 =
                TriggerBuilder
                        .newTrigger()
                        .withIdentity("hello-at0-trigger", "trigger-group1")
                        .withSchedule(CronScheduleBuilder.cronSchedule("0 * * * * ?"))
                        .build();

        JobDetail jobDetail2 =
                JobBuilder
                        .newJob(HelloAt15Job.class)
                        .withIdentity("hello-at15-job", "job-group1")
                        .build();

        Trigger trigger2 =
                TriggerBuilder
                        .newTrigger()
                        .withIdentity("hello-at15-trigger", "trigger-group1")
                        .withSchedule(CronScheduleBuilder.cronSchedule("15 * * * * ?"))
                        .build();

        JobDetail jobDetail3 =
                JobBuilder
                        .newJob(HelloAt30Job.class)
                        .withIdentity("hello-at30-job", "job-group1")
                        .build();

        Trigger trigger3 =
                TriggerBuilder
                        .newTrigger()
                        .withIdentity("hello-at30-trigger", "trigger-group1")
                        .withSchedule(CronScheduleBuilder.cronSchedule("30 * * * * ?"))
                        .build();

        JobDetail jobDetail4 =
                JobBuilder
                        .newJob(HelloAt45Job.class)
                        .withIdentity("hello-at45-job", "job-group1")
                        .build();

        Trigger trigger4 =
                TriggerBuilder
                        .newTrigger()
                        .withIdentity("hello-at45-trigger", "trigger-group1")
                        .withSchedule(CronScheduleBuilder.cronSchedule("45 * * * * ?"))
                        .build();

        scheduler.scheduleJob(jobDetail1, trigger1);
        scheduler.scheduleJob(jobDetail2, trigger2);
        scheduler.scheduleJob(jobDetail3, trigger3);
        scheduler.scheduleJob(jobDetail4, trigger4);
    }
}

コマンドライン引数で、「Schedulerのシャットダウン時に実行中のジョブを待つかどうか」と「Schedulerにジョブを登録するか」を
booleanで指定するようにしています。

        boolean waitForJobsToComplete;
        boolean registerSchedule;

        if (args.length > 0) {
            waitForJobsToComplete = Boolean.parseBoolean(args[0]);

            if (args.length > 1) {
                registerSchedule = Boolean.parseBoolean(args[1]);
            } else {
                registerSchedule = true;
            }
        } else {
            waitForJobsToComplete = true;
            registerSchedule = true;
        }

後者は、クラスタリング向けですね。

なにも指定しないと、「Schedulerのシャットダウン時に実行中のジョブを待つ」、「Schedulerにジョブを登録する」になります。

このあたりに影響します。

            // Schedulerにジョブを登録
            if (registerSchedule) {
                logger.info("register schedule");
                registerSchedules(scheduler);
            }


        } finally {
            if (scheduler != null) {
                try {
                    logger.info("shutdown start...");
                    // Schedulerのシャットダウン時に実行中のジョブを待つかどうかをbooleanで指定
                    scheduler.shutdown(waitForJobsToComplete);
                    logger.info("shutdown end");
                } catch (SchedulerException e) {
                    e.printStackTrace();
                }
            }
        }

どういうモードで実行しているかは、ログで表示します。

            logger.info("scheduler start, wait for jobs to complete = [{}], scheduler registered = [{}]", waitForJobsToComplete, registerSchedule);
            scheduler.start();

アプリケーションは、Enterを打つと停止を始めるようになっています。

            Console console = System.console();
            console.readLine();

ジョブの登録はこのあたりですが、省略します…。

    static void registerSchedules(Scheduler scheduler) throws SchedulerException {
        JobDetail jobDetail1 =
                JobBuilder
                        .newJob(HelloAt0Job.class)
                        .withIdentity("hello-at0-job", "job-group1")
                        .build();

        Trigger trigger1 =
                TriggerBuilder
                        .newTrigger()
                        .withIdentity("hello-at0-trigger", "trigger-group1")
                        .withSchedule(CronScheduleBuilder.cronSchedule("0 * * * * ?"))
                        .build();

         // 省略
    }

毎分0秒、15秒、30秒、45秒に、実行に30秒かかるジョブが起動するようになります。

スタンドアロンで確認する

では、確認してみましょう。

パッケージング。

$ mvn package

実行。

$ java -jar target/-0.0.1-SNAPSHOT.jar

実行すると、こんな感じで進んでいきます。

[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:27:30] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:27:45] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:28:00] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - Hello from HelloAt30Job
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:28:00] job end
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - Hello from HelloAt45Job
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:28:15] job end

1度やり直して、2つジョブが実行している間に止めてみましょう。デフォルトではジョブが終了するまで待つはずです。

結果はこちら。

[main] INFO org.littlewings.quartz.shutdown.App - scheduler start, wait for jobs to complete = [true], scheduler registered = [true]
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started.
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:30:45] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:31:00] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:31:15] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - Hello from HelloAt45Job
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:31:15] job end

[main] INFO org.littlewings.quartz.shutdown.App - shutdown start...
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutting down.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED paused.
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - Hello from HelloAt0Job
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:31:30] job end
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:31:45] job end
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutdown complete.
[main] INFO org.littlewings.quartz.shutdown.App - shutdown end

空行があるところが、Enterを打った箇所です。

HelloAt45Jobのジョブが終了し、HelloAt0JobとHelloAt15Jobが実行中に停止を始めたわけですが、確かに終了するまで待っています。

では、次は待たないようにしてみましょう。

$ java -jar target/app-0.0.1-SNAPSHOT.jar false

結果。

[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started.
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:33:45] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:34:00] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:34:15] job start..., sleep 30sec
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - Hello from HelloAt45Job
[DefaultQuartzScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:34:15] job end

[main] INFO org.littlewings.quartz.shutdown.App - shutdown start...
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutting down.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED paused.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED shutdown complete.
[main] INFO org.littlewings.quartz.shutdown.App - shutdown end
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - Hello from HelloAt0Job
[DefaultQuartzScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:34:30] job end
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[DefaultQuartzScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:34:45] job end

動作が変わり、Scheduler自体はジョブの終了を待たなくなりました。

一方で、ジョブを無視して終了しているかというと、アクティブなスレッドが残っているのでJavaVMが終了しない状態になりましたね…。

実行中のジョブが強制的に止められるわけではないということも合わせてわかりましたが、Schedulerの振る舞いは確認できました。

クラスタリングしてみる

次は、Quartzをクラスタリングしてみます。

クラスタリング用のプロパティファイルを作成。今回はデフォルトの名前(quartz.properties)で作成せず、アプリケーションの実行時に
-Dorg.quartz.propertiesシステムプロパティで指定することにします。

src/main/resources/quartz-clustering.properties

org.quartz.scheduler.instanceName=ClusteredExampleScheduler
org.quartz.scheduler.instanceId=AUTO

org.quartz.threadPool.class=org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.threadCount=10

org.quartz.jobStore.class=org.quartz.impl.jdbcjobstore.JobStoreTX
org.quartz.jobStore.isClustered=true
org.quartz.jobStore.driverDelegateClass=org.quartz.impl.jdbcjobstore.StdJDBCDelegate
org.quartz.jobStore.tablePrefix=QRTZ_
org.quartz.jobStore.useProperties=true
org.quartz.jobStore.dataSource=mysqlds

org.quartz.dataSource.mysqlds.driver=com.mysql.cj.jdbc.Driver
org.quartz.dataSource.mysqlds.URL=jdbc:mysql://172.17.0.2:3306/practice?characterEncoding=utf-8&connectionCollation=utf8mb4_0900_bin
org.quartz.dataSource.mysqlds.user=kazuhira
org.quartz.dataSource.mysqlds.password=password
org.quartz.dataSource.mysqlds.maxConnections=10

パッケージング。

$ mvn package

実行。2つのインスタンスを起動することにします。

## ひとつ目
$ java -Dorg.quartz.properties=quartz-clustering.properties -jar target/app-0.0.1-SNAPSHOT.jar true true


## 2つ目
$ java -Dorg.quartz.properties=quartz-clustering.properties -jar target/app-0.0.1-SNAPSHOT.jar true false

2つ目のインスタンスは、ジョブを登録しません。最初のインスタンスが登録するからですね。

ひとつ目のインスタンスで、起動してから3つ目のジョブが起動したところでシャットダウンを開始。

[main] INFO org.littlewings.quartz.shutdown.App - scheduler start, wait for jobs to complete = [true], scheduler registered = [true]
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160589507 started.
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:43:15] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:43:30] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:43:45] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:43:45] job end

[main] INFO org.littlewings.quartz.shutdown.App - shutdown start...
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160589507 shutting down.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160589507 paused.
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt30Job - Hello from HelloAt30Job
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:44:00] job end
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt45Job - Hello from HelloAt45Job
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:44:15] job end
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160589507 shutdown complete.
[main] INFO org.littlewings.quartz.shutdown.App - shutdown end

ひとつ目のインスタンスに実行ジョブが偏っていて、シャットダウンを始めたところでジョブの開始がなくなります。これは
スタンドアロンで実行していた時と同じですね。

一方で、2つ目のインスタンス側ではひとつ目のインスタンスがシャットダウンを始めた後、ジョブスケジュールに則ってジョブの
実行を継続します。

[main] INFO org.littlewings.quartz.shutdown.App - scheduler start, wait for jobs to complete = [true], scheduler registered = [false]
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160590005 started.
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:44:00] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:44:15] job start..., sleep 30sec

この後にシャットダウンを始めると、実行中のジョブの完了は待ちますがすんなり終了します。

[main] INFO org.littlewings.quartz.shutdown.App - shutdown start...
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160590005 shutting down.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160590005 paused.
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt0Job - Hello from HelloAt0Job
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:44:30] job end
[QuartzScheduler_ClusteredExampleScheduler-server1696160590005_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: detected 1 failed or restarted instances.
[QuartzScheduler_ClusteredExampleScheduler-server1696160590005_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: Scanning for instance "server1696160589507"'s failed in-progress jobs.
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:44:45] job end
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696160590005 shutdown complete.
[main] INFO org.littlewings.quartz.shutdown.App - shutdown end

クラスタリングしていれば、あるインスタンスがシャットダウン中であってもジョブスケジュールの引き継ぎまで行うことが
確認できました。

ちなみに、しばらく待っていると2つ目のインスタンスが他のインスタンスが終了したことを検出します。

[QuartzScheduler_ClusteredExampleScheduler-ikaruga1696160590005_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: detected 1 failed or restarted instances.
[QuartzScheduler_ClusteredExampleScheduler-ikaruga1696160590005_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: Scanning for instance "server1696160589507"'s failed in-progress jobs.

続いては、ジョブの終了を待たないようにしてはどうでしょうか。

## ひとつ目
$ java -Dorg.quartz.properties=quartz-clustering.properties -jar target/app-0.0.1-SNAPSHOT.jar false true


## 2つ目
$ java -Dorg.quartz.properties=quartz-clustering.properties -jar target/app-0.0.1-SNAPSHOT.jar false false

実行時の注意点として、前述の実行例の後に続けて実行する場合は、第2引数をfalseにする必要があります。先のアプリケーションの
実行で、ジョブスケジュールはすでに登録済みだからです。

$ java -Dorg.quartz.properties=quartz-clustering.properties -jar target/app-0.0.1-SNAPSHOT.jar false false

MySQLデータベースを作り直して実行しています。

実行結果はこちら。

ひとつ目のインスタンス。HelloAt15Jobの実行が終わり、HelloAt45Jobの実行中にシャットダウンを始めました。

[main] INFO org.littlewings.quartz.shutdown.App - scheduler start, wait for jobs to complete = [false], scheduler registered = [true]
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696161362884 started.
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:56:15] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:56:45] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:56:45] job end

[main] INFO org.littlewings.quartz.shutdown.App - shutdown start...
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696161362884 shutting down.
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696161362884 paused.
[ClusteredExampleScheduler_QuartzSchedulerThread] ERROR org.quartz.core.QuartzSchedulerThread - Runtime error occurred in main trigger firing loop.
java.lang.IllegalStateException: JobStore is shutdown - aborting retry
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3833)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696161362884 shutdown complete.
[main] INFO org.littlewings.quartz.shutdown.App - shutdown end
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - Hello from HelloAt45Job
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt45Job - [2023-10-01 20:57:15] job end
[ClusteredExampleScheduler_Worker-2] ERROR org.quartz.simpl.SimpleThreadPool - Error while executing the Runnable:
java.lang.IllegalStateException: JobStore is shutdown - aborting retry
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3833)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.triggeredJobComplete(JobStoreSupport.java:3116)
        at org.quartz.core.QuartzScheduler.notifyJobStoreJobComplete(QuartzScheduler.java:1786)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:269)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

動いているには動いているのですが、シャットダウン後にJobStoreにアクセスしようとして失敗していますね…。

これは、ジョブが完了したことをJobStoreに反映しようとしているように見えます。

2つ目のインスタンス。HelloAt30Jobは、ひとつ目のインスタンスが停止する前からこちらに振り分けられて実行されていました。

[main] INFO org.littlewings.quartz.shutdown.App - scheduler start, wait for jobs to complete = [false], scheduler registered = [false]
[main] INFO org.quartz.core.QuartzScheduler - Scheduler ClusteredExampleScheduler_$_server1696161363985 started.
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:56:30] job start..., sleep 30sec
[QuartzScheduler_ClusteredExampleScheduler-server1696161363985_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: detected 1 failed or restarted instances.
[QuartzScheduler_ClusteredExampleScheduler-server1696161363985_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: Scanning for instance "server1696161362884"'s failed in-progress jobs.
[QuartzScheduler_ClusteredExampleScheduler-server1696161363985_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Freed 1 acquired trigger(s).
[QuartzScheduler_ClusteredExampleScheduler-server1696161363985_ClusterManager] INFO org.quartz.impl.jdbcjobstore.JobStoreTX - ClusterManager: ......Cleaned-up 1 other failed job(s).
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:57:00] job start..., sleep 30sec
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - Hello from HelloAt30Job
[ClusteredExampleScheduler_Worker-1] INFO org.littlewings.quartz.shutdown.HelloAt30Job - [2023-10-01 20:57:00] job end
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:57:15] job start..., sleep 30sec

今回は、ひとつ目のインスタンスが終了したことの検知が速かったです。また、ひとつ目のインスタンスがシャットダウンした後の
HelloAt0Jobの実行から引き継いでいます。

一見問題なさそうに見えますが、こちらのインスタンスでシャットダウンを開始するとデータベースアクセスを開始して大変なことに
なります…。

[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners!
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1621)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1535)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:380)
        at jdk.internal.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.invoke(AttributeRestoringConnectionInvocationHandler.java:73)
        at jdk.proxy2/jdk.proxy2.$Proxy4.prepareStatement(Unknown Source)
        at org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:115)
        at org.quartz.impl.jdbcjobstore.DBSemaphore.obtainLock(DBSemaphore.java:113)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3857)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1550)
        ... 14 more
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners!
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1621)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1535)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:380)
        at jdk.internal.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.invoke(AttributeRestoringConnectionInvocationHandler.java:73)
        at jdk.proxy2/jdk.proxy2.$Proxy4.prepareStatement(Unknown Source)
        at org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:115)
        at org.quartz.impl.jdbcjobstore.DBSemaphore.obtainLock(DBSemaphore.java:113)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3857)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:1550)
        ... 14 more
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners!
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1816)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:1033)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.invoke(AttributeRestoringConnectionInvocationHandler.java:73)
        at jdk.proxy2/jdk.proxy2.$Proxy4.rollback(Unknown Source)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.rollbackConnection(JobStoreSupport.java:3727)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3886)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1770)
        ... 13 more
[ClusteredExampleScheduler_QuartzSchedulerThread] ERROR org.quartz.impl.jdbcjobstore.JobStoreTX - Couldn't rollback jdbc connection. No operations allowed after connection closed.
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1816)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:1033)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.invoke(AttributeRestoringConnectionInvocationHandler.java:73)
        at jdk.proxy2/jdk.proxy2.$Proxy4.rollback(Unknown Source)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.rollbackConnection(JobStoreSupport.java:3727)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3886)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1770)
        ... 13 more
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners!
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2022)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:1059)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.restoreOriginalAtributes(AttributeRestoringConnectionInvocationHandler.java:141)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.cleanupConnection(JobStoreSupport.java:3677)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3896)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:1965)
        ... 8 more
[ClusteredExampleScheduler_QuartzSchedulerThread] WARN org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler - Failed restore connection's original auto commit setting.
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:111)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:98)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:90)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:64)
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:74)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)
        at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2022)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:1059)
        at org.quartz.impl.jdbcjobstore.AttributeRestoringConnectionInvocationHandler.restoreOriginalAtributes(AttributeRestoringConnectionInvocationHandler.java:141)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.cleanupConnection(JobStoreSupport.java:3677)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3896)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3819)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
        at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150)
        at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:753)
        at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:565)
        at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:1965)
        ... 8 more
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - Hello from HelloAt0Job
[ClusteredExampleScheduler_Worker-2] INFO org.littlewings.quartz.shutdown.HelloAt0Job - [2023-10-01 20:57:30] job end
[ClusteredExampleScheduler_Worker-2] ERROR org.quartz.simpl.SimpleThreadPool - Error while executing the Runnable:
java.lang.IllegalStateException: JobStore is shutdown - aborting retry
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3833)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.triggeredJobComplete(JobStoreSupport.java:3116)
        at org.quartz.core.QuartzScheduler.notifyJobStoreJobComplete(QuartzScheduler.java:1786)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:269)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
[ClusteredExampleScheduler_QuartzSchedulerThread] ERROR org.quartz.core.QuartzSchedulerThread - Runtime error occurred in main trigger firing loop.
java.lang.IllegalStateException: JobStore is shutdown - aborting retry
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3833)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2940)
        at org.quartz.core.QuartzSchedulerThread.releaseIfScheduleChangedSignificantly(QuartzSchedulerThread.java:472)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:333)
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - Hello from HelloAt15Job
[ClusteredExampleScheduler_Worker-3] INFO org.littlewings.quartz.shutdown.HelloAt15Job - [2023-10-01 20:57:45] job end
[ClusteredExampleScheduler_Worker-3] ERROR org.quartz.simpl.SimpleThreadPool - Error while executing the Runnable:
java.lang.IllegalStateException: JobStore is shutdown - aborting retry
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.retryExecuteInNonManagedTXLock(JobStoreSupport.java:3833)
        at org.quartz.impl.jdbcjobstore.JobStoreSupport.triggeredJobComplete(JobStoreSupport.java:3116)
        at org.quartz.core.QuartzScheduler.notifyJobStoreJobComplete(QuartzScheduler.java:1786)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:269)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

というわけで、クラスタリングを使っている場合はScheduler#shutdownにはtrueを指定すべきですね。JobStoreへの反映の必要と、
Schedulerの状態の整合性が取れなくなるようなので。

これで、確認したいことは見れたかなと思います。

オマケ:Spring Bootで試してみる

最後にオマケで、Spring Bootでも確認してみましょう。こちらはクラスタリングのみで行います。

こちらは最初からクラスタリング構成のみで確認します。

プロジェクトの作成。

$ curl -s https://start.spring.io/starter.tgz \
  -d bootVersion=3.1.4 \
  -d javaVersion=17 \
  -d type=maven-project \
  -d name=quartz-shutdown-example \
  -d groupId=org.littlewings \
  -d artifactId=quartz-shutdown-example \
  -d version=0.0.1-SNAPSHOT \
  -d packageName=org.littlewings.spring.quartz \
  -d dependencies=quartz,jdbc,mysql \
  -d baseDir=quartz-shutdown-example | tar zxvf -

ディレクトリ内に移動。

$ cd quartz-shutdown-example

自動生成されたソースコードは削除。

$ rm src/main/java/org/littlewings/spring/quartz/QuartzShutdownExampleApplication.java src/test/java/org/littlewings/spring/quartz/QuartzShutdownExampleApplicationTests.java

ログ設定はSpring BootのLogbackのものになるので、ジョブの内容を少し簡素にしました。

src/main/java/org/littlewings/spring/quartz/HelloAt0Job.java

package org.littlewings.spring.quartz;

import org.quartz.Job;
import org.quartz.JobExecutionContext;
import org.quartz.JobExecutionException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.time.format.DateTimeFormatter;
import java.util.concurrent.TimeUnit;

public class HelloAt0Job implements Job {
    Logger logger = LoggerFactory.getLogger(HelloAt0Job.class);

    @Override
    public void execute(JobExecutionContext jobExecutionContext) throws JobExecutionException {
        logger.info("job start..., sleep 30sec");

        try {
            TimeUnit.SECONDS.sleep(30L);
        } catch (InterruptedException e) {
        }

        logger.info("Hello from {}", getClass().getSimpleName());

        logger.info("job end");
    }
}

その他のジョブの中身は同じなので、割愛します。

mainメソッドとジョブの登録。

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

package org.littlewings.spring.quartz;

import org.quartz.JobDetail;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.scheduling.quartz.CronTriggerFactoryBean;
import org.springframework.scheduling.quartz.JobDetailFactoryBean;

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

    @Bean("helloAt0Job")
    public JobDetailFactoryBean helloAt0JobDetailFactoryBean() {
        JobDetailFactoryBean jobDetailFactoryBean = new JobDetailFactoryBean();
        jobDetailFactoryBean.setName("hello-at0-job");
        jobDetailFactoryBean.setGroup("job-group1");
        jobDetailFactoryBean.setJobClass(HelloAt0Job.class);
        jobDetailFactoryBean.setDurability(true);

        return jobDetailFactoryBean;
    }

    @Bean
    public CronTriggerFactoryBean helloAt0CronTriggerFactoryBean(JobDetail helloAt0Job) {
        CronTriggerFactoryBean cronTriggerFactoryBean = new CronTriggerFactoryBean();
        cronTriggerFactoryBean.setName("hello-at0-trigger");
        cronTriggerFactoryBean.setGroup("trigger-group1");
        cronTriggerFactoryBean.setJobDetail(helloAt0Job);
        cronTriggerFactoryBean.setCronExpression("0 * * * * ?");
        return cronTriggerFactoryBean;
    }

    @Bean("helloAt15Job")
    public JobDetailFactoryBean helloAt15JobDetailFactoryBean() {
        JobDetailFactoryBean jobDetailFactoryBean = new JobDetailFactoryBean();
        jobDetailFactoryBean.setName("hello-at15-job");
        jobDetailFactoryBean.setGroup("job-group1");
        jobDetailFactoryBean.setJobClass(HelloAt15Job.class);
        jobDetailFactoryBean.setDurability(true);

        return jobDetailFactoryBean;
    }

    @Bean
    public CronTriggerFactoryBean helloAt15CronTriggerFactoryBean(JobDetail helloAt15Job) {
        CronTriggerFactoryBean cronTriggerFactoryBean = new CronTriggerFactoryBean();
        cronTriggerFactoryBean.setName("hello-at15-trigger");
        cronTriggerFactoryBean.setGroup("trigger-group1");
        cronTriggerFactoryBean.setJobDetail(helloAt15Job);
        cronTriggerFactoryBean.setCronExpression("15 * * * * ?");
        return cronTriggerFactoryBean;
    }

    @Bean("helloAt30Job")
    public JobDetailFactoryBean helloAt30JobDetailFactoryBean() {
        JobDetailFactoryBean jobDetailFactoryBean = new JobDetailFactoryBean();
        jobDetailFactoryBean.setName("hello-at30-job");
        jobDetailFactoryBean.setGroup("job-group1");
        jobDetailFactoryBean.setJobClass(HelloAt30Job.class);
        jobDetailFactoryBean.setDurability(true);

        return jobDetailFactoryBean;
    }

    @Bean
    public CronTriggerFactoryBean helloAt30CronTriggerFactoryBean(JobDetail helloAt30Job) {
        CronTriggerFactoryBean cronTriggerFactoryBean = new CronTriggerFactoryBean();
        cronTriggerFactoryBean.setName("hello-at30-trigger");
        cronTriggerFactoryBean.setGroup("trigger-group1");
        cronTriggerFactoryBean.setJobDetail(helloAt30Job);
        cronTriggerFactoryBean.setCronExpression("30 * * * * ?");
        return cronTriggerFactoryBean;
    }

    @Bean("helloAt45Job")
    public JobDetailFactoryBean helloAt45JobDetailFactoryBean() {
        JobDetailFactoryBean jobDetailFactoryBean = new JobDetailFactoryBean();
        jobDetailFactoryBean.setName("hello-at45-job");
        jobDetailFactoryBean.setGroup("job-group1");
        jobDetailFactoryBean.setJobClass(HelloAt45Job.class);
        jobDetailFactoryBean.setDurability(true);

        return jobDetailFactoryBean;
    }

    @Bean
    public CronTriggerFactoryBean helloAt45CronTriggerFactoryBean(JobDetail helloAt45Job) {
        CronTriggerFactoryBean cronTriggerFactoryBean = new CronTriggerFactoryBean();
        cronTriggerFactoryBean.setName("hello-at45-trigger");
        cronTriggerFactoryBean.setGroup("trigger-group1");
        cronTriggerFactoryBean.setJobDetail(helloAt45Job);
        cronTriggerFactoryBean.setCronExpression("45 * * * * ?");
        return cronTriggerFactoryBean;
    }
}

Spring Bootの場合、Quartzの設定はapplication.propertiesで設定できます。

src/main/resources/application.properties

spring.datasource.url=jdbc:mysql://172.17.0.2:3306/practice?characterEncoding=utf-8&connectionCollation=utf8mb4_0900_bin
spring.datasource.username=kazuhira
spring.datasource.password=password

spring.quartz.job-store-type=jdbc
spring.quartz.properties.org.quartz.jobStore.isClustered=true
spring.quartz.properties.org.quartz.jobStore.useProperties=true
spring.quartz.jdbc.initialize-schema=never
spring.quartz.wait-for-jobs-to-complete-on-shutdown=true

Quartzが使うデータベースは、spring.datasource.〜のものになります。

JobStoreはjdbcにして、クラスタリングも有効化。Quartzのテーブルは先に作成済みとします。

spring.quartz.job-store-type=jdbc
spring.quartz.properties.org.quartz.jobStore.isClustered=true
spring.quartz.properties.org.quartz.jobStore.useProperties=true
spring.quartz.jdbc.initialize-schema=never

Scheduler#shutdownの設定は、spring.quartz.wait-for-jobs-to-complete-on-shutdownで設定しますが、デフォルト値はfalseです。

spring.quartz.wait-for-jobs-to-complete-on-shutdown

今回はtrueにしておきます。

spring.quartz.wait-for-jobs-to-complete-on-shutdown=true

では、パッケージングして

$ mvn package

起動。

## ひとつ目
$ java -jar target/quartz-shutdown-example-0.0.1-SNAPSHOT.jar


## 2つ目
$ java -jar target/quartz-shutdown-example-0.0.1-SNAPSHOT.jar

ひとつ目のインスタンスで、HelloAt15Jobが実行終了、HelloAt30Jobが実行中のところでCtrl-cでシャットダウン。
なお、HelloAt45Jobは2つ目のインスタンスで起動しました。

2023-10-01T21:55:15.056+09:00  INFO 30881 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt15Job           : job start..., sleep 30sec
2023-10-01T21:55:30.046+09:00  INFO 30881 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt30Job           : job start..., sleep 30sec
2023-10-01T21:55:45.057+09:00  INFO 30881 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt15Job           : Hello from HelloAt15Job
2023-10-01T21:55:45.058+09:00  INFO 30881 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt15Job           : job end
^C2023-10-01T21:55:49.124+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED paused.
2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] o.s.s.quartz.SchedulerFactoryBean        : Shutting down Quartz Scheduler
2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED shutting down.
2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED paused.

ジョブの完了を待ってから終了するようになっています。

2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] o.s.s.quartz.SchedulerFactoryBean        : Shutting down Quartz Scheduler
2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED shutting down.
2023-10-01T21:55:49.125+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED paused.
2023-10-01T21:56:00.047+09:00  INFO 30881 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt30Job           : Hello from HelloAt30Job
2023-10-01T21:56:00.047+09:00  INFO 30881 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt30Job           : job end
2023-10-01T21:56:00.078+09:00  INFO 30881 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED shutdown complete.
2023-10-01T21:56:00.079+09:00  INFO 30881 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2023-10-01T21:56:00.090+09:00  INFO 30881 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

2つ目のインスタンスの様子。ひとつ目のインスタンスがシャットダウン中に起動タイミングを迎えたHelloAt0Jobの実行を引き継いでは
いるのですが、開始タイミングがちょっと遅れてますね…。

2023-10-01T21:55:45.057+09:00  INFO 30923 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt45Job           : job start..., sleep 30sec
2023-10-01T21:56:15.046+09:00  INFO 30923 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt15Job           : job start..., sleep 30sec
2023-10-01T21:56:15.058+09:00  INFO 30923 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt45Job           : Hello from HelloAt45Job
2023-10-01T21:56:15.058+09:00  INFO 30923 --- [eduler_Worker-1] o.l.spring.quartz.HelloAt45Job           : job end
2023-10-01T21:56:15.121+09:00  INFO 30923 --- [eduler_Worker-3] o.littlewings.spring.quartz.HelloAt0Job  : job start..., sleep 30sec

その後、終了。

2023-10-01T21:56:28.069+09:00  INFO 30923 --- [ionShutdownHook] o.s.s.quartz.SchedulerFactoryBean        : Shutting down Quartz Scheduler
2023-10-01T21:56:28.069+09:00  INFO 30923 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED shutting down.
2023-10-01T21:56:28.069+09:00  INFO 30923 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED paused.
2023-10-01T21:56:45.047+09:00  INFO 30923 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt15Job           : Hello from HelloAt15Job
2023-10-01T21:56:45.048+09:00  INFO 30923 --- [eduler_Worker-2] o.l.spring.quartz.HelloAt15Job           : job end
2023-10-01T21:56:45.122+09:00  INFO 30923 --- [eduler_Worker-3] o.littlewings.spring.quartz.HelloAt0Job  : Hello from HelloAt0Job
2023-10-01T21:56:45.122+09:00  INFO 30923 --- [eduler_Worker-3] o.littlewings.spring.quartz.HelloAt0Job  : job end
2023-10-01T21:56:45.153+09:00  INFO 30923 --- [ionShutdownHook] org.quartz.core.QuartzScheduler          : Scheduler quartzScheduler_$_NON_CLUSTERED shutdown complete.
2023-10-01T21:56:45.155+09:00  INFO 30923 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2023-10-01T21:56:45.166+09:00  INFO 30923 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

こちらもジョブの実行を待ってからの終了になりました。

ちょっとジョブの実行タイミングはブレましたが、まあいいでしょう…。

spring.quartz.wait-for-jobs-to-complete-on-shutdownの反映先は、こちら。

https://github.com/spring-projects/spring-boot/blob/v3.1.4/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/quartz/QuartzAutoConfiguration.java#L80

SchedulerFactoryBean#setWaitForJobsToCompleteOnShutdown)

そして、Bean破棄のタイミングで呼び出されるScheduler#shutdownの引数に使われます。

https://github.com/spring-projects/spring-framework/blob/v6.0.12/spring-context-support/src/main/java/org/springframework/scheduling/quartz/SchedulerFactoryBean.java#L848

おわりに

QuartzのScheduler#shutdownを実行した時の、実行中のジョブの扱いを確認してみました。

基本的には、Scheduler#shutdownはtrueにするのが良さそうなのですが、どうしてこれデフォルトでtrueではないんでしょうね…?

Jestでテストが並列に動作していることを確認してみる

これは、なにをしたくて書いたもの?

Jestはデフォルトでテストを並列に実行するというので、動作を確認しておきたいなと思いまして。

JestのCLIのオプションを確認する

JestのCLIのオプションを見てみます。

Jest CLI Options · Jest

以下の2つの項目が関連しそうです。

--maxWorkersはテストを実行するためにワーカープールが生成する、ワーカーの最大数を指定するそうです。
デフォルトでは動作しているホストのCPU数から1を引いた値(CPUがひとつなら1)となり、--watchを指定したウォッチモードでは
ホストのCPUの半分に設定されるようです。
このオプションは、パーセンテージでの指定(--maxWorkers=50%など)も可能です。

--runInBandは、ワーカーの数を1にします。--maxWorkers=1と同じです。

maxWorkersは設定ファイルでも指定できそうです。

Configuring Jest / maxWorkers [number | string]

なお、並列で実行されるのはファイル単位(テストコード単位)で、ファイル内にあるテストはシーケンシャルに実行されるようです。

テストを並行に実行したい場合は、テストをtestではなくtest.concurrentを使って書くようです。

test.concurrent(name, fn, timeout)

こちらの設定は、--maxConcurrencyで行うようです。

今回はtest.concurrentについてはパスしておきます。

テストコードを用意して、実際にどのように動いているのか確認してみたいと思います。使ったJestのバージョンは、29.7.0です。

環境

今回の環境は、こちら。

$ node --version
v18.18.0


$ npm --version
9.8.1

CPUは8個あります。

$ grep processor /proc/cpuinfo
processor       : 0
processor       : 1
processor       : 2
processor       : 3
processor       : 4
processor       : 5
processor       : 6
processor       : 7

準備

まずは、Node.jsプロジェクトを作成します。ソースコードはTypeScriptで書くことにします。

$ npm init -y
$ npm i -D typescript
$ npm i -D prettier
$ npm i -D @types/node@v18

Jestとesbuild、esbuild-jestのインストール。

$ npm i -D jest @types/jest
$ npm i -D esbuild esbuild-jest

テストコードは、testディレクトリに置くことにします。

$ mkdir test

依存関係。

  "devDependencies": {
    "@types/jest": "^29.5.5",
    "@types/node": "^18.18.1",
    "esbuild": "^0.19.4",
    "esbuild-jest": "^0.5.0",
    "jest": "^29.7.0",
    "prettier": "^3.0.3",
    "typescript": "^5.2.2"
  }

scripts。

  "scripts": {
    "typecheck": "tsc --project .",
    "typecheck:watch": "tsc --project . --watch",
    "test": "jest",
    "format": "prettier --write test"
  },

各種設定ファイル。

tsconfig.json

{
  "compilerOptions": {
    "target": "esnext",
    "module": "commonjs",
    "moduleResolution": "node",
    "lib": ["esnext"],
    "baseUrl": "./test",
    "noEmit": true,
    "strict": true,
    "forceConsistentCasingInFileNames": true,
    "noFallthroughCasesInSwitch": true,
    "noImplicitOverride": true,
    "noImplicitReturns": true,
    "noPropertyAccessFromIndexSignature": true,
    "esModuleInterop": true
  },
  "include": [
    "test"
  ]
}

.prettierrc.json

{
  "singleQuote": true,
  "printWidth": 120
}

jest.config.js

module.exports = {
  testEnvironment: 'node',
  transform: {
    "^.+\\.tsx?$": "esbuild-jest"
  }
};

Jestは、npx jestで実行することにしましょう。

テストコードを書いてみる

まずはテストコードをひとつ用意してみます。

test/test1.test.ts

import { basename } from 'node:path';
import { setTimeout } from 'node:timers/promises';

jest.setTimeout(10 * 1000);

const testBaseName = basename(__filename);
const currentDir = process.cwd();

test(`${testBaseName}: test1`, async () => {
  console.log(
    `[${testBaseName}] jest worker id = ${process.env['JEST_WORKER_ID']}, pid = ${
      process.pid
    }, path = ${process.argv[1].replace(currentDir + '/', '')}`,
  );
  await setTimeout(2 * 1000);
});

test(`${testBaseName}: test2`, async () => {
  console.log(
    `[${testBaseName}] jest worker id = ${process.env['JEST_WORKER_ID']}, pid = ${
      process.pid
    }, path = ${process.argv[1].replace(currentDir + '/', '')}`,
  );
  await setTimeout(2 * 1000);
});

各テストでは、2秒ずつスリープさせています。

JEST_WORKER_IDというのは、Jestのワーカープロセスに1から割り当てられる数字で、こちらを参照できる環境変数です。

Environment Variables · Jest

今回は、JestのワーカーID、プロセスのid、プロセスの実行パスをそれぞれ出力してみます。

では

$ npx jest
  console.log
    [test1.test.ts] jest worker id = 1, pid = 18771, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test1.test.ts:7:11)

  console.log
    [test1.test.ts] jest worker id = 1, pid = 18771, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test1.test.ts:13:11)

 PASS  test/test1.test.ts
  ✓ test1.test.ts: test1 (2018 ms)
  ✓ test1.test.ts: test2 (2008 ms)

Test Suites: 1 passed, 1 total
Tests:       2 passed, 2 total
Snapshots:   0 total
Time:        4.341 s, estimated 5 s
Ran all test suites.

4秒少々かかりました。同じプロセスで実行されていますね。

テストコードを増やしてみる

では、このテストコードをコピーして増やしてみます。

$ cp test/test1.test.ts test/test2.test.ts
$ cp test/test1.test.ts test/test3.test.ts

3ファイルにしてみました。

もう1度、テストを実行してみます。

$ npx jest

結果はこのようになり、4秒少々なので並列に実行されたようです。

 PASS  test/test1.test.ts
  ● Console

    console.log
      [test1.test.ts] jest worker id = 3, pid = 19089, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:7:11)

    console.log
      [test1.test.ts] jest worker id = 3, pid = 19089, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:13:11)

 PASS  test/test3.test.ts
  ● Console

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19077, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:7:11)

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19077, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:13:11)

 PASS  test/test2.test.ts
  ● Console

    console.log
      [test2.test.ts] jest worker id = 2, pid = 19078, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:7:11)

    console.log
      [test2.test.ts] jest worker id = 2, pid = 19078, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:13:11)


Test Suites: 3 passed, 3 total
Tests:       6 passed, 6 total
Snapshots:   0 total
Time:        4.693 s, estimated 5 s
Ran all test suites.

JestのワーカーID、PIDもそれぞれ異なります。また、実行されているファイルがprocessChild.jsになりました。

ここで、--maxWorkersを指定してみましょう。2つのプロセスにしてみます。

$ npx jest --maxWorkers=2

test1.test.tsとtest3.test.tsが同じプロセス(Jestワーカー)で実行されるようになりました。

 PASS  test/test3.test.ts
  ● Console

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19245, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:7:11)

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19245, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:13:11)

 PASS  test/test2.test.ts
  ● Console

    console.log
      [test2.test.ts] jest worker id = 2, pid = 19246, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:7:11)

    console.log
      [test2.test.ts] jest worker id = 2, pid = 19246, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:13:11)

 PASS  test/test1.test.ts
  ● Console

    console.log
      [test1.test.ts] jest worker id = 1, pid = 19245, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:7:11)

    console.log
      [test1.test.ts] jest worker id = 1, pid = 19245, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:13:11)


Test Suites: 3 passed, 3 total
Tests:       6 passed, 6 total
Snapshots:   0 total
Time:        8.703 s
Ran all test suites.

実行時間としても、2倍(ひとつはシーケンシャルだから)になっています。

今度は、--runInBandを指定してみましょう。

$ npx jest --runInBand

完全にシーケンシャルになりましたね。

$ npx jest --runInBand
 PASS  test/test2.test.ts
  ● Console

    console.log
      [test2.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test2.test.ts:7:11)

    console.log
      [test2.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test2.test.ts:13:11)

 PASS  test/test3.test.ts
  ● Console

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test3.test.ts:7:11)

    console.log
      [test3.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test3.test.ts:13:11)

 PASS  test/test1.test.ts
  ● Console

    console.log
      [test1.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test1.test.ts:7:11)

    console.log
      [test1.test.ts] jest worker id = 1, pid = 19341, path = node_modules/.bin/jest

      at Object.<anonymous> (test/test1.test.ts:13:11)


Test Suites: 3 passed, 3 total
Tests:       6 passed, 6 total
Snapshots:   0 total
Time:        12.605 s, estimated 13 s
Ran all test suites.

これで、基本的な動作は確認できたかなと思います。

デフォルト値を確認する

デフォルト値も確認してみましょう。デフォルトでは、CPU数から1引いた数のワーカー数になるという話でした。

今回の動作環境のCPU数は8なので、8ファイル用意するとひとつだけ同じプロセスになって実行時間が2倍になるはずですね。

ファイルを増やしてみます。

$ for ((i=4; i < 9; i++)) do cp test/test1.test.ts test/test${i}.test.ts; done
$ ls -1 test
test1.test.ts
test2.test.ts
test3.test.ts
test4.test.ts
test5.test.ts
test6.test.ts
test7.test.ts
test8.test.ts

確認。

$ npx jest

結果。

$ npx jest
 PASS  test/test1.test.ts
  ● Console

    console.log
      [test1.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:7:11)

    console.log
      [test1.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:13:11)

 PASS  test/test2.test.ts
  ● Console

    console.log
      [test2.test.ts] jest worker id = 7, pid = 20099, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:7:11)

    console.log
      [test2.test.ts] jest worker id = 7, pid = 20099, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test2.test.ts:13:11)

 PASS  test/test6.test.ts
  ● Console

    console.log
      [test6.test.ts] jest worker id = 3, pid = 20056, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test6.test.ts:7:11)

    console.log
      [test6.test.ts] jest worker id = 3, pid = 20056, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test6.test.ts:13:11)

 PASS  test/test7.test.ts
  ● Console

    console.log
      [test7.test.ts] jest worker id = 2, pid = 20055, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test7.test.ts:7:11)

    console.log
      [test7.test.ts] jest worker id = 2, pid = 20055, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test7.test.ts:13:11)

 PASS  test/test8.test.ts
  ● Console

    console.log
      [test8.test.ts] jest worker id = 1, pid = 20054, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test8.test.ts:7:11)

    console.log
      [test8.test.ts] jest worker id = 1, pid = 20054, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test8.test.ts:13:11)

 PASS  test/test4.test.ts
  ● Console

    console.log
      [test4.test.ts] jest worker id = 5, pid = 20074, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test4.test.ts:7:11)

    console.log
      [test4.test.ts] jest worker id = 5, pid = 20074, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test4.test.ts:13:11)

 PASS  test/test5.test.ts
  ● Console

    console.log
      [test5.test.ts] jest worker id = 4, pid = 20068, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test5.test.ts:7:11)

    console.log
      [test5.test.ts] jest worker id = 4, pid = 20068, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test5.test.ts:13:11)

 PASS  test/test3.test.ts
  ● Console

    console.log
      [test3.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:7:11)

    console.log
      [test3.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:13:11)


Test Suites: 8 passed, 8 total
Tests:       16 passed, 16 total
Snapshots:   0 total
Time:        9.143 s
Ran all test suites.

今回は、test1.test.tsとtest3.test.tsが同じワーカーになりました。

 PASS  test/test1.test.ts
  ● Console

    console.log
      [test1.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:7:11)

    console.log
      [test1.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test1.test.ts:13:11)


 PASS  test/test3.test.ts
  ● Console

    console.log
      [test3.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:7:11)

    console.log
      [test3.test.ts] jest worker id = 6, pid = 20083, path = node_modules/jest-worker/build/workers/processChild.js

      at Object.<anonymous> (test/test3.test.ts:13:11)

ソースコードから確認してみる

ソースコードも少し見てみましょう。

ワーカー数のデフォルト値を決めているのは、このあたりのようですね。

https://github.com/jestjs/jest/blob/v29.7.0/packages/jest-repl/src/cli/runtime-cli.ts#L83

--watchでCPU数の半分になるというのは、こちらですね。

https://github.com/jestjs/jest/blob/v29.7.0/packages/jest-config/src/getMaxWorkers.ts#L38

--maxWorkersや--runInBandの解釈はこのあたりです。

https://github.com/jestjs/jest/blob/v29.7.0/packages/jest-config/src/getMaxWorkers.ts#L27-L32

こう見ると、--runInBandと--maxWorkers=1が同義なこともわかりますね。

ワーカーによるテストの実行はこちら。

https://github.com/jestjs/jest/blob/v29.7.0/packages/jest-runner/src/testWorker.ts#L88-L108

そこからテストコードを読み込んで実行しているのは、このあたりですね。

jest/packages/jest-runner/src/runTest.ts at v29.7.0 · jestjs/jest · GitHub

今回は見ていませんが、テストの並行実行についてはこのあたりを見るとよさそうです。

https://github.com/jestjs/jest/blob/v29.7.0/packages/jest-circus/src/run.ts#L137-L158

おわりに

CPU数次第ですが、Jestでテストが並列に実行されることを確認してみました。

遊んでいる時はファイル数が少なかったり、あまり意識したりしていなかったので、あらためて見返してメモ的に書いておきました。
こうすると思い出しやすいでしょう、的な。

それにしても、こういう動作だとデータベースといった、共有リソースの操作には気をつけないといけないということですね。