Container start failure can lead to repeated error from Docker Java client

We have some tests in Spring Boot that use Testcontainers 1.7.2 to run Cassandra. Sometimes, when Cassandra fails to start, things seem to get stuck such that Docker Java client repeatedly logs an error message. We give Cassandra 3 attempts to start, each timing out at 60 seconds.

The first attempt to start Cassandra fails:

2018-05-11 09:44:13.522  INFO 5291 --- [           main] tAndSystemPropertyClientProviderStrategy : Found docker client settings from environment
2018-05-11 09:44:13.553  INFO 5291 --- [           main] o.t.d.DockerClientProviderStrategy       : Found Docker environment with Environment variables, system properties
and defaults. Resolved:
    dockerHost=unix:///var/run/docker.sock
    apiVersion='{UNKNOWN_VERSION}'
    registryUrl='https://index.docker.io/v1/'
    registryUsername='root'
    registryPassword='null'
    registryEmail='null'
    dockerConfig='DefaultDockerClientConfig[dockerHost=unix:///var/run/docker.sock,registryUsername=root,registryPassword=<null>,registryEmail=<null>,registryUrl=https://i
ndex.docker.io/v1/,dockerConfigPath=/root/.docker,sslConfig=<null>,apiVersion={UNKNOWN_VERSION},dockerConfig=<null>]'

2018-05-11 09:44:18.196  INFO 5291 --- [           main] org.testcontainers.DockerClientFactory   : Docker host IP address is 172.17.0.1
2018-05-11 09:44:18.499  INFO 5291 --- [           main] org.testcontainers.DockerClientFactory   : Connected to docker:
  Server Version: 17.05.0-ce
  API Version: 1.29
  Operating System: Debian GNU/Linux buster/sid (containerized)
  Total Memory: 24110 MB
2018-05-11 09:44:22.574  INFO 5291 --- [           main] org.testcontainers.DockerClientFactory   : Ryuk started - will monitor and terminate Testcontainers containers on
JVM exit
        ℹ︎ Checking the system...
        ✔ Docker version should be at least 1.6.0
        ✔ Docker environment should have more than 2GB free disk space
        ✔ File should be mountable
2018-05-11 09:44:23.016  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Pulling docker image: cassandra:3.11.1. Please be patient; this may tak
e some time but only needs to be done once.
2018-05-11 09:44:43.405  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Creating container for image: cassandra:3.11.1
2018-05-11 09:44:43.566  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Starting container with ID: 3bb922ee9dd4e342be159b92f851ca1afe73a77fde9
2784a3125c484a2cc7137
2018-05-11 09:44:44.760  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container cassandra:3.11.1 is starting: 3bb922ee9dd4e342be159b92f851ca1
afe73a77fde92784a3125c484a2cc7137
2018-05-11 09:45:44.972 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Could not start container

org.testcontainers.containers.ContainerLaunchException: Timed out waiting for container port to open (172.17.0.1 ports: [32770] should be listening)
	at org.testcontainers.containers.wait.strategy.HostPortWaitStrategy.waitUntilReady(HostPortWaitStrategy.java:47)
	at org.springframework.boot.testsupport.testcontainers.CassandraContainer$WaitStrategy.waitUntilReady(CassandraContainer.java:57)
	at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:32)
	at org.testcontainers.containers.GenericContainer.waitUntilContainerStarted(GenericContainer.java:531)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:258)
	at org.testcontainers.containers.GenericContainer.lambda$start$0(GenericContainer.java:209)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:207)
	at org.testcontainers.containers.GenericContainer.starting(GenericContainer.java:638)
	at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:29)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:379)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:340)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:125)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:413)

2018-05-11 09:45:45.006 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container log output (if any) will follow:
…
2018-05-11 09:45:46.148  INFO 5291 --- [iners-netty-1-8] 🐳 [cassandra:3.11.1]                    : STDOUT: INFO  [MigrationStage:1] 2018-05-11 09:45:38,024 ViewManager.ja
va:137 - Not submitting build tasks for views in keyspace system_distributed as storage service is not initialized
2018-05-11 09:45:46.148  INFO 5291 --- [iners-netty-1-8] 🐳 [cassandra:3.11.1]                    : STDOUT: INFO  [MigrationStage:1] 2018-05-11 09:45:38,196 ColumnFamilySt
ore.java:408 - Initializing system_distributed.parent_repair_history
2018-05-11 09:45:46.148  INFO 5291 --- [iners-netty-1-8] 🐳 [cassandra:3.11.1]                    : STDOUT: INFO  [MigrationStage:1] 2018-05-11 09:45:38,613 ColumnFamilySt
ore.java:408 - Initializing system_distributed.repair_history
2018-05-11 09:45:46.148  INFO 5291 --- [iners-netty-1-8] 🐳 [cassandra:3.11.1]                    : STDOUT: INFO  [MigrationStage:1] 2018-05-11 09:45:38,621 ColumnFamilySt
ore.java:408 - Initializing system_distributed.view_build_status
2018-05-11 09:45:46.148  INFO 5291 --- [iners-netty-1-8] 🐳 [cassandra:3.11.1]                    : STDOUT: INFO  [main] 2018-05-11 09:45:38,732 StorageService.java:1442 -
 JOINING: Finish joining ring

And so does the second attempt, but with no container log output this time:

2018-05-11 09:45:46.149  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Creating container for image: cassandra:3.11.1
2018-05-11 09:45:49.979  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Starting container with ID: 7f26fb8bdaffea1d9573c88254bf0a596336d48bebb
aa24d5fa81286669f1808
2018-05-11 09:45:54.775  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container cassandra:3.11.1 is starting: 7f26fb8bdaffea1d9573c88254bf0a5
96336d48bebbaa24d5fa81286669f1808
2018-05-11 09:46:55.087 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Could not start container

org.testcontainers.containers.ContainerLaunchException: Timed out waiting for container port to open (172.17.0.1 ports: [32775] should be listening)
	at org.testcontainers.containers.wait.strategy.HostPortWaitStrategy.waitUntilReady(HostPortWaitStrategy.java:47)
	at org.springframework.boot.testsupport.testcontainers.CassandraContainer$WaitStrategy.waitUntilReady(CassandraContainer.java:57)
	at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:32)
	at org.testcontainers.containers.GenericContainer.waitUntilContainerStarted(GenericContainer.java:531)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:258)
	at org.testcontainers.containers.GenericContainer.lambda$start$0(GenericContainer.java:209)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:207)
	at org.testcontainers.containers.GenericContainer.starting(GenericContainer.java:638)
	at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:29)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:379)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:340)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:125)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:413)

2018-05-11 09:46:55.467 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container log output (if any) will follow:

The third then fails in a similar fashion:

2018-05-11 09:47:10.299  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Creating container for image: cassandra:3.11.1
2018-05-11 09:47:30.691  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Starting container with ID: 06484b44ae48384289006a3af3892777a76cc5c0ac6
2bd0570ed0d325d902c16
2018-05-11 09:47:50.170  INFO 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container cassandra:3.11.1 is starting: 06484b44ae48384289006a3af389277
7a76cc5c0ac62bd0570ed0d325d902c16
2018-05-11 09:48:50.506 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Could not start container

org.testcontainers.containers.ContainerLaunchException: Timed out waiting for container port to open (172.17.0.1 ports: [32780] should be listening)
	at org.testcontainers.containers.wait.strategy.HostPortWaitStrategy.waitUntilReady(HostPortWaitStrategy.java:47)
	at org.springframework.boot.testsupport.testcontainers.CassandraContainer$WaitStrategy.waitUntilReady(CassandraContainer.java:57)
	at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:32)
	at org.testcontainers.containers.GenericContainer.waitUntilContainerStarted(GenericContainer.java:531)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:258)
	at org.testcontainers.containers.GenericContainer.lambda$start$0(GenericContainer.java:209)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:207)
	at org.testcontainers.containers.GenericContainer.starting(GenericContainer.java:638)
	at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:29)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:379)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:340)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:125)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:413)

2018-05-11 09:48:51.098 ERROR 5291 --- [           main] 🐳 [cassandra:3.11.1]                    : Container log output (if any) will follow:

This time, however, the failure is then followed by numerous error messages from Docker Java that look like something possibly hasn't been cleaned up properly. Each failure looks like this:

2018-05-11 09:49:16.999 ERROR 5291 --- [iners-netty-1-1] c.g.d.core.async.ResultCallbackTemplate  : Error during callback

com.github.dockerjava.api.exception.InternalServerErrorException: {"message":"Container 06484b44ae48384289006a3af3892777a76cc5c0ac62bd0570ed0d325d902c16 is not running"}

	at com.github.dockerjava.netty.handler.HttpResponseHandler.channelRead0(HttpResponseHandler.java:109)
	at com.github.dockerjava.netty.handler.HttpResponseHandler.channelRead0(HttpResponseHandler.java:33)
	at org.testcontainers.shaded.io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at org.testcontainers.shaded.io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:438)
	at org.testcontainers.shaded.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
	at org.testcontainers.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:284)
	at org.testcontainers.shaded.io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:253)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at org.testcontainers.shaded.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1342)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at org.testcontainers.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at org.testcontainers.shaded.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:934)
	at org.testcontainers.shaded.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:979)
	at org.testcontainers.shaded.io.netty.channel.epoll.EpollDomainSocketChannel$EpollDomainUnsafe.epollInReady(EpollDomainSocketChannel.java:138)
	at org.testcontainers.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404)
	at org.testcontainers.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:307)
	at org.testcontainers.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at org.testcontainers.shaded.io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.base/java.lang.Thread.run(Thread.java:844)

Please let me know if I can provide any more information that would help to diagnose the issue.

GenericContainer.start と tryStart から始め、次にスタックトレースで参照されている HostPortWaitStrategy と CassandraContainer.java を調べます。CassandraDataAutoConfigurationIntegrationTests.java を使って失敗を再現し、タイムアウトした各試行の後に何が残るかを追跡します。失敗したコンテナーの起動によって、再試行のたびに報告されている Docker クライアントのエラーが繰り返し発生しなくなれば完了です。