search

spring-projects / spring-boot

Spring Boot helps you to create Spring-powered, production-grade applications and services with absolute minimum fuss.
https://spring.io/projects/spring-boot
Apache License 2.0
75.46k stars 40.76k forks source link

HikariCheckpointRestoreLifecycle - new connection opened immediately after stop() #42906

Closed deki closed 1 month ago

deki commented 1 month ago

Despite the open issue https://github.com/brettwooldridge/HikariCP/issues/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).

snicoll commented 1 month ago

It turned out though that a new connection is opened directly:

This seems to be the case in your setup but it's impossible for us to know why based on those logs. Can you please share a small sample we can use to reproduce the problem?

deki commented 1 month ago

Sure will try to narrow it down and share a reproducer...

deki commented 1 month ago

Figured out that allow-pool-suspension=true is required for it to work. Improve the logging but this should be probably an exception.

snicoll commented 1 month ago

Thanks for the PR, let's continue the discussion there.

Closing in favor of https://github.com/spring-projects/spring-boot/pull/42937.