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
Comment From: 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?
Comment From: 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
Comment From: 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.
Comment From: sdeleuze
Yeah please add a repro, I am surprised to see a stacktrace involving a database initialization with spring.sql.init.mode=never.
Comment From: smoell
Sure, I'll push two different versions in one repo.
Comment From: smoell
I found the issue: old application.properties file in the JAR, rebuild helped, sorry :(