Spring Boot 3.4.1 CRaC checkpoint on refresh-error

[smoell]

Hi,

I ran into an issue with Spring Boot 3.4.1 and CRaC if I want to generate the snapshot, spring.datasource.hikari.allow-pool-suspension=true is set in application.properties.

java -Dspring.context.checkpoint=onRefresh -Dspring.profiles.active=prod -Djdk.crac.collect-fd-stacktraces=true -XX:CPUFeatures=0x214e1805ddfbff,0x3e6 -XX:CRaCCheckpointTo=/opt/crac-files/ -jar /store-spring.jar

Starting the application...

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::                (v3.4.1)

2024-12-29T19:00:28.803Z  INFO 129 --- [           main] com.unicorn.store.StoreApplication       : Starting StoreApplication v1.0.0 using Java 21.0.5 with PID 129 (/store-spring.jar started by root in /)
2024-12-29T19:00:28.808Z  INFO 129 --- [           main] com.unicorn.store.StoreApplication       : The following 1 profile is active: "prod"
2024-12-29T19:00:31.493Z  INFO 129 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2024-12-29T19:00:31.601Z  INFO 129 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 90 ms. Found 1 JPA repository interface.
2024-12-29T19:00:33.090Z  INFO 129 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port 8080 (http)
2024-12-29T19:00:33.116Z  INFO 129 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2024-12-29T19:00:33.117Z  INFO 129 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.34]
2024-12-29T19:00:33.168Z  INFO 129 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2024-12-29T19:00:33.170Z  INFO 129 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 4241 ms
2024-12-29T19:00:33.748Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2024-12-29T19:00:34.556Z  INFO 129 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4228f269
2024-12-29T19:00:34.558Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2024-12-29T19:00:34.717Z  INFO 129 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2024-12-29T19:00:34.801Z  INFO 129 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 6.6.4.Final
2024-12-29T19:00:34.866Z  INFO 129 --- [           main] o.h.c.internal.RegionFactoryInitiator    : HHH000026: Second-level cache disabled
2024-12-29T19:00:35.238Z  INFO 129 --- [           main] o.s.o.j.p.SpringPersistenceUnitInfo      : No LoadTimeWeaver setup: ignoring JPA class transformer
2024-12-29T19:00:35.260Z  WARN 129 --- [           main] org.hibernate.orm.deprecation            : HHH90000021: Encountered deprecated setting [hibernate.temp.use_jdbc_metadata_defaults], use [hibernate.boot.allow_jdbc_metadata_access] instead
2024-12-29T19:00:35.298Z  WARN 129 --- [           main] org.hibernate.orm.deprecation            : HHH90000025: PostgreSQLDialect does not need to be specified explicitly using 'hibernate.dialect' (remove the property setting and it will be selected by default)
2024-12-29T19:00:35.321Z  INFO 129 --- [           main] org.hibernate.orm.connections.pooling    : HHH10001005: Database info:
        Database JDBC URL [undefined/unknown]
        Database driver: undefined/unknown
        Database version: 12.0
        Autocommit mode: undefined/unknown
        Isolation level: <unknown>
        Minimum pool size: undefined/unknown
        Maximum pool size: undefined/unknown
2024-12-29T19:00:36.502Z  INFO 129 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000489: No JTA platform available (set 'hibernate.transaction.jta.platform' to enable JTA platform integration)
2024-12-29T19:00:36.510Z  INFO 129 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2024-12-29T19:00:37.004Z  INFO 129 --- [           main] c.unicorn.store.data.UnicornPublisher    : Creating EventBridgeAsyncClient
2024-12-29T19:00:39.483Z  INFO 129 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint beneath base path '/actuator'
2024-12-29T19:00:39.616Z  INFO 129 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Triggering JVM checkpoint/restore
2024-12-29T19:00:39.618Z  INFO 129 --- [           main] jdk.crac                                 : Starting checkpoint
2024-12-29T19:00:39.639Z  INFO 129 --- [           main] c.unicorn.store.data.UnicornPublisher    : Executing beforeCheckpoint...
2024-12-29T19:00:39.639Z  INFO 129 --- [           main] c.unicorn.store.data.UnicornPublisher    : Closing EventBridgeAsyncClient
2024-12-29T19:00:41.689Z  INFO 129 --- [           main] jdk.crac                                 : /store-spring.jar is recorded as always available on restore
2024-12-29T19:00:42.041Z  INFO 129 --- [           main] c.unicorn.store.data.UnicornPublisher    : Executing afterRestore ...
2024-12-29T19:00:42.041Z  INFO 129 --- [           main] c.unicorn.store.data.UnicornPublisher    : Creating EventBridgeAsyncClient
2024-12-29T19:00:42.055Z  INFO 129 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Restarting Spring-managed lifecycle beans after JVM restore
2024-12-29T19:00:42.063Z  INFO 129 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Spring-managed lifecycle restart completed (restored JVM running for -1 ms)
2024-12-29T19:00:42.064Z  WARN 129 --- [           main] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.context.ApplicationContextException: Failed to take CRaC checkpoint on refresh
2024-12-29T19:00:42.074Z  INFO 129 --- [           main] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2024-12-29T19:00:42.091Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2024-12-29T19:00:42.104Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
2024-12-29T19:00:42.118Z  INFO 129 --- [           main] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2024-12-29T19:00:42.195Z  INFO 129 --- [           main] .s.b.a.l.ConditionEvaluationReportLogger : 

Error starting ApplicationContext. To display the condition evaluation report re-run your application with 'debug' enabled.
2024-12-29T19:00:42.254Z ERROR 129 --- [           main] o.s.boot.SpringApplication               : Application run failed

org.springframework.context.ApplicationContextException: Failed to take CRaC checkpoint on refresh
        at org.springframework.context.support.DefaultLifecycleProcessor$CracDelegate.checkpointRestore(DefaultLifecycleProcessor.java:577) ~[spring-context-6.2.1.jar!/:6.2.1]
        at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:232) ~[spring-context-6.2.1.jar!/:6.2.1]
        at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:1006) ~[spring-context-6.2.1.jar!/:6.2.1]
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:630) ~[spring-context-6.2.1.jar!/:6.2.1]
        at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:146) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:752) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:439) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:318) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1361) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1350) ~[spring-boot-3.4.1.jar!/:3.4.1]
        at com.unicorn.store.StoreApplication.main(StoreApplication.java:13) ~[!/:1.0.0]
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
        at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:102) ~[store-spring.jar:1.0.0]
        at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:64) ~[store-spring.jar:1.0.0]
        at org.springframework.boot.loader.launch.JarLauncher.main(JarLauncher.java:40) ~[store-spring.jar:1.0.0]
Caused by: org.crac.CheckpointException: null
        at org.crac.Core$Compat.checkpointRestore(Core.java:144) ~[crac-1.4.0.jar!/:na]
        at org.crac.Core.checkpointRestore(Core.java:237) ~[crac-1.4.0.jar!/:na]
        at org.springframework.context.support.DefaultLifecycleProcessor$CracDelegate.checkpointRestore(DefaultLifecycleProcessor.java:571) ~[spring-context-6.2.1.jar!/:6.2.1]
        ... 15 common frames omitted
        Suppressed: jdk.internal.crac.mirror.impl.CheckpointOpenSocketException: Socket[addr=unicornstore-db-cluster.cluster-cfayusec6hfg.eu-west-1.rds.amazonaws.com/10.0.3.89,port=5432,localport=41588]
                at java.base/jdk.internal.crac.JDKSocketResourceBase.lambda$beforeCheckpoint$0(JDKSocketResourceBase.java:68) ~[na:na]
                at java.base/jdk.internal.crac.mirror.Core.checkpointRestore1(Core.java:170) ~[na:na]
                at java.base/jdk.internal.crac.mirror.Core.checkpointRestore(Core.java:315) ~[na:na]
                at java.base/jdk.internal.crac.mirror.Core.checkpointRestore(Core.java:294) ~[na:na]
                at jdk.crac/jdk.crac.Core.checkpointRestore(Core.java:72) ~[na:na]
                at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
                at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
                at org.crac.Core$Compat.checkpointRestore(Core.java:141) ~[crac-1.4.0.jar!/:na]
                ... 17 common frames omitted
        Caused by: java.lang.Exception: This file descriptor was created by main at epoch:1735498833816 here
                at java.base/jdk.internal.crac.JDKFdResource.<init>(JDKFdResource.java:60)
                at java.base/jdk.internal.crac.JDKSocketResourceBase.<init>(JDKSocketResourceBase.java:44)
                at java.base/jdk.internal.crac.JDKSocketResource.<init>(JDKSocketResource.java:38)
                at java.base/java.net.SocketImpl$1.<init>(SocketImpl.java:78)
                at java.base/java.net.SocketImpl.<init>(SocketImpl.java:77)
                at java.base/sun.nio.ch.NioSocketImpl.<init>(NioSocketImpl.java:139)
                at java.base/java.net.SocketImpl.createPlatformSocketImpl(SocketImpl.java:54)
                at java.base/java.net.Socket.createImpl(Socket.java:583)
                at java.base/java.net.Socket.<init>(Socket.java:189)
                at java.base/javax.net.DefaultSocketFactory.createSocket(SocketFactory.java:261)
                at org.postgresql.core.PGStream.createSocket(PGStream.java:248)
                at org.postgresql.core.PGStream.<init>(PGStream.java:121)
                at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:140)
                at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:268)
                at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
                at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:273)
                at org.postgresql.Driver.makeConnection(Driver.java:446)
                at org.postgresql.Driver.connect(Driver.java:298)
                at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:137)
                at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
                at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
                at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
                at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:550)
                at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:98)
                at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:111)
                at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:160)
                at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:118)
                at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:81)
                at org.springframework.jdbc.datasource.init.DatabasePopulatorUtils.execute(DatabasePopulatorUtils.java:52)
                at org.springframework.boot.jdbc.init.DataSourceScriptDatabaseInitializer.runScripts(DataSourceScriptDatabaseInitializer.java:87)
                at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.runScripts(AbstractScriptDatabaseInitializer.java:146)
                at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.applyScripts(AbstractScriptDatabaseInitializer.java:108)
                at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.applySchemaScripts(AbstractScriptDatabaseInitializer.java:98)
                at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.initializeDatabase(AbstractScriptDatabaseInitializer.java:76)
                at org.springframework.boot.sql.init.AbstractScriptDatabaseInitializer.afterPropertiesSet(AbstractScriptDatabaseInitializer.java:66)
                at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1855)
                at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1804)
                at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:601)
                at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:523)
                at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:336)
                at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:289)
                at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:334)
                at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)
                at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:312)
                at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:204)
                at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:970)
                at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:627)
                ... 12 common frames omitted

[sdeleuze]

Hi, database initialization is performed very early (by design) in the Spring Lifecycle, so even if you configure pool suspension at Hikari level, I suspect HikariCheckpointRestoreLifecycle is not invoked. You may be able to workaround by customizing the configuration to avoid early database interaction, see this related documentation.

@snicoll I think this use case is not supported yet. If you agree that issue should be discussed on Spring Boot side where are triggered the database initialization and where live HikariCheckpointRestoreLifecycle, could you please move that issue?

[smoell]

Hey,

I've added the config to my application.properties (see below), but it doesn't have an effect. This is weird, because before 3.4.x, it worked like a charm.

spring.sql.init.mode=never
spring.datasource.username=postgres
spring.jpa.database-platform=org.hibernate.dialect.PostgreSQLDialect
server.error.include-message=always
spring.jpa.open-in-view=false
spring.datasource.hikari.maximumPoolSize=1
spring.datasource.hikari.data-source-properties.preparedStatementCacheQueries=0
management.endpoint.health.probes.enabled=true

# Disable Hibernate usage of JDBC metadata
spring.jpa.properties.hibernate.temp.use_jdbc_metadata_defaults=false
spring.jpa.properties.hibernate.boot.allow_jdbc_metadata_access=false

# Database initialization will typically be performed outside of Spring lifecycle
spring.jpa.hibernate.ddl-auto=none
spring.datasource.hikari.allow-pool-suspension=true

# Enable virtual threads
spring.threads.virtual.enabled=true

[snicoll]

This is weird, because before 3.4.x, it worked like a charm.

That would have been an interesting information to share in the original report. Can you provide a small sample we can run ourselves that work with 3.3.x and fail when upgraded to 3.4.x? You can attach a zip to this issue or push the code to a GitHub repository.

[sdeleuze]

Yeah please add a repro, I am surprised to see a stacktrace involving a database initialization with spring.sql.init.mode=never.

[smoell]

Sure, I'll push two different versions in one repo.

[smoell]

I found the issue: old application.properties file in the JAR, rebuild helped, sorry :(