SpringアプリのテストでHikariDataSource has been closedなどと言われたのでなんとかした

TL; DR

  • Springのテスト時に使われるコンテキストキャッシュ DefaultContextCache はデフォルトの保持数が32で、それを超えると古いコンテキストが破棄される。そのときにDBのコネクションプールも破棄されてしまって困る。
  • キャッシュの保持数はSpringのプロパティspring.test.context.cache.maxSize で設定できる。

環境

本題

なにごと?

JUnitでSpring Bootアプリのテストをゴリゴリ追加していたところ、いきなりエラーが。

logger:o.s.b.w.embedded.tomcat.TomcatWebServer  LEVEL:INFO  thread:main msg:Tomcat started on port(s): 52394 (http) with context path ''
logger:xxx.xxx.XxxTest                          LEVEL:INFO  thread:main msg:Started XxxTest in 1.134 seconds (JVM running for 65.714)
logger:o.s.s.concurrent.ThreadPoolTaskExecutor  LEVEL:INFO  thread:main msg:Shutting down ExecutorService 'applicationTaskExecutor'
logger:com.zaxxer.hikari.HikariDataSource       LEVEL:INFO  thread:main msg:HikariPool-1 - Shutdown initiated...
logger:com.zaxxer.hikari.HikariDataSource       LEVEL:INFO  thread:main msg:HikariPool-1 - Shutdown completed.
logger:o.s.test.context.TestContextManager      LEVEL:WARN  thread:main msg:Caught exception while invoking 'beforeTestMethod' callback on TestExecutionListener [org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener@347d1586] for test method [com.intuit.karate.junit5.Karate xxx.xxx.XxxTest.testXxx()] and test instance [xxx.xxx.XxxTest.testXxx@5e462cc]
org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: HikariDataSource HikariDataSource (HikariPool-1) has been closed.
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:309)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)

下記の行に注目。DBへのコネクションを開始しようとしたのにDataSourceが閉じられてしまっているのでエラー、ということらしい。

Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: HikariDataSource HikariDataSource (HikariPool-1) has been closed.

DataSourceが勝手に閉じられるのはよろしくないので、なぜ閉じられているのかを調べることにする。

調べてみる

HikariCPで何か起こっているということはわかったので、HikariCPのログレベルを debug に変更し、ログの情報量を増やしてみる。

application.yamlを下記のように設定して再度テストを実行。

logging:
  level:
    com.zaxxer.hikari: debug

そうすると、テスト開始時にDBとのコネクションが閉じられている様子が表示される。(connection evicted) ですって。

logger:o.s.b.w.embedded.tomcat.TomcatWebServer  LEVEL:INFO  thread:main msg:Tomcat started on port(s): 54354 (http) with context path ''
logger:xxx.xxx.XxxTest    LEVEL:INFO  thread:main msg:Started XxxTest in 1.068 seconds (JVM running for 64.084)
logger:o.s.s.concurrent.ThreadPoolTaskExecutor  LEVEL:INFO  thread:main msg:Shutting down ExecutorService 'applicationTaskExecutor'
logger:com.zaxxer.hikari.HikariDataSource       LEVEL:INFO  thread:main msg:HikariPool-1 - Shutdown initiated...
logger:com.zaxxer.hikari.pool.HikariPool        LEVEL:DEBUG thread:main msg:HikariPool-1 - Before shutdown stats (total=10, active=0, idle=10, waiting=0)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@36d7a68a: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@1eeacb6e: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@102d26c3: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@1412a01e: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@51102cf8: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@19692c0f: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@600b1adf: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@61984490: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@313fd3b7: (connection evicted)
logger:com.zaxxer.hikari.pool.PoolBase          LEVEL:DEBUG thread:HikariPool-1 connection closer msg:HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@61e698cb: (connection evicted)
logger:com.zaxxer.hikari.pool.HikariPool        LEVEL:DEBUG thread:main msg:HikariPool-1 - After shutdown stats (total=0, active=0, idle=0, waiting=0)
logger:com.zaxxer.hikari.HikariDataSource       LEVEL:INFO  thread:main msg:HikariPool-1 - Shutdown completed.
logger:o.s.test.context.TestContextManager      LEVEL:WARN  thread:main msg:Caught exception while invoking 'beforeTestMethod' callback on TestExecutionListener [org.springframework.test.context.jdbc.SqlScriptsTestExe
cutionListener@7ef7161d] for test method [com.intuit.karate.junit5.Karate xxx.xxx.XxxTest.testXxx()] and test instance [xxx.xxx.XxxTest@55b5625d]
org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: HikariDataSource HikariDataSource (HikariPool-1) has been closed.
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:309)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)

HikariCPのソースコード内を (connection evicted) で検索すると、HikariPool の下記のメソッドが見つかる。

public final class HikariPool extends PoolBase implements HikariPoolMXBean, IBagStateListener
{
   // 中略
   /** {@inheritDoc} */
   @Override
   public void softEvictConnections()
   {
      connectionBag.values().forEach(poolEntry -> softEvictConnection(poolEntry, "(connection evicted)", false /* not owner */));
   }

https://github.com/brettwooldridge/HikariCP/blob/ed2da5f1f4ef19f871fac12effc0b199706905dc/src/main/java/com/zaxxer/hikari/pool/HikariPool.java#L375

どうやらDataSourceが閉じられる際には、ここを通っているらしい。 IntelliJ IDEAで上記メソッドにブレークポイントを仕掛けて、コールスタックを追ってみる。

f:id:ser1zw:20210806023511p:plain

最初の HikariPool#shutdown, HikariDataSource#close は正常なコネクションプール終了処理であり、特に気になる部分は無し。

そのまま順番に追っていくと、DefaultContextCache.LruCache#removeEldestEntryDefaultContextCache.this.remove(〜) しているところが見つかる。

f:id:ser1zw:20210806022737p:plain

public class DefaultContextCache implements ContextCache {
    // 中略
    private class LruCache extends LinkedHashMap<MergedContextConfiguration, ApplicationContext> {
        LruCache(int initialCapacity, float loadFactor) {
            super(initialCapacity, loadFactor, true);
        }

        protected boolean removeEldestEntry(Entry<MergedContextConfiguration, ApplicationContext> eldest) {
            if (this.size() > DefaultContextCache.this.getMaxSize()) {
                DefaultContextCache.this.remove((MergedContextConfiguration)eldest.getKey(), HierarchyMode.CURRENT_LEVEL); // ←これ
            }

https://github.com/spring-projects/spring-framework/blob/7c2a72c9b43d066ae9e71d4f39d7bab8f6d9c2ff/spring-test/src/main/java/org/springframework/test/context/cache/DefaultContextCache.java#L337

DefaultContextCacheはspring-testでのテストの際にアプリケーションコンテキストのキャッシュを保持するクラスで、LruCacheはその内部クラス。 LRUっていうぐらいだし、キャッシュがいっぱいになったら古いものを削除するんだろうなと想像できる。実際、削除処理の条件も if (this.size() > DefaultContextCache.this.getMaxSize()) だし。

キャッシュ保持数はデフォルトで32の様子*1。 このことから、以下のような事象が起こっていると考えられる。

  1. テスト実行時に、アプリケーションコンテキストが DefaultContextCache に格納される。32番目のテストまでは、問題なく実行される。
  2. 33番目のテストの際、アプリケーションコンテキストを DefaultContextCache に格納しようとすると、キャッシュ保持数の最大値を超えているため、古いアプリケーションコンテキストが削除される。
  3. アプリケーションコンテキストが削除されると、それに紐づくDBのコネクションプールがクローズされる。
  4. 33番目のテストでDBに接続しようとすると、3.で閉じられたコネクションプールが使われてしまい、エラーとなる。

キャッシュから削除されないようにキャッシュ保持数の最大値を大きくすれば、ひとまずは解消できそう。 DefaultContextCache のドキュメントによると、この最大値はプロパティ spring.test.context.cache.maxSize で変更できるらしい。

最大サイズは、コンストラクターの引数として指定するか、システムプロパティまたは spring.test.context.cache.maxSize という Spring プロパティを介して設定できます。

spring.pleiades.io

application.yaml で設定したり、実行時引数で指定したりすればOK。

# application.yaml
spring.test.context.cache.maxSize: 128
$ mvn test -Dspring.test.context.cache.maxSize=128

とはいえ、これだとコンテキストが破棄されないのでリソース消費が気になる…。本当はもうちょっとまともな対応方法がほしいところではあるけど、まぁテストだしこれでいいことにする。

まとめ

つかれた。

*1:DefaultContextCacheのコンストラクタにブレークポイントを仕掛けてmaxSizeの値を確認した