dasniko/testcontainers-keycloak

Timeout exception in Spring Tests

Closed this issue · 12 comments

hantsy commented

Describe the bug

Follow the https://testcontainers.com/guides/securing-spring-boot-microservice-using-keycloak-and-testcontainers/, tried to use testcontainers Keycloak in my projects.

My config for bootstraping a Keycloak testcontainers

@TestConfiguration(proxyBeanMethods = false)
@EnableConfigurationProperties(value = [AppProperties::class])
@ImportAutoConfiguration(TestcontainersPropertySourceAutoConfiguration::class)
class TestConfig {

    companion object {
        const val POSTGRES_IMAGE: String = "postgres:16"
        const val KEYCLOAK_IMAGE: String = "quay.io/keycloak/keycloak:latest"
        const val REALM_IMPORT_FILE: String = "/keycloak/myrealm-realm.json"
        const val REALM_NAME: String = "myrealm"
    }

    @Bean
    @ServiceConnection
    fun postgres(): PostgreSQLContainer<*> = PostgreSQLContainer(POSTGRES_IMAGE)

    @Bean
    fun keycloak(registry: DynamicPropertyRegistry): KeycloakContainer {
        val kcContainer = KeycloakContainer(KEYCLOAK_IMAGE)
            .withRealmImportFile(REALM_IMPORT_FILE)
            .withStartupTimeout(Duration.ofMillis(500_000))

        registry.add("spring.security.oauth2.resourceserver.jwt.issuer-uri") {
            kcContainer.authServerUrl + "/realms/" + REALM_NAME
        }

        return kcContainer
    }
}

And when tried to call the users API like:

@Autowired
lateinit var keycloakContainer: KeycloakContainer

@Test
fun `get users from custom realm`() = runTest {
    val keycloak = keycloakContainer.keycloakAdminClient
    val etipRealm = keycloak.realm("myrealm").toRepresentation()

    etipRealm.users.forEach { log.debug("user: $it") }
    etipRealm.user("user1")?.also { log.debug("get uesr1: $it") }
}

And got the following result.

      Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'application': Error creating bean with name 'postgres' defined in io.etip.backend.externalApiTest.KeycloakUserTest$TestConfig: Container startup failed for image quay.io/keycloak/keycloak:latest

      Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'postgres' defined in io.etip.backend.externalApiTest.KeycloakUserTest$TestConfig: Container startup failed for image quay.io/keycloak/keycloak:latest

      Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed for image quay.io/keycloak/keycloak:latest

      Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception

      Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container

      Caused by: java.lang.IllegalStateException: Wait strategy failed. Container exited with code 1

      Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for URL to be accessible (http://localhost:32770/health/started should return HTTP 200)

      Caused by: org.rnorth.ducttape.TimeoutException: Timeout waiting for result with exception

      Caused by: java.lang.RuntimeException: java.net.ConnectException: Connection refused

      Caused by: java.net.ConnectException: Connection refused

Version

3.4.0

Expected behavior

I have run it on my local machine and also committed codes to Github to run tests by Github actions, both failed.

martijnhaex commented

We were still using keycloak version 23.0.3 the management port didn't contain the liveness endpoint (/health/started). When starting the KeycloakContainer with the default constructor the test were succeeding.

Alternative what solved it was to override the wait strategy, and using the default HTTP port

	@Container
	static final KeycloakContainer KEYCLOAK_TEST_CONTAINER = new KeycloakContainer("quay.io/keycloak/keycloak:23.0.3")
			.withRealmImportFile("keycloak/tenant-realm.json")
			.waitingFor(Wait.forHttp("/health/started").forPort(8080));
hantsy commented

@martijnhaex I encountered this issue when importing realm files, keycloak/keycloak#11664

Unluckily the docker logs are not shown in my IDE console as others when starting up the testcontainres. I set a large startup timeout and show logs via docker logs to see the details.

Manually remove the policies nodes via this comment to fix the issue.

martijnhaex commented

@hantsy that doesn't seem to be the case in my scenario. No policies in the imported realm, in the docker logs is even stated that the realm imported correctly.

When starting the container like

	@Container
	static final KeycloakContainer KEYCLOAK_TEST_CONTAINER = new KeycloakContainer("quay.io/keycloak/keycloak:23.0.3");

The liveness seems to fail

2:48:05.732 [docker-java-stream--668368833] INFO  tc.quay.io/keycloak/keycloak:23.0.3 - STDOUT: 2024-07-03 10:48:05,731 WARN  [org.keycloak.quarkus.runtime.KeycloakMain] (main) Running the server in development mode. DO NOT use this configuration in production.
12:49:54.323 [Test worker] ERROR tc.quay.io/keycloak/keycloak:23.0.3 - Could not start container
org.testcontainers.containers.ContainerLaunchException: Timed out waiting for URL to be accessible (http://localhost:55347/health/started should return HTTP 200)
	at org.testcontainers.containers.wait.strategy.HttpWaitStrategy.waitUntilReady(HttpWaitStrategy.java:320)
	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)
	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.junit.jupiter.TestcontainersExtension$StoreAdapter.start(TestcontainersExtension.java:280)
	at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.access$200(TestcontainersExtension.java:267)
	at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$null$4(TestcontainersExtension.java:82)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore.lambda$getOrComputeIfAbsent$5(NamespacedHierarchicalStore.java:147)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$MemoizingSupplier.computeValue(NamespacedHierarchicalStore.java:372)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$MemoizingSupplier.get(NamespacedHierarchicalStore.java:361)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$StoredValue.evaluate(NamespacedHierarchicalStore.java:308)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$StoredValue.access$200(NamespacedHierarchicalStore.java:287)
	at org.junit.platform.engine.support.store.NamespacedHierarchicalStore.getOrComputeIfAbsent(NamespacedHierarchicalStore.java:149)
	at org.junit.jupiter.engine.execution.NamespaceAwareStore.lambda$getOrComputeIfAbsent$2(NamespaceAwareStore.java:57)
	at org.junit.jupiter.engine.execution.NamespaceAwareStore.accessStore(NamespaceAwareStore.java:90)
	at org.junit.jupiter.engine.execution.NamespaceAwareStore.getOrComputeIfAbsent(NamespaceAwareStore.java:57)
	at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$startContainers$5(TestcontainersExtension.java:82)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.testcontainers.junit.jupiter.TestcontainersExtension.startContainers(TestcontainersExtension.java:82)
	at org.testcontainers.junit.jupiter.TestcontainersExtension.beforeAll(TestcontainersExtension.java:56)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$12(ClassBasedTestDescriptor.java:396)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:396)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:212)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:85)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:148)
	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:107)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
	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:568)
	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.proxy2/jdk.proxy2.$Proxy5.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:113)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:65)
	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.TimeoutException: Timeout waiting for result with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:54)
	at org.testcontainers.containers.wait.strategy.HttpWaitStrategy.waitUntilReady(HttpWaitStrategy.java:252)
	... 79 common frames omitted
Caused by: java.lang.RuntimeException: java.net.SocketException: Unexpected end of file from server
	at org.testcontainers.containers.wait.strategy.HttpWaitStrategy.lambda$null$6(HttpWaitStrategy.java:312)
	at org.rnorth.ducttape.ratelimits.RateLimiter.doWhenReady(RateLimiter.java:27)
	at org.testcontainers.containers.wait.strategy.HttpWaitStrategy.lambda$waitUntilReady$7(HttpWaitStrategy.java:257)
	at org.rnorth.ducttape.unreliables.Unreliables.lambda$retryUntilSuccess$0(Unreliables.java:43)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.net.SocketException: Unexpected end of file from server
	at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:936)
	at java.base/sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:759)
	at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:933)
	at java.base/sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:759)
	at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1688)
	at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1589)
	at java.base/java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:529)
	at org.testcontainers.containers.wait.strategy.HttpWaitStrategy.lambda$null$6(HttpWaitStrategy.java:276)
	... 7 common frames omitted

So seem to be a different, and more keycloak version/tag related.

tschuehly commented

Same issue here:

org.testcontainers.containers.ContainerLaunchException: Timed out waiting for URL to be accessible (http://localhost:32775/health/started should return HTTP 200)

upgraded from 3.3.1 to 3.4.0

With the following config:

    TestcontainersConfiguration.getInstance().updateUserConfig("testcontainers.reuse.enable", "true");
    keycloakContainer = new KeycloakContainer("quay.io/keycloak/keycloak:24.0.2")
        .withAdminPassword("admin")
        .withAdminUsername("admin")
        .withRealmImportFile("keycloak/test-realm.json")
        .withReuse(true);
    keycloakContainer.start();
    ```
dasniko commented

If you use version 3.4+ of this module with Keycloak prior to 25, these errors will occur.

hantsy commented

If you use version 3.4+ of this module with Keycloak prior to 25, these errors will occur.

I used the newest kc 25.0.1 with this testcotnainer-keycloak 3.4, and also got the issue. From the IDE console, it is a timeout exception, but check the docker logs, here I got the famous script upload failed error which exists in Keycloak for a long time.

hantsy commented

@martijnhaex Increase the startup timeout value, and use docker logs <docker id> to check the real reason in the Docker container.

dasniko commented

@hantsy The "script upload" issue is not related to this testcontainer module, this has to be fixed inside your realm json file.

The issue from @martijnhaex seems to be version related, as he mentioned 24.x explicitly in his code.

So, I'm going to close this issue. If you experience other errors, feel free to open a new issue.

hantsy commented

@dasniko The timeout exception is too generic here, we can not detect the real reason in Keycloak server.

I am not sure when this module does not expose the complete docker logs as Postgres (any server-side log is sent to our client console) etc. this module only shows the logs in console if connected successfully.

dasniko commented

@hantsy So this is still not a bug, but a feature request.
As you can see, I'm configuring a log consumer here:

testcontainers-keycloak/src/main/java/dasniko/testcontainers/keycloak/ExtendableKeycloakContainer.java

Line 138 in cebf232

withLogConsumer(new Slf4jLogConsumer(logger()));

In all of my projects, when having a slf4j compliant logging lib in the classpath during tests, I get all the container logs, at every time.

If you have a proposal, what I should do differently, please open a new issue with proper type and provide a PR with a possible solution. But there are no guarantees...

hantsy commented

I also used withLogConsumer{...} and tried to adapt the logs to my logger in the tests, as I described, it also did not print the full logs in the docker container.
https://github.com/hantsy/spring-security-oauth2-resourceserver-example/blob/master/src/test/kotlin/com/example/demo/KeycloakIntegrationTest.kt#L62