HikariCheckpointRestoreLifecycle - new connection opened immediately after stop() #42906
Closed as not planned
Description
Despite the open issue brettwooldridge/HikariCP#2082 I had the feeling HikariCheckpointRestoreLifecycle would properly close all connections. It turned out though that a new connection is opened directly:
| 1730117809191 | 2024-10-28T12:16:49.191Z INFO 8 --- [ Thread-0] o.s.boot.SpringApplication : Started application in 7.355 seconds (process running for 7.877) |
| 1730117809192 | 2024-10-28T12:16:49.192Z DEBUG 8 --- [ Thread-0] o.s.b.a.ApplicationAvailabilityBean : Application availability state LivenessState changed to CORRECT |
| 1730117809194 | 2024-10-28T12:16:49.194Z DEBUG 8 --- [ Thread-0] o.s.b.a.ApplicationAvailabilityBean : Application availability state ReadinessState changed to ACCEPTING_TRAFFIC |
| 1730117809194 | 2024-10-28T12:16:49.194Z INFO 8 --- [ Thread-0] o.s.c.f.serverless.web.ServerlessMVC : Application is started successfully. |
| 1730117809198 | 2024-10-28T12:16:49.198Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping Spring-managed lifecycle beans before JVM checkpoint |
| 1730117809199 | 2024-10-28T12:16:49.199Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147483647 |
| 1730117809199 | 2024-10-28T12:16:49.199Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Bean 'applicationTaskExecutor' completed its stop procedure |
| 1730117809199 | 2024-10-28T12:16:49.199Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147482623 |
| 1730117809200 | 2024-10-28T12:16:49.200Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerGracefulShutdown' completed its stop procedure |
| 1730117809200 | 2024-10-28T12:16:49.200Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147481599 |
| 1730117809200 | 2024-10-28T12:16:49.200Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerStartStop' completed its stop procedure |
| 1730117809201 | 2024-10-28T12:16:49.200Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 0 |
| 1730117809201 | 2024-10-28T12:16:49.201Z INFO 8 --- [ main] o.s.b.j.HikariCheckpointRestoreLifecycle : Evicting Hikari connections |
| 1730117809201 | 2024-10-28T12:16:49.201Z DEBUG 8 --- [ main] o.s.b.j.HikariCheckpointRestoreLifecycle : Waiting for Hikari connections to be closed |
| 1730117809201 | 2024-10-28T12:16:49.201Z DEBUG 8 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@437d822b: (connection evicted) |
| 1730117809205 | 2024-10-28T12:16:49.205Z DEBUG 8 --- [onnection adder] org.postgresql.Driver : Connecting with URL: jdbc:postgresql://XXX.us-west-2.rds.amazonaws.com:5432/db |
| 1730117809205 | 2024-10-28T12:16:49.205Z DEBUG 8 --- [onnection adder] org.postgresql.jdbc.PgConnection : PostgreSQL JDBC Driver 42.7.4 |
| 1730117809206 | 2024-10-28T12:16:49.206Z DEBUG 8 --- [onnection adder] org.postgresql.jdbc.PgConnection : setDefaultFetchSize = 0 |
| 1730117809206 | 2024-10-28T12:16:49.206Z DEBUG 8 --- [onnection adder] org.postgresql.jdbc.PgConnection : setPrepareThreshold = 5 |
| 1730117809206 | 2024-10-28T12:16:49.206Z DEBUG 8 --- [onnection adder] o.p.core.v3.ConnectionFactoryImpl : Trying to establish a protocol version 3 connection to XXX.us-west-2.rds.amazonaws.com:5432 |
| 1730117809208 | 2024-10-28T12:16:49.208Z DEBUG 8 --- [onnection adder] o.p.core.v3.ConnectionFactoryImpl : Receive Buffer Size is 65,536 |
| 1730117809208 | 2024-10-28T12:16:49.208Z DEBUG 8 --- [onnection adder] o.p.core.v3.ConnectionFactoryImpl : Send Buffer Size is 23,040 |
| 1730117809209 | 2024-10-28T12:16:49.209Z DEBUG 8 --- [onnection adder] org.postgresql.ssl.MakeSSL : converting regular socket connection to ssl |
| 1730117809240 | 2024-10-28T12:16:49.239Z DEBUG 8 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@93242be |
| 1730117809256 | 2024-10-28T12:16:49.255Z DEBUG 8 --- [ main] o.s.b.j.HikariCheckpointRestoreLifecycle : Hikari connections closed |
| 1730117809256 | 2024-10-28T12:16:49.256Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Successfully stopped bean 'hikariCheckpointRestoreLifecycle' |
| 1730117809256 | 2024-10-28T12:16:49.256Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase -2147483647 |
| 1730117809256 | 2024-10-28T12:16:49.256Z DEBUG 8 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Bean 'springBootLoggingLifecycle' completed its stop procedure |
This results in stale connections being part of the snapshot as indicated by the warning:
| 1730117777239 | 2024-10-28T12:16:17.239Z WARN 8 --- [ main] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@7c133b76 (This connection has been closed.). Possibly consider using a shorter maxLifetime value. |
| 1730117777240 | 2024-10-28T12:16:17.240Z DEBUG 8 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@7c133b76: (connection is dead) |
| 1730117777286 | 2024-10-28T12:16:17.286Z DEBUG 8 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@72d4da84 |
Is there a way to influence this behavior on the Spring Boot end? If not it should be at least mentioned somewhere (maybe on https://docs.spring.io/spring-boot/reference/packaging/checkpoint-restore.html).