SpringアプリのテストでHikariDataSource has been closedなどと言われたのでなんとかした
TL; DR
- Springのテスト時に使われるコンテキストキャッシュ
DefaultContextCache
はデフォルトの保持数が32で、それを超えると古いコンテキストが破棄される。そのときにDBのコネクションプールも破棄されてしまって困る。 - キャッシュの保持数はSpringのプロパティ
spring.test.context.cache.maxSize
で設定できる。
環境
- Spring Boot (spring-boot-starter 2.4.4)
- spring-framework 5.3.5
- HikariCP 3.4.5
- AdoptOpenJDK 16.0.1
- IntelliJ IDEA 2021.2 (Ultimate)
本題
なにごと?
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 */)); }
どうやらDataSourceが閉じられる際には、ここを通っているらしい。 IntelliJ IDEAで上記メソッドにブレークポイントを仕掛けて、コールスタックを追ってみる。
最初の HikariPool#shutdown
, HikariDataSource#close
は正常なコネクションプール終了処理であり、特に気になる部分は無し。
そのまま順番に追っていくと、DefaultContextCache.LruCache#removeEldestEntry
で DefaultContextCache.this.remove(〜)
しているところが見つかる。
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); // ←これ }
DefaultContextCacheはspring-testでのテストの際にアプリケーションコンテキストのキャッシュを保持するクラスで、LruCacheはその内部クラス。
LRUっていうぐらいだし、キャッシュがいっぱいになったら古いものを削除するんだろうなと想像できる。実際、削除処理の条件も if (this.size() > DefaultContextCache.this.getMaxSize())
だし。
キャッシュ保持数はデフォルトで32の様子*1。 このことから、以下のような事象が起こっていると考えられる。
- テスト実行時に、アプリケーションコンテキストが
DefaultContextCache
に格納される。32番目のテストまでは、問題なく実行される。 - 33番目のテストの際、アプリケーションコンテキストを
DefaultContextCache
に格納しようとすると、キャッシュ保持数の最大値を超えているため、古いアプリケーションコンテキストが削除される。 - アプリケーションコンテキストが削除されると、それに紐づくDBのコネクションプールがクローズされる。
- 33番目のテストでDBに接続しようとすると、3.で閉じられたコネクションプールが使われてしまい、エラーとなる。
キャッシュから削除されないようにキャッシュ保持数の最大値を大きくすれば、ひとまずは解消できそう。
DefaultContextCache
のドキュメントによると、この最大値はプロパティ spring.test.context.cache.maxSize
で変更できるらしい。
最大サイズは、コンストラクターの引数として指定するか、システムプロパティまたは spring.test.context.cache.maxSize という Spring プロパティを介して設定できます。
application.yaml
で設定したり、実行時引数で指定したりすればOK。
# application.yaml spring.test.context.cache.maxSize: 128
$ mvn test -Dspring.test.context.cache.maxSize=128
とはいえ、これだとコンテキストが破棄されないのでリソース消費が気になる…。本当はもうちょっとまともな対応方法がほしいところではあるけど、まぁテストだしこれでいいことにする。
まとめ
つかれた。