Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: Latest Ryuk changed the log to "starting" but Ryuk container expects "Started" #9369

Closed
mdelapenya opened this issue Oct 9, 2024 · 5 comments
Labels

Comments

@mdelapenya
Copy link
Member

Module

Core

Testcontainers version

Latest

Using the latest Testcontainers version?

Yes

Host OS

Any

Host Arch

Any

Docker version

Client:
Version: 27.2.1-rd
API version: 1.43 (downgraded from 1.47)
Go version: go1.22.7
Git commit: cc0ee3e
Built: Tue Sep 10 15:41:09 2024
OS/Arch: darwin/arm64
Context: tcd

Server: Testcontainers Cloud
Engine:
Version: 82+testcontainerscloud
API version: 1.46 (minimum version 1.24)
Go version: go1.21.12
Git commit: cc13f952511154a2866bddbb7dddebfe9e83b801
Built: Thu Aug 1 16:00:49 2024
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.7.12
GitCommit:
runc:
Version: 1.1.12-0ubuntu2~22.04.1
GitCommit:
docker-init:
Version: 0.19.0
GitCommit:

What happened?

testcontainers/moby-ryuk#141 changed the log format to be more structured and used lowercase

Relevant log output

Starting Ryuk:

time=2024-09-30T19:42:30.000+01:00 level=INFO msg=starting connection_timeout=1m0s reconnection_timeout=10s request_timeout=10s shutdown_timeout=10m0s remove_retries=10 retry_offset=-1s port=8080 verbose=false
time=2024-09-30T19:42:30.001+01:00 level=INFO msg=listening address=[::]:8080
time=2024-09-30T19:42:30.001+01:00 level=INFO msg="client processing started"
time=2024-09-30T19:42:38.002+01:00 level=INFO msg="client connected" address=127.0.0.1:56432 clients=1
time=2024-09-30T19:42:38.002+01:00 level=INFO msg="adding filter" type=label values="[testing=true testing.sessionid=mysession]"
time=2024-09-30T19:42:38.002+01:00 level=INFO msg="adding filter" type=label values=[something]
time=2024-09-30T19:42:38.002+01:00 level=INFO msg="client disconnected" address=127.0.0.1:56432 clients=0
time=2024-09-30T19:42:42.047+01:00 level=INFO msg="adding filter" type=label values=[something_else]
time=2024-09-30T19:42:42.047+01:00 level=INFO msg="client connected" address=127.0.0.1:56434 clients=1
time=2024-09-30T19:42:42.047+01:00 level=INFO msg="client disconnected" address=127.0.0.1:56434 clients=0
time=2024-09-30T19:42:52.051+01:00 level=INFO msg="prune check" clients=0
time=2024-09-30T19:42:52.216+01:00 level=INFO msg="client processing stopped"
time=2024-09-30T19:42:52.216+01:00 level=INFO msg=removed containers=0 networks=0 volumes=0 images=0
time=2024-09-30T19:42:52.216+01:00 level=INFO msg=done

Additional Information

1.17 works but latest does not

@stevenh
Copy link

stevenh commented Oct 9, 2024

I would recommend waiting for port instead of logs, logs are always fragile and can lead to race cases which this would be as starting is output before it's actually able to accept connections. While this is likely to work it could fail.

@eddumelendez
Copy link
Member

eddumelendez commented Oct 9, 2024

what does 1.17 works but latest does not mean?

I think next time we should consider that there are users updating the image via testcontainers.properties when doing those changes.

@mdelapenya
Copy link
Member Author

what does 1.17 works but latest does not mean?

@Kehrlann could you share the analysis you did so we can learn more about how to verify this kind of regressions beforehand? 🙏

In any case, we released a patch release in Ryuk keeping the old behaviour in the log, so I think we can close this one.

@Kehrlann
Copy link

Kehrlann commented Oct 11, 2024

Repro case was a simple testcontainers test, running against ryuk:0.10.0

The test:

import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.Test;
import org.testcontainers.containers.GenericContainer;

import java.net.URI;
import java.net.http.HttpClient;
import java.net.http.HttpRequest;
import java.net.http.HttpResponse;

import static org.assertj.core.api.Assertions.assertThat;

class TestcontainersTest {
    private static final boolean DEBUG = false;

    @Test
    void test() throws Exception {
        try (GenericContainer<?> nginx = new GenericContainer<>("nginx:1-alpine-slim")) {
            nginx.withExposedPorts(80).start();
            HttpClient httpClient = HttpClient.newBuilder().build();
            String url = String.format("http://%s:%d", nginx.getHost(), nginx.getFirstMappedPort());
            HttpResponse<String> response = httpClient.send(HttpRequest.newBuilder().GET().uri(URI.create(url)).build(), HttpResponse.BodyHandlers.ofString());
            assertThat(response.statusCode()).isEqualTo(200);
            assertThat(response.body()).contains("<h1>Welcome to nginx!</h1>");
        }
    }
}

testcontainers.properties:

ryuk.container.image=testcontainers/ryuk:0.10.0

Tested in Testcontainers 1.17.1

The test succeeds and works as expected.

Tested in Testcontainers 1.19.8

The test fails after a timeout, with log (full log at the end):

[Test worker] ERROR tc.testcontainers/ryuk:0.10.0 - Could not start container

Analysis

The issue is that RyukContainer waits for the explicit log .*Started.* with capital S (source). But Ryuk changed the logs and it does not print started anymore, so the container is not detected to be running.

In 1.17.1, the RyukContainer did not exist and RyukReaper created the ryuk container inline (source) and did not implement this "wait-for-logline" strategy. AFAIK RyukContainer was introduced in 1.17.2 and therefore all tc-java version >= 1.17.2 are incompatible with ryuk:0.10.0

Conclusion

I agree with @stevenh , waiting on specific logs is brittle.

In the meantime, @mdelapenya has mitigated this issue by releasing ryuk:0.10.1 which re-introduces the Started word in the logs.

Appendix: full stack trace in TC 1.19.8

[Test worker] WARN org.testcontainers.dockerclient.DockerClientProviderStrategy - DOCKER_HOST tcp://127.0.0.1:49245 is not listening
[Test worker] WARN org.testcontainers.dockerclient.DockerClientProviderStrategy - DOCKER_HOST tcp://127.0.0.1:49245 is not listening
[Test worker] WARN org.testcontainers.utility.ConfigurationFileImageNameSubstitutor - Image name testcontainers/ryuk:0.7.0 was substituted by configuration to testcontainers/ryuk:0.10.0. This approach is deprecated and will be removed in the future
[Test worker] ERROR tc.testcontainers/ryuk:0.10.0 - Could not start container
java.lang.IllegalStateException: Wait strategy failed. Container is removed
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:511)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org.testcontainers.utility.RyukResourceReaper.maybeStart(RyukResourceReaper.java:78)
	at org.testcontainers.utility.RyukResourceReaper.register(RyukResourceReaper.java:68)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:434)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org_testcontainers.testcontainers.TestcontainersTest.test(TestcontainersTest.java:31)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
	at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:119)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:94)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:89)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:62)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at jdk.proxy1/jdk.proxy1.$Proxy2.stop(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
	at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:119)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:66)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Started.*'
	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.GenericContainer.waitUntilContainerStarted(GenericContainer.java:909)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
	... 97 more
[Test worker] ERROR tc.testcontainers/ryuk:0.10.0 - There are no stdout/stderr logs available for the failed container
[Test worker] ERROR tc.nginx:1-alpine-slim - Could not start container
org.testcontainers.containers.ContainerLaunchException: Container startup failed for image testcontainers/ryuk:0.10.0
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:359)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org.testcontainers.utility.RyukResourceReaper.maybeStart(RyukResourceReaper.java:78)
	at org.testcontainers.utility.RyukResourceReaper.register(RyukResourceReaper.java:68)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:434)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org_testcontainers.testcontainers.TestcontainersTest.test(TestcontainersTest.java:31)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
	at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:119)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:94)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:89)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:62)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at jdk.proxy1/jdk.proxy1.$Proxy2.stop(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
	at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:119)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:66)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	... 94 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 95 more
Caused by: java.lang.IllegalStateException: Wait strategy failed. Container is removed
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:511)
	... 97 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Started.*'
	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.GenericContainer.waitUntilContainerStarted(GenericContainer.java:909)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
	... 97 more

Container startup failed for image nginx:1-alpine-slim
org.testcontainers.containers.ContainerLaunchException: Container startup failed for image nginx:1-alpine-slim
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:359)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org_testcontainers.testcontainers.TestcontainersTest.test(TestcontainersTest.java:31)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	... 5 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 6 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed for image testcontainers/ryuk:0.10.0
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:359)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at org.testcontainers.utility.RyukResourceReaper.maybeStart(RyukResourceReaper.java:78)
	at org.testcontainers.utility.RyukResourceReaper.register(RyukResourceReaper.java:68)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:434)
	... 8 more
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	... 12 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 13 more
Caused by: java.lang.IllegalStateException: Wait strategy failed. Container is removed
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:511)
	... 15 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Started.*'
	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.GenericContainer.waitUntilContainerStarted(GenericContainer.java:909)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
	... 15 more


Retry limit hit with exception
org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at app//org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
	at app//org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	at app//org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at app//org_testcontainers.testcontainers.TestcontainersTest.test(TestcontainersTest.java:31)
	at [email protected]/java.lang.reflect.Method.invoke(Method.java:569)
	at [email protected]/java.util.ArrayList.forEach(ArrayList.java:1511)
	at [email protected]/java.util.ArrayList.forEach(ArrayList.java:1511)
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
	at app//org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at app//org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 6 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed for image testcontainers/ryuk:0.10.0
	at app//org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:359)
	at app//org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
	at app//org.testcontainers.utility.RyukResourceReaper.maybeStart(RyukResourceReaper.java:78)
	at app//org.testcontainers.utility.RyukResourceReaper.register(RyukResourceReaper.java:68)
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:434)
	... 8 more
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at app//org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
	at app//org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
	... 12 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
	at app//org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
	at app//org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 13 more
Caused by: java.lang.IllegalStateException: Wait strategy failed. Container is removed
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:511)
	... 15 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Started.*'
	at app//org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:47)
	at app//org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:52)
	at app//org.testcontainers.containers.GenericContainer.waitUntilContainerStarted(GenericContainer.java:909)
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
	... 15 more

@kiview
Copy link
Member

kiview commented Oct 11, 2024

I would recommend waiting for port instead of logs, logs are always fragile and can lead to race cases which this would be as starting is output before it's actually able to accept connections.

That absolutely depends on the image, for some images, a log based wait strategy is proven to be the most stable integration point for the actual wait behavior (PostgreSQL is such an example, that will have the port open considerable time before actual readiness and the database engine restart means, that log message based wait strategy is unfortunately the best indicator of non-flaky readiness).

@eddumelendez is also right with avoiding a breaking change for users upgrading the image manually. So reverting the breaking change in an integration point in Ryuk is the right thing to do here.

I'll close this issue, since it is not a bug in tc-java and we did revert the breaking change already in Ryuk.

@kiview kiview closed this as completed Oct 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants