quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.73k stars 2.67k forks source link

Keycloak Devservice failed 'Timed out waiting for log output matching '.*Keycloak.*started.*' #33467

Closed drsarutobi8 closed 1 year ago

drsarutobi8 commented 1 year ago

Describe the bug

Cannot start the devservice as described in https://quarkus.io/guides/security-openid-connect-dev-services

Expected behavior

Keycloak devservice started

Actual behavior

when run with ./gradlew quarkusDev

2023-05-18 18:37:29,851 INFO  [🐳 .io/.0.2]] (build-13) Container quay.io/keycloak/keycloak:21.0.2 is starting: 53e1e5c5e4dba996c74a39480c20265bea4163b3354818737181f4f9bd39919f
2023-05-18 18:38:31,337 ERROR [🐳 .io/.0.2]] (build-13) Could not start container: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Keycloak.*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:953)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:485)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:344)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:334)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.lambda$startContainer$4(KeycloakDevServicesProcessor.java:372)
    at java.base/java.util.Optional.orElseGet(Optional.java:364)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startContainer(KeycloakDevServicesProcessor.java:397)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:195)
    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 io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
    at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at java.base/java.lang.Thread.run(Thread.java:833)
    at org.jboss.threads.JBossThread.run(JBossThread.java:501)

2023-05-18 18:38:31,361 ERROR [🐳 .io/.0.2]] (build-13) Log output from the failed container:
Changes detected in configuration. Updating the server image.
Updating the configuration and installing your custom providers, if any. Please wait.
2023-05-18 11:37:46,824 WARN  [org.keycloak.common.Profile] (main) Experimental features enabled: map-storage
2023-05-18 11:37:46,907 WARN  [org.keycloak.common.Profile] (main) Experimental features enabled: map-storage
2023-05-18 11:37:49,656 WARN  [org.keycloak.common.Profile] (build-25) Experimental features enabled: map-storage
2023-05-18 11:37:49,713 WARN  [org.keycloak.common.Profile] (build-34) Experimental features enabled: map-storage
2023-05-18 11:37:51,711 WARN  [io.quarkus.hibernate.orm.deployment.HibernateOrmProcessor] (build-73) Hibernate ORM is disabled because no JPA entities were found

2023-05-18 18:38:31,366 INFO  [io.qua.dep.dev.IsolatedDevModeMain] (main) Attempting to start live reload endpoint to recover from previous Quarkus startup failure
2023-05-18 18:38:31,703 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to start quarkus: java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
    [error]: Build step io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor#startKeycloakContainer threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:247)
    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 io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
    at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at java.base/java.lang.Thread.run(Thread.java:833)
    at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:349)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.lambda$startContainer$4(KeycloakDevServicesProcessor.java:372)
    at java.base/java.util.Optional.orElseGet(Optional.java:364)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startContainer(KeycloakDevServicesProcessor.java:397)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:195)
    ... 11 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:334)
    ... 16 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:542)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:344)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    ... 17 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Keycloak.*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:953)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:485)
    ... 19 more

    at io.quarkus.runner.bootstrap.AugmentActionImpl.runAugment(AugmentActionImpl.java:335)
    at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:252)
    at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:60)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:86)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
    [error]: Build step io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor#startKeycloakContainer threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:247)
    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 io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
    at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at java.base/java.lang.Thread.run(Thread.java:833)
    at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:349)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.lambda$startContainer$4(KeycloakDevServicesProcessor.java:372)
    at java.base/java.util.Optional.orElseGet(Optional.java:364)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startContainer(KeycloakDevServicesProcessor.java:397)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:195)
    ... 11 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:334)
    ... 16 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:542)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:344)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    ... 17 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Keycloak.*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:953)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:485)
    ... 19 more

    at io.quarkus.builder.Execution.run(Execution.java:123)
    at io.quarkus.builder.BuildExecutionBuilder.execute(BuildExecutionBuilder.java:79)
    at io.quarkus.deployment.QuarkusAugmentor.run(QuarkusAugmentor.java:160)
    at io.quarkus.runner.bootstrap.AugmentActionImpl.runAugment(AugmentActionImpl.java:331)
    ... 9 more
Caused by: java.lang.RuntimeException: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:247)
    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 io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:909)
    at io.quarkus.builder.BuildContext.run(BuildContext.java:282)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at java.base/java.lang.Thread.run(Thread.java:833)
    at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:349)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.lambda$startContainer$4(KeycloakDevServicesProcessor.java:372)
    at java.base/java.util.Optional.orElseGet(Optional.java:364)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startContainer(KeycloakDevServicesProcessor.java:397)
    at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.startKeycloakContainer(KeycloakDevServicesProcessor.java:195)
    ... 11 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:334)
    ... 16 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:542)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:344)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    ... 17 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Keycloak.*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:953)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:485)
    ... 19 more

How to Reproduce?

  1. create new quarkus project

    quarkus create app --gradle-kotlin-dsl

  2. cd inside project and then run

    ./gradlew addExtension --extensions='quarkus-oidc'

  3. run quarkusDev

    ./gradlew --console=plain quarkusDev

Output of uname -a or ver

Linux mrwhite 5.19.0-41-generic #42~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Tue Apr 18 17:40:00 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

openjdk version "17.0.7" 2023-04-18 OpenJDK Runtime Environment (build 17.0.7+7-Ubuntu-0ubuntu122.04.2) OpenJDK 64-Bit Server VM (build 17.0.7+7-Ubuntu-0ubuntu122.04.2, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.0.3.Final

Build tool (ie. output of mvnw --version or gradlew --version)

------------------------------------------------------------ Gradle 8.1.1 ------------------------------------------------------------ Build time: 2023-04-21 12:31:26 UTC Revision: 1cf537a851c635c364a4214885f8b9798051175b Kotlin: 1.8.10 Groovy: 3.0.15 Ant: Apache Ant(TM) version 1.10.11 compiled on July 10 2021 JVM: 17.0.7 (Private Build 17.0.7+7-Ubuntu-0ubuntu122.04.2) OS: Linux 5.19.0-41-generic amd64

Additional information

this also happens with quarkus 2.16.7

quarkus-bot[bot] commented 1 year ago

/cc @evanchooly (kotlin), @geoand (kotlin), @pedroigor (keycloak), @sberyozkin (keycloak)

geoand commented 1 year ago

I just tried this and it worked perfectly for me:

2023-05-19 10:03:15,659 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-38) Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2023-05-19 10:03:15,856 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-38) Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
2023-05-19 10:03:15,857 INFO  [org.tes.DockerClientFactory] (build-38) Docker host IP address is localhost
2023-05-19 10:03:15,865 INFO  [org.tes.DockerClientFactory] (build-38) Connected to docker: 
  Server Version: 24.0.0
  API Version: 1.43
  Operating System: Ubuntu 22.04.2 LTS
  Total Memory: 64230 MB
2023-05-19 10:03:15,872 INFO  [org.tes.uti.ImageNameSubstitutor] (build-38) Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2023-05-19 10:03:15,874 INFO  [org.tes.DockerClientFactory] (build-38) Checking the system...
2023-05-19 10:03:15,874 INFO  [org.tes.DockerClientFactory] (build-38) ✔︎ Docker server version should be at least 1.6.0
2023-05-19 10:03:15,886 INFO  [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-38) Using Quarkus powered Keycloak distribution
2023-05-19 10:03:15,913 INFO  [🐳 .io/.0.2]] (build-38) Creating container for image: quay.io/keycloak/keycloak:21.0.2
2023-05-19 10:03:15,915 INFO  [org.tes.uti.RegistryAuthLocator] (build-38) Failure when attempting to lookup auth config. Please ignore if you don't have images in an authenticated registry. Details: (dockerImageName: quay.io/keycloak/keycloak:21.0.2, configFile: /home/gandrian/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/gandrian/.docker/config.json (No such file or directory)
2023-05-19 10:03:15,920 INFO  [🐳 .3.4]] (build-38) Creating container for image: testcontainers/ryuk:0.3.4
2023-05-19 10:03:15,920 INFO  [org.tes.uti.RegistryAuthLocator] (build-38) Failure when attempting to lookup auth config. Please ignore if you don't have images in an authenticated registry. Details: (dockerImageName: testcontainers/ryuk:0.3.4, configFile: /home/gandrian/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/gandrian/.docker/config.json (No such file or directory)
2023-05-19 10:03:15,979 INFO  [🐳 .3.4]] (build-38) Container testcontainers/ryuk:0.3.4 is starting: 7423dcc9e9d0cb3d8212dbc8fa9d9f0333874cbc9e80450dbd503441c873f4aa
2023-05-19 10:03:16,233 INFO  [🐳 .3.4]] (build-38) Container testcontainers/ryuk:0.3.4 started in PT0.313026198S
2023-05-19 10:03:16,245 INFO  [🐳 .io/.0.2]] (build-38) Container quay.io/keycloak/keycloak:21.0.2 is starting: 1bfca39388b97cd51b3ada6ed52e91971a4346a012fedded5190363965e36f8a
2023-05-19 10:03:20,979 INFO  [🐳 .io/.0.2]] (build-38) Container quay.io/keycloak/keycloak:21.0.2 started in PT5.091985938S
2023-05-19 10:03:21,721 INFO  [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-38) Dev Services for Keycloak started.
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2023-05-19 10:03:22,301 WARN  [io.qua.oid.run.TenantConfigContext] (vert.x-eventloop-thread-1) Secret key for encrypting tokens should be 32 characters long
2023-05-19 10:03:22,353 INFO  [io.quarkus] (Quarkus Main Thread) code-with-quarkus 1.0.0-SNAPSHOT on JVM (powered by Quarkus 3.0.3.Final) started in 7.161s. Listening on: http://localhost:8080
2023-05-19 10:03:22,354 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2023-05-19 10:03:22,354 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, oidc, resteasy-reactive, security, smallrye-context-propagation, vertx]
sberyozkin commented 1 year ago

Hi, thanks @geoand, missed that you already tried it :-), I was testing it too and yes, works for me.

My guess is, it may be taking awhile to download a Keycloak image, so @drsarutobi8 if you fetch it with docker first before starting devmode it should work fine.

Or a global quarkus.devservices.timeout property can help, set it for example to 2 mins (in Java Duration format)

sberyozkin commented 1 year ago

@drsarutobi8 I've opened a PR to explain in the docs how to configure a timeout, it will resolve this issue once reviewed/approved, give it a go (or like I said above, get the image with the docker directly first) and re-open if still won't work, thanks

drsarutobi8 commented 1 year ago

yes, after adding application.properties

quarkus.devservices.timeout=2m  

it works now. Thank you so much. @geoand @sberyozkin