Testcontainers start first test so long

Question

I'm following this document to build a spring-boot application with org.springframework.boot:spring-boot-testcontainers dependency. I'm running the test in IntelliJ IDEA 2022.1

java version 17
org.springframework.boot' version '3.1.4'
io.spring.dependency-management version '1.1.3'

Here is my build.gradle file:

// other settings
dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-actuator'
    implementation 'org.springframework.boot:spring-boot-starter-cache'
    implementation 'org.springframework.boot:spring-boot-starter-data-jpa'
    implementation 'org.springframework.boot:spring-boot-starter-validation'
    implementation 'org.springframework.boot:spring-boot-starter-web'
    implementation 'org.springdoc:springdoc-openapi-starter-webmvc-ui:2.2.0'
    implementation 'org.springdoc:springdoc-openapi-starter-webmvc-api:2.2.0'
    implementation 'org.springdoc:springdoc-openapi-starter-common:2.2.0'
    implementation 'org.flywaydb:flyway-core'
    implementation 'org.ehcache:ehcache:3.10.8'
    implementation 'org.hibernate.orm:hibernate-jcache:6.3.1.Final'
    implementation 'org.springframework.boot:spring-boot-devtools'
    compileOnly 'org.projectlombok:lombok'
    runtimeOnly 'org.postgresql:postgresql'
    annotationProcessor 'org.projectlombok:lombok'
    testImplementation 'org.springframework.boot:spring-boot-starter-test'
    testImplementation 'org.springframework.boot:spring-boot-testcontainers'
    testImplementation 'org.testcontainers:postgresql'
    testImplementation 'org.testcontainers:junit-jupiter'
    testImplementation 'io.rest-assured:rest-assured:5.3.1'
}
tasks.named('test') {
    useJUnitPlatform()
}

I have a Integration Test class

@TestConfiguration(proxyBeanMethods = false)
public class TestContainersConfiguration {

  @Bean
  @ServiceConnection
  public PostgreSQLContainer<?> postgreSQLContainer() {
    return new PostgreSQLContainer<>("postgres:15.2-alpine")
        .withReuse(true);
  }
}

@SpringBootTest(webEnvironment = RANDOM_PORT)
@Testcontainers
@Import(TestContainersConfiguration.class)
public class ApiIT {

  @Autowired
  protected PostgreSQLContainer postgreSQLContainer;

  @LocalServerPort
  private Integer port;

  @BeforeEach
  void setUp() {
    RestAssured.baseURI = "http://localhost:" + port;
  }

  @Test
  void test() {
    assertThat(postgreSQLContainer.isRunning()).isTrue();
  }

  @Test
  void checkHealth() {
    when().get("/api/actuator/health")
        .then().statusCode(200)
        .and().body("status", containsString("UP"));
  }
}

The test worked fine as expected but it took too long for starting the first test method.

Task :compileJava UP-TO-DATE Task :processResources UP-TO-DATE Task :classes UP-TO-DATE Task :compileTestJava UP-TO-DATE Task :processTestResources UP-TO-DATE Task :testClasses UP-TO-DATE Task :test 12:17:21.344 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils -- Could not detect default configuration classes for test class [org.phuongnq.springboot3.hibernate.cache.integration.api.ApiBaseIT]: ApiBaseIT does not declare any static, non-private, non-final, nested classes annotated with @Configuration. 12:17:21.506 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper -- Found @SpringBootConfiguration org.phuongnq.springboot3.hibernate.cache.DemoApplication for test class org.phuongnq.springboot3.hibernate.cache.integration.api.ApiBaseIT

_ _ \ \ \
` | \ \ \
__)| |)| | | | | || (| | ) ) ) ) ' || .__|| ||| |_, | / / / / =========||==============|/=//// Spring Boot :: (v3.1.4)

2023-10-30T12:17:22.046+07:00 INFO 19068 --- [ Test worker] o.p.s.h.cache.integration.api.ApiBaseIT : Starting ApiBaseIT using Java 17.0.2 with PID 19068 (started by PNguyen in C:\demo-workspace\spring-demo\spring-boot3-hibernate-cache) 2023-10-30T12:17:22.049+07:00 INFO 19068 --- [ Test worker] o.p.s.h.cache.integration.api.ApiBaseIT : No active profile set, falling back to 1 default profile: "default" 2023-10-30T12:17:23.424+07:00 INFO 19068 --- [ Test worker] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode. 2023-10-30T12:17:23.485+07:00 INFO 19068 --- [ Test worker] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 49 ms. Found 1 JPA repository interfaces. 2023-10-30T12:17:24.171+07:00 INFO 19068 --- [ Test worker] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 0 (http) 2023-10-30T12:17:24.182+07:00 INFO 19068 --- [ Test worker] o.apache.catalina.core.StandardService : Starting service [Tomcat] 2023-10-30T12:17:24.182+07:00 INFO 19068 --- [ Test worker] o.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/10.1.13] 2023-10-30T12:17:24.299+07:00 INFO 19068 --- [ Test worker] o.a.c.c.C.[Tomcat].[localhost].[/api] : Initializing Spring embedded WebApplicationContext 2023-10-30T12:17:24.299+07:00 INFO 19068 --- [ Test worker] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1997 ms 2023-10-30T12:17:24.609+07:00 INFO 19068 --- [ Test worker] o.t.utility.ImageNameSubstitutor : Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor') 2023-10-30T12:17:24.859+07:00 INFO 19068 --- [ Test worker] o.t.d.DockerClientProviderStrategy : Loaded org.testcontainers.dockerclient.NpipeSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first 2023-10-30T12:17:25.154+07:00 INFO 19068 --- [ Test worker] o.t.d.DockerClientProviderStrategy : Found Docker environment with local Npipe socket (npipe:////./pipe/docker_engine) 2023-10-30T12:17:25.154+07:00 INFO 19068 --- [ Test worker] org.testcontainers.DockerClientFactory : Docker host IP address is localhost 2023-10-30T12:17:25.176+07:00 INFO 19068 --- [ Test worker] org.testcontainers.DockerClientFactory : Connected to docker: Server Version: 20.10.13 API Version: 1.41 Operating System: Docker Desktop Total Memory: 2988 MB 2023-10-30T12:17:25.185+07:00 INFO 19068 --- [ Test worker] org.testcontainers.DockerClientFactory : Checking the system... 2023-10-30T12:17:25.186+07:00 INFO 19068 --- [ Test worker] org.testcontainers.DockerClientFactory : ?? Docker server version should be at least 1.6.0 2023-10-30T12:17:25.280+07:00 INFO 19068 --- [ Test worker] tc.postgres:15.2-alpine : Creating container for image: postgres:15.2-alpine 2023-10-30T12:17:29.537+07:00 INFO 19068 --- [ Test worker] o.t.utility.RegistryAuthLocator : Credential helper/store (docker-credential-desktop) does not have credentials for https://index.docker.io/v1/ 2023-10-30T12:17:29.708+07:00 INFO 19068 --- [ Test worker] tc.postgres:15.2-alpine : Container postgres:15.2-alpine is starting: 8c543caaa6ea6a3b4092f34e5dc6a37608e4cf7fe2f813eb2c013ec6c66f58c5 2023-10-30T12:17:32.166+07:00 INFO 19068 --- [ Test worker] tc.postgres:15.2-alpine : Container postgres:15.2-alpine started in PT6.9795259S 2023-10-30T12:17:32.167+07:00 INFO 19068 --- [ Test worker] tc.postgres:15.2-alpine : Container is started (JDBC URL: jdbc:postgresql://localhost:54464/test?loggerLevel=OFF) 2023-10-30T12:17:32.311+07:00 INFO 19068 --- [ Test worker] o.f.c.internal.license.VersionPrinter : Flyway Community Edition 9.16.3 by Redgate 2023-10-30T12:17:32.311+07:00 INFO 19068 --- [ Test worker] o.f.c.internal.license.VersionPrinter : See release notes here: https://rd.gt/416ObMi 2023-10-30T12:17:32.311+07:00 INFO 19068 --- [ Test worker] o.f.c.internal.license.VersionPrinter : 2023-10-30T12:17:32.503+07:00 INFO 19068 --- [ Test worker] o.f.c.i.database.base.BaseDatabaseType : Database: jdbc:postgresql://localhost:54464/test (PostgreSQL 15.2) 2023-10-30T12:17:32.550+07:00 INFO 19068 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Schema history table "public"."flyway_schema_history" does not exist yet 2023-10-30T12:17:32.554+07:00 INFO 19068 --- [ Test worker] o.f.core.internal.command.DbValidate : Successfully validated 2 migrations (execution time 00:00.021s) 2023-10-30T12:17:32.574+07:00 INFO 19068 --- [ Test worker] o.f.c.i.s.JdbcTableSchemaHistory : Creating Schema History table "public"."flyway_schema_history" ... 2023-10-30T12:17:32.621+07:00 INFO 19068 --- [ Test worker] o.f.core.internal.command.DbMigrate : Current version of schema "public": << Empty Schema >> 2023-10-30T12:17:32.630+07:00 INFO 19068 --- [ Test worker] o.f.core.internal.command.DbMigrate : Migrating schema "public" to version "1.1 - DDL initial db" 2023-10-30T12:17:32.672+07:00 INFO 19068 --- [ Test worker] o.f.core.internal.command.DbMigrate : Migrating schema "public" to version "1.2 - DML initial data" 2023-10-30T12:17:32.690+07:00 INFO 19068 --- [ Test worker] o.f.core.internal.command.DbMigrate : Successfully applied 2 migrations to schema "public", now at version v1.2 (execution time 00:00.077s) 2023-10-30T12:17:32.756+07:00 INFO 19068 --- [ Test worker] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting... 2023-10-30T12:17:32.801+07:00 INFO 19068 --- [ Test worker] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@5e6bbe63 2023-10-30T12:17:32.804+07:00 INFO 19068 --- [ Test worker] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed. 2023-10-30T12:17:32.848+07:00 INFO 19068 --- [ Test worker] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default] 2023-10-30T12:17:32.932+07:00 INFO 19068 --- [ Test worker] org.hibernate.Version : HHH000412: Hibernate ORM core version 6.2.9.Final 2023-10-30T12:17:32.937+07:00 INFO 19068 --- [ Test worker] org.hibernate.cfg.Environment : HHH000406: Using bytecode reflection optimizer 2023-10-30T12:17:33.119+07:00 INFO 19068 --- [ Test worker] o.h.b.i.BytecodeProviderInitiator : HHH000021: Bytecode provider name : bytebuddy 2023-10-30T12:17:33.275+07:00 INFO 19068 --- [ Test worker] o.s.o.j.p.SpringPersistenceUnitInfo : No LoadTimeWeaver setup: ignoring JPA class transformer 2023-10-30T12:17:33.532+07:00 INFO 19068 --- [ Test worker] o.h.b.i.BytecodeProviderInitiator : HHH000021: Bytecode provider name : bytebuddy 2023-10-30T12:17:33.705+07:00 WARN 19068 --- [ Test worker] org.hibernate.orm.cache : HHH90001006: Missing cache[default-update-timestamps-region] was created on-the-fly. The created cache will use a provider-specific default configuration: make sure you defined one. You can disable this warning by setting 'hibernate.javax.cache.missing_cache_strategy' to 'create'. 2023-10-30T12:17:33.783+07:00 INFO 19068 --- [ Test worker] org.ehcache.core.EhcacheManager : Cache 'default-update-timestamps-region' created in EhcacheManager. 2023-10-30T12:17:33.793+07:00 WARN 19068 --- [ Test worker] org.hibernate.orm.cache : HHH90001006: Missing cache[default-query-results-region] was created on-the-fly. The created cache will use a provider-specific default configuration: make sure you defined one. You can disable this warning by setting 'hibernate.javax.cache.missing_cache_strategy' to 'create'. 2023-10-30T12:17:33.803+07:00 INFO 19068 --- [ Test worker] org.ehcache.core.EhcacheManager : Cache 'default-query-results-region' created in EhcacheManager. 2023-10-30T12:17:33.854+07:00 WARN 19068 --- [ Test worker] org.hibernate.orm.cache : HHH90001006: Missing cache[org.phuongnq.springboot3.hibernate.cache.entity.Category] was created on-the-fly. The created cache will use a provider-specific default configuration: make sure you defined one. You can disable this warning by setting 'hibernate.javax.cache.missing_cache_strategy' to 'create'. 2023-10-30T12:17:33.854+07:00 INFO 19068 --- [ Test worker] org.ehcache.core.EhcacheManager : Cache 'org.phuongnq.springboot3.hibernate.cache.entity.Category' created in EhcacheManager. 2023-10-30T12:17:34.494+07:00 INFO 19068 --- [ Test worker] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform] 2023-10-30T12:17:34.497+07:00 INFO 19068 --- [ Test worker] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default' 2023-10-30T12:17:35.093+07:00 WARN 19068 --- [ Test worker] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning 2023-10-30T12:17:36.024+07:00 INFO 19068 --- [ Test worker] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint(s) beneath base path '/actuator' 2023-10-30T12:17:36.128+07:00 INFO 19068 --- [ Test worker] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 54477 (http) with context path '/api' 2023-10-30T12:17:36.138+07:00 INFO 19068 --- [ Test worker] o.p.s.h.cache.integration.api.ApiBaseIT : Started ApiBaseIT in 14.461 seconds (process running for 15.885) OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended

Task :test 2023-10-30T12:19:43.085+07:00 INFO 19068 --- [o-auto-1-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/api] : Initializing Spring DispatcherServlet 'dispatcherServlet' 2023-10-30T12:19:43.085+07:00 INFO 19068 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet' 2023-10-30T12:19:43.087+07:00 INFO 19068 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 2 ms 2023-10-30T12:19:44.231+07:00 INFO 19068 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default' 2023-10-30T12:19:44.237+07:00 INFO 19068 --- [ionShutdownHook] org.ehcache.core.EhcacheManager : Cache 'org.phuongnq.springboot3.hibernate.cache.entity.Category' removed from EhcacheManager. 2023-10-30T12:19:44.238+07:00 INFO 19068 --- [ionShutdownHook] org.ehcache.core.EhcacheManager : Cache 'default-query-results-region' removed from EhcacheManager. 2023-10-30T12:19:44.243+07:00 INFO 19068 --- [ionShutdownHook] org.ehcache.core.EhcacheManager : Cache 'default-update-timestamps-region' removed from EhcacheManager. 2023-10-30T12:19:44.250+07:00 INFO 19068 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown initiated... 2023-10-30T12:19:44.256+07:00 INFO 19068 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Shutdown completed. Task :test

Deprecated Gradle features were used in this build, making it incompatible with Gradle 9.0.

You can use '--warning-mode all' to show the individual deprecation warnings and determine if they come from your own scripts or plugins.

For more on this, please refer to https://docs.gradle.org/8.3/userguide/command_line_interface.html#sec:command_line_warnings in the Gradle documentation. BUILD SUCCESSFUL in 2m 25s 5 actionable tasks: 1 executed, 4 up-to-date 12:19:44 PM: Execution finished 'test'.

As you can see it took only 14.461 seconds to start application, and I can access and get the response from url at that time localhost:54477/api/actuator/health. But then it took more than 2m to start the test() method 12:17:36.138 to 12:19:44.231.

Is there any reason for that delay? How can I force the test case to run immediately after the container is ready?

Answer 1

I faced the same issue when running in Intellij, it happened when RAM reached the maximum settings. Increase your memory settings and run again.

Answer 2

I checked your log, and found what +2 min happens when Spring context download. Has worring OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appendedTask :test 2023-10-30T12:19:43.085+07:00

It seems to me that the problem is loading (starting) the application itself