TestContainers parallel initialization doesn't work properly

[kuzmin-anton-dev]

Hello.

Parallel TestContainers initialization was supported in the PR. But it seems it doesn't work as it should. Despite on setting it starts containers sequentially in two cases:

1. Using ImportTestcontainers annotation

I've found that in ImportTestcontainersRegistrar while bean definitions registration in ContainerFieldsImporter Spring immediately starts containers sequentially despite on spring.testcontainers.beans.startup setting.

Startup logs:

2023-12-15T16:18:24.053+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:18:24.120+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 8614fdc6fdc43012c73644ed3e38c20f81334c184223c0b1310eda5ff319d66f
2023-12-15T16:18:25.113+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT1.059991S
2023-12-15T16:18:25.114+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33032/test?loggerLevel=OFF)
2023-12-15T16:18:25.115+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:18:25.148+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 5c8762434fc624dbe55ab7ff2d1f049517a524c780375bef4f0dd77ea4ec80db
2023-12-15T16:18:26.068+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT0.952306S
2023-12-15T16:18:26.068+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33033/test?loggerLevel=OFF)
2023-12-15T16:18:26.069+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:18:26.105+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: c84ccfe898bf9da06a0dd804809f8a2b507afadeb91945715276056c77111205
2023-12-15T16:18:26.995+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT0.926222S
2023-12-15T16:18:26.996+01:00  INFO 16284 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33034/test?loggerLevel=OFF)
2023-12-15T16:18:27.178+01:00  INFO 16284 --- [    Test worker] k.s.b.t.d.i.ImportTestContainersDemoTest : Started ImportTestContainersDemoTest in 5.572 seconds (process running for 6.21)

2. Using Bean annotation

TestcontainersLifecycleBeanPostProcessor starts containers which are defined as beans. At first look is seem that is should work because it takes into account spring.testcontainers.beans.startup:

private void start(List<Object> beans) {
    Set<Startable> startables = beans.stream()
        .filter(Startable.class::isInstance)
	.map(Startable.class::cast)
	.collect(Collectors.toCollection(LinkedHashSet::new));
    this.startup.start(startables);
}

But it still start containers sequentially because of

if (bean instanceof Startable startableBean) {
    if (this.startablesInitialized.compareAndSet(false, true)) {
        initializeStartables(startableBean, beanName);
    } else {
        startableBean.start();
    }
}

When Spring calls getBeans method for the first container is will come again to the fragment above, where this.startablesInitialized will be already true. So it starts all containers one by one.

Startup logs:

2023-12-15T16:19:11.894+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:19:11.941+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 098ad928a38bff8ff92cdf804731184d00ba164dc10478ec1a610faa0effe9df
2023-12-15T16:19:12.935+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT1.040903S
2023-12-15T16:19:12.937+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33036/test?loggerLevel=OFF)
2023-12-15T16:19:12.939+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:19:12.973+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: e9bf58269cbf7cc0f4596700d1f77b2d490f62577a6ac5dd225753da7d92afed
2023-12-15T16:19:13.945+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT1.005915S
2023-12-15T16:19:13.945+01:00  INFO 16353 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33037/test?loggerLevel=OFF)
2023-12-15T16:19:13.947+01:00  INFO 16353 --- [ers-lifecycle-1] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-15T16:19:13.984+01:00  INFO 16353 --- [ers-lifecycle-1] tc.postgres:16                           : Container postgres:16 is starting: d9c50b98386f437f4907d3bdcb8b19f8e05c5dda83aa0956a87673a1bcb15813
2023-12-15T16:19:14.891+01:00  INFO 16353 --- [ers-lifecycle-1] tc.postgres:16                           : Container postgres:16 started in PT0.944609S
2023-12-15T16:19:14.893+01:00  INFO 16353 --- [ers-lifecycle-1] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33038/test?loggerLevel=OFF)
2023-12-15T16:19:14.945+01:00  INFO 16353 --- [    Test worker] c.k.s.b.t.d.b.BeanTestContainersDemoTest : Started BeanTestContainersDemoTest in 4.824 seconds (process running for 5.478)

I also have pushed demo project you to be able to reproduce the behaviour.

Am I doing something in a wrong way or it is a bug? Thanks.

[philwebb]

Well this is more than a little embarrassing 🤦. Thanks for your analysis and the sample application. I've pushed a fix that I hope will solve things.

[kuzmin-anton-dev]

@philwebb, thanks for a fix a lot!)

As far as I understand, fix only covers case when containers are defined as beans. Does it mean that case with importing containers via ImportTestcontainers won't support parallel startup?

[philwebb]

@kuz94 Are you still seeing issues with @ImportTestcontainers tests? I thought the fix I applied would also work there as well.

[kuzmin-anton-dev]

Bean definition now works perfectly:

2023-12-17T22:33:13.537+01:00  INFO 50484 --- [ers-lifecycle-0] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:33:13.537+01:00  INFO 50484 --- [ers-lifecycle-2] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:33:13.537+01:00  INFO 50484 --- [ers-lifecycle-1] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:33:13.616+01:00  INFO 50484 --- [ers-lifecycle-0] tc.postgres:16                           : Container postgres:16 is starting: af4a007cc4324f5bf9f00146110d8a74f3c43d86fbc6e1f2fc1814c4da1bd867
2023-12-17T22:33:13.621+01:00  INFO 50484 --- [ers-lifecycle-2] tc.postgres:16                           : Container postgres:16 is starting: 54c8e28daa3255eccdb8686245e807dcef1251352fa0e688115770d909f6832f
2023-12-17T22:33:13.621+01:00  INFO 50484 --- [ers-lifecycle-1] tc.postgres:16                           : Container postgres:16 is starting: ed86f1eadde712da2f9dfa422870446886679ca9c361b4ce581ea43369aa331c
2023-12-17T22:33:14.738+01:00  INFO 50484 --- [ers-lifecycle-0] tc.postgres:16                           : Container postgres:16 started in PT1.201849S
2023-12-17T22:33:14.739+01:00  INFO 50484 --- [ers-lifecycle-0] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33089/test?loggerLevel=OFF)
2023-12-17T22:33:14.962+01:00  INFO 50484 --- [ers-lifecycle-1] tc.postgres:16                           : Container postgres:16 started in PT1.425763S
2023-12-17T22:33:14.963+01:00  INFO 50484 --- [ers-lifecycle-1] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33090/test?loggerLevel=OFF)
2023-12-17T22:33:14.964+01:00  INFO 50484 --- [ers-lifecycle-2] tc.postgres:16                           : Container postgres:16 started in PT1.42731S
2023-12-17T22:33:14.964+01:00  INFO 50484 --- [ers-lifecycle-2] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33091/test?loggerLevel=OFF)
2023-12-17T22:33:15.026+01:00  INFO 50484 --- [    Test worker] c.k.s.b.t.d.b.BeanTestContainersDemoTest : Started BeanTestContainersDemoTest in 4.522 seconds (process running for 5.123)

But I still experience problems with @ImportTestcontainers:

2023-12-17T22:34:46.571+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:34:46.608+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 6cb808177ac92491805aff66bde9d2ae2715aecaa12e6d17e8ae0d00ebef7a9a
2023-12-17T22:34:47.509+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT0.938053S
2023-12-17T22:34:47.509+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33093/test?loggerLevel=OFF)
2023-12-17T22:34:47.512+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:34:47.544+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 50f3de7bf002edba5b22d8fcad720f16117dbef1480433c9aaa51627c7438e6a
2023-12-17T22:34:48.442+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT0.930497S
2023-12-17T22:34:48.443+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33094/test?loggerLevel=OFF)
2023-12-17T22:34:48.443+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Creating container for image: postgres:16
2023-12-17T22:34:48.476+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 is starting: 85bc36658c4dbaf655b763df6c1c8453097a70a7d941bd1220c03142e59ce2a3
2023-12-17T22:34:49.375+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container postgres:16 started in PT0.931557S
2023-12-17T22:34:49.375+01:00  INFO 50577 --- [    Test worker] tc.postgres:16                           : Container is started (JDBC URL: jdbc:postgresql://localhost:33095/test?loggerLevel=OFF)
2023-12-17T22:34:49.524+01:00  INFO 50577 --- [    Test worker] k.s.b.t.d.i.ImportTestContainersDemoTest : Started ImportTestContainersDemoTest in 6.154 seconds (process running for 6.747)

If I understand it right, some fixes should be done in the ContainerFieldsImporter:

...
void registerBeanDefinitions(BeanDefinitionRegistry registry, Class<?>[] definitionClasses) {
	for (Field field : getContainerFields(definitionClass)) {
		assertValid(field);
		Container<?> container = getContainer(field);
		if (container instanceof Startable startable) {
			startable.start();
		}
		registerBeanDefinition(registry, field, container);
	}
}
...

P.S.: I also updated the demo project so you can reproduce the problem

[philwebb]

Thanks again @kuz94. I could have sworn I tested the import case, but you're exactly right with your analysis. I've removed that start call so we now rely on the postprocessor.