• spring-boot version: 3.2.0, 3.2.2, 3.3.0-M1
  • spring version: 6.1.1
  • azul version: zulu21.32.17-ca-crac-jdk21.0.2-linux_aarch64.tar.gz
  • profile: default, postgres

I'm unable to successfully perform Checkpoint-Restore with PetClinic. Seems like Spring cannot close the DB connection for the checkpoint moment. spring-data-jpa is covered for checkpoint-restore according to https://github.com/spring-projects/spring-lifecycle-smoke-tests/blob/main/STATUS.adoc

Reproduce: - Copy checkpoint restore related files from https://github.com/sdeleuze/spring-boot-crac-demo to PetClinic - extend delay before checkpoint (entrypoint.sh)

    sleep 15
    jcmd /opt/app/spring-boot-crac-demo-1.0.0-SNAPSHOT.jar JDK.checkpoint
  • extend delay before killing checkpoint container (checkpoint.sh)
    sleep 60
    docker commit --change='ENTRYPOINT ["/opt/app/entrypoint.sh"]' $(docker ps -qf "name=spring-boot-crac-demo") sdeleuze/spring-boot-crac-demo:checkpoint
    docker kill $(docker ps -qf "name=spring-boot-crac-demo")

2024-01-23 10:22:16 
2024-01-23 10:22:16 
2024-01-23 10:22:16               |\      _,,,--,,_
2024-01-23 10:22:16              /,`.-'`'   ._  \-;;,_
2024-01-23 10:22:16   _______ __|,4-  ) )_   .;.(__`'-'__     ___ __    _ ___ _______
2024-01-23 10:22:16  |       | '---''(_/._)-'(_\_)   |   |   |   |  |  | |   |       |
2024-01-23 10:22:16  |    _  |    ___|_     _|       |   |   |   |   |_| |   |       | __ _ _
2024-01-23 10:22:16  |   |_| |   |___  |   | |       |   |   |   |       |   |       | \ \ \ \
2024-01-23 10:22:16  |    ___|    ___| |   | |      _|   |___|   |  _    |   |      _|  \ \ \ \
2024-01-23 10:22:16  |   |   |   |___  |   | |     |_|       |   | | |   |   |     |_    ) ) ) )
2024-01-23 10:22:16  |___|   |_______| |___| |_______|_______|___|_|  |__|___|_______|  / / / /
2024-01-23 10:22:16  ==================================================================/_/_/_/
2024-01-23 10:22:16 
2024-01-23 10:22:16 :: Built with Spring Boot :: 3.3.0-M1
2024-01-23 10:22:16 
2024-01-23 10:22:16 
2024-01-23 10:22:16 2024-01-23T09:22:16.826Z  INFO 129 --- [           main] o.s.s.petclinic.PetClinicApplication     : Starting PetClinicApplication v3.2.0-SNAPSHOT using Java 21.0.2 with PID 129 (/opt/app/spring-boot-crac-demo-1.0.0-SNAPSHOT.jar started by root in /)
2024-01-23 10:22:16 2024-01-23T09:22:16.832Z  INFO 129 --- [           main] o.s.s.petclinic.PetClinicApplication     : The following 1 profile is active: "postgres"
2024-01-23 10:22:17 2024-01-23T09:22:17.775Z  INFO 129 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2024-01-23 10:22:17 2024-01-23T09:22:17.809Z  INFO 129 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 29 ms. Found 2 JPA repository interfaces.
2024-01-23 10:22:18 2024-01-23T09:22:18.317Z  INFO 129 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port 8080 (http)
2024-01-23 10:22:18 2024-01-23T09:22:18.325Z  INFO 129 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2024-01-23 10:22:18 2024-01-23T09:22:18.325Z  INFO 129 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.18]
2024-01-23 10:22:18 2024-01-23T09:22:18.348Z  INFO 129 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2024-01-23 10:22:18 2024-01-23T09:22:18.349Z  INFO 129 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1459 ms
2024-01-23 10:22:18 2024-01-23T09:22:18.541Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2024-01-23 10:22:18 2024-01-23T09:22:18.694Z  INFO 129 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@3ef3f661
2024-01-23 10:22:18 2024-01-23T09:22:18.695Z  INFO 129 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2024-01-23 10:22:18 2024-01-23T09:22:18.816Z  INFO 129 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2024-01-23 10:22:18 2024-01-23T09:22:18.849Z  INFO 129 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 6.4.1.Final
2024-01-23 10:22:18 2024-01-23T09:22:18.867Z  INFO 129 --- [           main] o.h.c.internal.RegionFactoryInitiator    : HHH000026: Second-level cache disabled
2024-01-23 10:22:18 2024-01-23T09:22:18.988Z  INFO 129 --- [           main] o.s.o.j.p.SpringPersistenceUnitInfo      : No LoadTimeWeaver setup: ignoring JPA class transformer
2024-01-23 10:22:19 2024-01-23T09:22:19.625Z  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-01-23 10:22:19 2024-01-23T09:22:19.627Z  INFO 129 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2024-01-23 10:22:19 2024-01-23T09:22:19.820Z  INFO 129 --- [           main] o.s.d.j.r.query.QueryEnhancerFactory     : Hibernate is in classpath; If applicable, HQL parser will be used.
2024-01-23 10:22:20 2024-01-23T09:22:20.701Z  INFO 129 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 13 endpoints beneath base path '/actuator'
2024-01-23 10:22:20 2024-01-23T09:22:20.758Z  INFO 129 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port 8080 (http) with context path '/'
2024-01-23 10:22:20 2024-01-23T09:22:20.766Z  INFO 129 --- [           main] o.s.s.petclinic.PetClinicApplication     : Started PetClinicApplication in 4.283 seconds (process running for 4.757)
2024-01-23 10:22:31 129:
2024-01-23 10:22:31 2024-01-23T09:22:31.240Z  INFO 129 --- [Attach Listener] jdk.crac                                 : Starting checkpoint
2024-01-23 10:22:31 2024-01-23T09:22:31.279Z  INFO 129 --- [Attach Listener] jdk.crac                                 : /opt/app/spring-boot-crac-demo-1.0.0-SNAPSHOT.jar is recorded as always available on restore
2024-01-23 10:22:31 An exception during a checkpoint operation:
2024-01-23 10:22:31 jdk.internal.crac.mirror.CheckpointException
2024-01-23 10:22:31     Suppressed: jdk.internal.crac.mirror.impl.CheckpointOpenSocketException: Socket[addr=host.docker.internal/192.168.65.254,port=5432,localport=55126]
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResourceBase.lambda$beforeCheckpoint$0(JDKSocketResourceBase.java:68)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestore1(Core.java:169)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestore(Core.java:286)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestoreInternal(Core.java:299)
2024-01-23 10:22:31     Caused by: java.lang.Exception: This file descriptor was created by HikariPool-1 connection adder at epoch:1706001738841 here
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKFdResource.<init>(JDKFdResource.java:60)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResourceBase.<init>(JDKSocketResourceBase.java:44)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResource.<init>(JDKSocketResource.java:38)
2024-01-23 10:22:31             at java.base/java.net.SocketImpl$1.<init>(SocketImpl.java:78)
2024-01-23 10:22:31             at java.base/java.net.SocketImpl.<init>(SocketImpl.java:77)
2024-01-23 10:22:31             at java.base/sun.nio.ch.NioSocketImpl.<init>(NioSocketImpl.java:139)
2024-01-23 10:22:31             at java.base/java.net.SocketImpl.createPlatformSocketImpl(SocketImpl.java:54)
2024-01-23 10:22:31             at java.base/java.net.Socket.createImpl(Socket.java:583)
2024-01-23 10:22:31             at java.base/java.net.Socket.<init>(Socket.java:189)
2024-01-23 10:22:31             at java.base/javax.net.DefaultSocketFactory.createSocket(SocketFactory.java:261)
2024-01-23 10:22:31             at org.postgresql.core.PGStream.createSocket(PGStream.java:231)
2024-01-23 10:22:31             at org.postgresql.core.PGStream.<init>(PGStream.java:98)
2024-01-23 10:22:31             at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:132)
2024-01-23 10:22:31             at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:258)
2024-01-23 10:22:31             at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
2024-01-23 10:22:31             at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:263)
2024-01-23 10:22:31             at org.postgresql.Driver.makeConnection(Driver.java:444)
2024-01-23 10:22:31             at org.postgresql.Driver.connect(Driver.java:297)
2024-01-23 10:22:31             at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:137)
2024-01-23 10:22:31             at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
2024-01-23 10:22:31             at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
2024-01-23 10:22:31             at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
2024-01-23 10:22:31             at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:724)
2024-01-23 10:22:31             at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:703)
2024-01-23 10:22:31             at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
2024-01-23 10:22:31             at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
2024-01-23 10:22:31             at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
2024-01-23 10:22:31             at java.base/java.lang.Thread.run(Thread.java:1583)
2024-01-23 10:22:31     Suppressed: jdk.internal.crac.mirror.impl.CheckpointOpenSocketException: sun.nio.ch.ServerSocketChannelImpl[/0.0.0.0:8080]
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResourceBase.lambda$beforeCheckpoint$0(JDKSocketResourceBase.java:68)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestore1(Core.java:169)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestore(Core.java:286)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.mirror.Core.checkpointRestoreInternal(Core.java:299)
2024-01-23 10:22:31     Caused by: java.lang.Exception: This file descriptor was created by main at epoch:1706001740751 here
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKFdResource.<init>(JDKFdResource.java:60)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResourceBase.<init>(JDKSocketResourceBase.java:44)
2024-01-23 10:22:31             at java.base/jdk.internal.crac.JDKSocketResource.<init>(JDKSocketResource.java:38)
2024-01-23 10:22:31             at java.base/sun.nio.ch.ServerSocketChannelImpl$Resource.<init>(ServerSocketChannelImpl.java:761)
2024-01-23 10:22:31             at java.base/sun.nio.ch.ServerSocketChannelImpl.<init>(ServerSocketChannelImpl.java:79)
2024-01-23 10:22:31             at java.base/sun.nio.ch.ServerSocketChannelImpl.<init>(ServerSocketChannelImpl.java:118)
2024-01-23 10:22:31             at java.base/sun.nio.ch.SelectorProviderImpl.openServerSocketChannel(SelectorProviderImpl.java:72)
2024-01-23 10:22:31             at java.base/java.nio.channels.ServerSocketChannel.open(ServerSocketChannel.java:145)
2024-01-23 10:22:31             at org.apache.tomcat.util.net.NioEndpoint.initServerSocket(NioEndpoint.java:244)
2024-01-23 10:22:31             at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:202)
2024-01-23 10:22:31             at org.apache.tomcat.util.net.AbstractEndpoint.bindWithCleanup(AbstractEndpoint.java:1280)
2024-01-23 10:22:31             at org.apache.tomcat.util.net.AbstractEndpoint.start(AbstractEndpoint.java:1366)
2024-01-23 10:22:31             at org.apache.coyote.AbstractProtocol.start(AbstractProtocol.java:635)
2024-01-23 10:22:31             at org.apache.catalina.connector.Connector.startInternal(Connector.java:1043)
2024-01-23 10:22:31             at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
2024-01-23 10:22:31             at org.apache.catalina.core.StandardService.addConnector(StandardService.java:232)
2024-01-23 10:22:31             at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.addPreviouslyRemovedConnectors(TomcatWebServer.java:310)
2024-01-23 10:22:31             at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.start(TomcatWebServer.java:236)
2024-01-23 10:22:31             at org.springframework.boot.web.servlet.context.WebServerStartStopLifecycle.start(WebServerStartStopLifecycle.java:44)
2024-01-23 10:22:31             at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:284)
2024-01-23 10:22:31             at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.start(DefaultLifecycleProcessor.java:467)
2024-01-23 10:22:31             at java.base/java.lang.Iterable.forEach(Iterable.java:75)
2024-01-23 10:22:31             at org.springframework.context.support.DefaultLifecycleProcessor.startBeans(DefaultLifecycleProcessor.java:256)
2024-01-23 10:22:31             at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:201)
2024-01-23 10:22:31             at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:978)
2024-01-23 10:22:31             at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:627)
2024-01-23 10:22:31             at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:146)
2024-01-23 10:22:31             at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
2024-01-23 10:22:31             at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:456)
2024-01-23 10:22:31             at org.springframework.boot.SpringApplication.run(SpringApplication.java:334)
2024-01-23 10:22:31             at org.springframework.boot.SpringApplication.run(SpringApplication.java:1354)
2024-01-23 10:22:31             at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
2024-01-23 10:22:31             at org.springframework.samples.petclinic.PetClinicApplication.main(PetClinicApplication.java:34)
2024-01-23 10:22:31             at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
2024-01-23 10:22:31             at java.base/java.lang.reflect.Method.invoke(Method.java:580)
2024-01-23 10:22:31             at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:91)
2024-01-23 10:22:31             at org.springframework.boot.loader.launch.Launcher.launch(Launcher.java:53)
2024-01-23 10:22:31             at org.springframework.boot.loader.launch.JarLauncher.main(JarLauncher.java:58)

Comment From: wilkinsona

@sdeleuze, can you please investigate?

Comment From: sdeleuze

I just tested and made it work with Spring Boot 3.2.2. Please check you have added the CRaC dependency. If that's the case, please share a reproducer as an attached archive or a link to a repository, with instructions to reproduce.

Comment From: rafalgalik-sadapay

Thanks for the quick response.

I'm using macOS btw

To reproduce:

  1. checkout https://github.com/rafalgalik-sadapay/spring-petclinic-checkpoint-restore-crac-bug
  2. start postgres docker-compose --profile postgres up -d
  3. ./checkpoint.sh
  4. wait ~15 secs
  5. docker logs <checnpoint_container_id>

I hope you'll be able to reproduce. Thanks for helping.

Comment From: rafalgalik-sadapay

I was also able to reproduce it on Ubuntu. OpenJDK Runtime Environment Zulu21.30+19-CRaC-CA (build 21.0.1+12-LTS)

  1. checkout https://github.com/rafalgalik-sadapay/spring-petclinic-checkpoint-restore-crac-bug
  2. start postgres docker-compose --profile postgres up -d
  3. ./mvnw clean package -DskipTests
  4. java -Dmanagement.endpoint.health.probes.add-additional-paths="true" -Dmanagement.health.probes.enabled="true" -Dspring.profiles.active=postgres -Djdk.crac.collect-fd-stacktraces=true -XX:CRaCCheckpointTo=cr -Dspring.datasource.url=jdbc:postgresql://localhost:5432/petclinic -jar target/spring-petclinic-3.2.0-SNAPSHOT.jar
  5. jcmd target/spring-petclinic-3.2.0-SNAPSHOT.jar JDK.checkpoint

Comment From: sdeleuze

I have been able to reproduce, this is due to the non-embedded database requiring additional configuration.

I have updated the lifecycle status page to mention that some test documentations provide configuration guidance, and have provided detailed guidance for Spring Data JPA.

I have tested that this configuration guidance allows to run your repro as expected, as a consequence, I think this issue can be closed.

Comment From: wilkinsona

Thanks, @sdeleuze.

Comment From: rafalgalik-sadapay

Thanks for your quick help @sdeleuze.