LogMessageWaitStrategy does not work for compose based restarting containers

[Mingela]

Hello!

The case is following:

• testcontainers-java 1.14.3
• docker-compose.yml with services A, B, C
• B depends on A
• C depends on B and A
• withLocalCompose(true)

A starts quite quickly, B start takes ~40 seconds
While B is unavailable C keeps restarting

• Tried Wait.forLogMessage() for A - works
• Tried Wait.forLogMessage() for B - works
• Tried Wait.forLogMessage() for C - Timed out waiting for log output matching <log>
• Tried Wait.forLogMessage() for both B and C - Timed out waiting for log output matching <log>

Actually I'm interested in waiting for both of the services B and C explicitly, but only C should be valid as well.

Tried all the possible regex stuff (.*log.*, .*log.*\\s, .*log!\\s, .*log.*\n.* etc)

From my impression it seems that log polling breaks for a restarting container.
The difference between B and C here is that when starting B does not encounter broken B->A interaction since A could easily be started for the time of starting B. Hence B does not get restarted 'on error'.

As I got from debugging

testcontainers-java/core/src/main/java/org/testcontainers/containers/output/WaitingConsumer.java

Line 85 in 816b8c3

OutputFrame frame = frames.pollLast(100, TimeUnit.MILLISECONDS);

becomes null when the container is going to start successfully, it's really strange. It contains lines from a stacktrace when the container is going to be restarted and null when it's running

Any ideas? Thanks.

p.s. of course I see the desired log of the C in my terminal using docker logs C

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you believe this is a mistake, please reply to this comment to keep it open. If there isn't one already, a PR to fix or at least reproduce the problem in a test case will always help us get back on track to tackle this.

[Mingela]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you believe this is a mistake, please reply to this comment to keep it open. If there isn't one already, a PR to fix or at least reproduce the problem in a test case will always help us get back on track to tackle this.

Would be good to grab some attention from devs

[olarende-tink]

Can confirm that this issue is affecting me as well. LogConsumers also have problems with restarting containers: the first container's logs are captured, but not subsequent containers.

[abendt]

we also ran into that issue and created a setup to reproduce the issue:
https://github.com/abendt/TestContainersWaitStrategy

in our scenario we are restarting the docker compose container programatically

to reproduce:
run the main method here: https://github.com/abendt/TestContainersWaitStrategy/blob/main/src/main/kotlin/demo/Main.kt#L15

you can see that restart of the docker compose container will fail then (https://github.com/abendt/TestContainersWaitStrategy/blob/main/src/main/kotlin/demo/Main.kt#L34)

[dacr]

Also went into the same this bug :( in a multiple containers scenario (Started through a docker compose file)

Exception encountered when invoking run on a nested suite - org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Kafka startTimeMs.*'
java.lang.RuntimeException: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Kafka startTimeMs.*'
	at org.rnorth.ducttape.timeouts.Timeouts.callFuture(Timeouts.java:68)
	at org.rnorth.ducttape.timeouts.Timeouts.doWithTimeout(Timeouts.java:60)
	at org.testcontainers.containers.wait.strategy.WaitAllStrategy.waitUntilReady(WaitAllStrategy.java:54)
	at org.testcontainers.containers.ComposeDelegate.waitUntilServiceStarted(ComposeDelegate.java:210)
	at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1608)
	at org.testcontainers.containers.ComposeDelegate.waitUntilServiceStarted(ComposeDelegate.java:184)
	at org.testcontainers.containers.ComposeContainer.start(ComposeContainer.java:143)
	at com.dimafeng.testcontainers.DockerComposeContainer.start(DockerComposeContainer.scala:184)
	at com.dimafeng.testcontainers.ContainerDef.start(ContainerDef.scala:14)
	at com.dimafeng.testcontainers.ContainerDef.start$(ContainerDef.scala:6)
	at com.dimafeng.testcontainers.DockerComposeContainer$Def.start(DockerComposeContainer.scala:88)
	at com.orange.thingin.stat.MainTest.startContainers(MainTest.scala:36)
	at com.orange.thingin.stat.MainTest.startContainers(MainTest.scala:35)
	at com.dimafeng.testcontainers.scalatest.TestContainersForAll.run(TestContainersForAll.scala:41)
	at com.dimafeng.testcontainers.scalatest.TestContainersForAll.run$(TestContainersForAll.scala:34)
	at com.orange.thingin.stat.MainTest.run(MainTest.scala:18)
	at org.scalatest.tools.SuiteRunner.run(SuiteRunner.scala:47)
	at org.scalatest.tools.Runner$.doRunRunRunDaDoRunRun$$anonfun$1(Runner.scala:1321)
	at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
	at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
	at scala.collection.immutable.List.foreach(List.scala:334)
	at org.scalatest.tools.Runner$.doRunRunRunDaDoRunRun(Runner.scala:1323)
	at org.scalatest.tools.Runner$.runOptionallyWithPassFailReporter$$anonfun$2(Runner.scala:992)
	at scala.runtime.function.JProcedure2.apply(JProcedure2.java:15)
	at scala.runtime.function.JProcedure2.apply(JProcedure2.java:10)
	at org.scalatest.tools.Runner$.withClassLoaderAndDispatchReporter(Runner.scala:1481)
	at org.scalatest.tools.Runner$.runOptionallyWithPassFailReporter(Runner.scala:993)
	at org.scalatest.tools.Runner$.run(Runner.scala:798)
	at org.scalatest.tools.Runner.run(Runner.scala)
	at org.jetbrains.plugins.scala.testingSupport.scalaTest.ScalaTestRunner.runScalaTest2or3(ScalaTestRunner.java:43)
	at org.jetbrains.plugins.scala.testingSupport.scalaTest.ScalaTestRunner.main(ScalaTestRunner.java:26)
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Kafka startTimeMs.*'
	at org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:47)
	at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:52)
	at org.testcontainers.containers.wait.strategy.WaitAllStrategy.waitUntilNestedStrategiesAreReady(WaitAllStrategy.java:66)
	at org.testcontainers.containers.wait.strategy.WaitAllStrategy.lambda$waitUntilReady$0(WaitAllStrategy.java:58)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1575)