quarkusio / quarkus

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

Oidc devservice not starting properly with autoconfiguration #42331

Closed bulldog98 closed 1 month ago

bulldog98 commented 3 months ago

Describe the bug

When creating a project with oidc extension and no configuration for it, the dev service is started in dev mode.

Console log Unauthorized ``` 2024-08-06 06:30:52,550 ERROR [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-13) Admin token can not be acquired due to a client connection timeout. You may try increasing the `quarkus.oidc.devui.web-client-timeout` property. 2024-08-06 06:30:52,700 ERROR [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-13) Realm quarkus can not be created 401 - Unauthorized 2024-08-06 06:31:00,759 ERROR [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-13) Realm quarkus can not be created: java.lang.RuntimeException: Keycloak server is not available: Retries exhausted : 4 attempts against 1722918662758/1722918662701 expiration at io.quarkus.oidc.deployment.devservices.keycloak.KeycloakDevServicesProcessor.lambda$createRealm$7(KeycloakDevServicesProcessor.java:723) at io.smallrye.mutiny.operators.uni.UniOnFailureTransform$UniOnFailureTransformProcessor.onFailure(UniOnFailureTransform.java:54) at io.smallrye.mutiny.operators.uni.builders.UniCreateFromPublisher$PublisherSubscriber.onError(UniCreateFromPublisher.java:78) at io.smallrye.mutiny.helpers.HalfSerializer.onError(HalfSerializer.java:59) at io.smallrye.mutiny.helpers.StrictMultiSubscriber.onFailure(StrictMultiSubscriber.java:90) at io.smallrye.mutiny.subscription.MultiSubscriber.onError(MultiSubscriber.java:73) at io.smallrye.mutiny.subscription.SerializedSubscriber.onFailure(SerializedSubscriber.java:101) at io.smallrye.mutiny.operators.multi.MultiRetryWhenOp$RetryWhenOperator.whenFailure(MultiRetryWhenOp.java:165) at io.smallrye.mutiny.operators.multi.MultiRetryWhenOp$TriggerSubscriber.onError(MultiRetryWhenOp.java:193) at io.smallrye.mutiny.helpers.HalfSerializer.onError(HalfSerializer.java:59) at io.smallrye.mutiny.helpers.StrictMultiSubscriber.onFailure(StrictMultiSubscriber.java:90) at io.smallrye.mutiny.operators.multi.MultiConcatMapOp$MainSubscriber.innerOnFailure(MultiConcatMapOp.java:167) at io.smallrye.mutiny.operators.multi.MultiConcatMapOp$MainSubscriber$InnerSubscriber.onFailure(MultiConcatMapOp.java:307) at io.smallrye.mutiny.subscription.MultiSubscriber.onError(MultiSubscriber.java:73) at io.smallrye.mutiny.converters.uni.UniToMultiPublisher$UniToMultiSubscription.onFailure(UniToMultiPublisher.java:104) at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownFailure$KnownFailureSubscription.forward(UniCreateFromKnownFailure.java:38) at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownFailure.subscribe(UniCreateFromKnownFailure.java:23) at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36) at io.smallrye.mutiny.converters.uni.UniToMultiPublisher$UniToMultiSubscription.request(UniToMultiPublisher.java:74) at io.smallrye.mutiny.operators.multi.MultiConcatMapOp$MainSubscriber.innerOnSubscribe(MultiConcatMapOp.java:109) at io.smallrye.mutiny.operators.multi.MultiConcatMapOp$MainSubscriber$InnerSubscriber.onSubscribe(MultiConcatMapOp.java:297) at io.smallrye.mutiny.converters.uni.UniToMultiPublisher.subscribe(UniToMultiPublisher.java:25) at io.smallrye.mutiny.groups.MultiCreate$1.subscribe(MultiCreate.java:165) at io.smallrye.mutiny.operators.multi.MultiConcatMapOp$MainSubscriber.onItem(MultiConcatMapOp.java:119) at io.smallrye.mutiny.subscription.MultiSubscriber.onNext(MultiSubscriber.java:61) at io.smallrye.mutiny.operators.multi.processors.UnicastProcessor.drainWithDownstream(UnicastProcessor.java:107) at io.smallrye.mutiny.operators.multi.processors.UnicastProcessor.drain(UnicastProcessor.java:138) at io.smallrye.mutiny.operators.multi.processors.UnicastProcessor.onNext(UnicastProcessor.java:204) at io.smallrye.mutiny.operators.multi.processors.SerializedProcessor.onNext(SerializedProcessor.java:104) at io.smallrye.mutiny.subscription.SerializedSubscriber.onItem(SerializedSubscriber.java:74) at io.smallrye.mutiny.subscription.MultiSubscriber.onNext(MultiSubscriber.java:61) at io.smallrye.mutiny.operators.multi.MultiRetryWhenOp$RetryWhenOperator.onFailure(MultiRetryWhenOp.java:127) at io.smallrye.mutiny.subscription.MultiSubscriber.onError(MultiSubscriber.java:73) at io.smallrye.mutiny.converters.uni.UniToMultiPublisher$UniToMultiSubscription.onFailure(UniToMultiPublisher.java:104) at io.smallrye.mutiny.operators.uni.UniOnItemTransform$UniOnItemTransformProcessor.onItem(UniOnItemTransform.java:40) at io.smallrye.mutiny.vertx.AsyncResultUni.lambda$subscribe$1(AsyncResultUni.java:35) at io.smallrye.mutiny.vertx.DelegatingHandler.handle(DelegatingHandler.java:25) at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java:397) at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:384) at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:362) at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:329) at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:291) at io.vertx.ext.web.client.impl.HttpContext.lambda$null$7(HttpContext.java:507) at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:279) at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:261) at io.vertx.core.impl.ContextInternal.lambda$runOnContext$0(ContextInternal.java:59) at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at ##java.base/java.lang.Thread.run(Thread.java:1583) ```

In the dev-ui keycloak admin link leads to a keycloak page telling "HTTPS required"

Expected behavior

Actual behavior

How to Reproduce?

  1. create a project with oidc extension
  2. start dev mode

I have a reproducer git repo reproduce-oidc-dev-service-problem

Output of uname -a or ver

No response

Output of java -version

openjdk version "21" 2023-09-19 LTS OpenJDK Runtime Environment Corretto-21.0.0.35.1 (build 21+35-LTS) OpenJDK 64-Bit Server VM Corretto-21.0.0.35.1 (build 21+35-LTS, mixed mode, sharing)

Quarkus version or git rev

3.8, 3.13

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

tried mvn and gradle

Additional information

No response

quarkus-bot[bot] commented 3 months ago

/cc @geoand (devservices), @pedroigor (oidc), @radcortez (config), @sberyozkin (oidc), @stuartwdouglas (devservices)

geoand commented 3 months ago

I just started the reproducer you provided and Quarkus started and configured Keycloak just fine:

Screenshot from 2024-08-07 13-00-11

bulldog98 commented 3 months ago

Have you gone to the dev ui and tried to open the keycloak admin ui, yes it configures something for keycloak, but my experience was that the values provided did not seem to match what keycloak wants and keycloak seems to not have generated the quarkus realm

geoand commented 3 months ago

I have

bulldog98 commented 2 months ago

Hm strange I started that exact project on my machine and the keycloak ui tells me https required. I'll post the output of docker ps and the logs of keycloak.

CONTAINER ID   IMAGE                              COMMAND                  CREATED          STATUS          PORTS                                                   NAMES
66bd8565b54a   quay.io/keycloak/keycloak:24.0.4   "/opt/keycloak/bin/k…"   33 seconds ago   Up 31 seconds   8443/tcp, 0.0.0.0:32770->8080/tcp, :::32770->8080/tcp   dazzling_golick
ee6c02f9331f   testcontainers/ryuk:0.6.0          "/bin/ryuk"              33 seconds ago   Up 32 seconds   0.0.0.0:32769->8080/tcp, :::32769->8080/tcp             testcontainers-ryuk-47101728-be34-431e-a1ab-75215cfbe367
Keycloak logs ``` Changes detected in configuration. Updating the server image. Updating the configuration and installing your custom providers, if any. Please wait. 2024-08-08 05:09:01,728 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index jakarta.jms.XAConnection: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,729 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index jakarta.jms.XASession: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,730 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index jakarta.jms.XAConnectionFactory: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,779 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index io.mashona.logwriting.ArrayStore: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,781 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.apache.activemq.artemis.core.journal.RecordInfo: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,781 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.apache.activemq.artemis.core.journal.Journal: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,800 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.apache.tools.ant.Task: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,837 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.springframework.core.io.Resource: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,838 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.springframework.core.io.DefaultResourceLoader: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,839 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index org.springframework.core.io.ResourceLoader: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:01,850 WARN [io.qua.dep.ind.IndexWrapper] (build-83) Failed to index jakarta.jms.Connection: Class does not exist in ClassLoader QuarkusClassLoader:Deployment Class Loader: PROD for keycloak@62b3df3a 2024-08-08 05:09:06,814 INFO [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 8594ms Server configuration updated and persisted. Run the following command to review the configuration: kc.sh show-config Next time you run the server, just run: kc.sh start --http-enabled=true --hostname-strict=false --hostname-strict-https=false --spi-user-profile-declarative-user-profile-config-file=/opt/keycloak/upconfig.json --optimized 2024-08-08 05:09:08,480 INFO [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller' 2024-08-08 05:09:08,660 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration! 2024-08-08 05:09:08,812 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN` 2024-08-08 05:09:08,818 INFO [org.jgroups.JChannel] (keycloak-cache-init) local_addr: 041d7286-8600-4dc1-9a6e-4f3fb3175d6c, name: 66bd8565b54a-31919 2024-08-08 05:09:08,832 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1MB, but the OS only allocated 212.99KB 2024-08-08 05:09:08,832 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 20MB, but the OS only allocated 212.99KB 2024-08-08 05:09:08,833 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1MB, but the OS only allocated 212.99KB 2024-08-08 05:09:08,833 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 25MB, but the OS only allocated 212.99KB 2024-08-08 05:09:08,844 INFO [org.jgroups.protocols.FD_SOCK2] (keycloak-cache-init) server listening on *.27243 2024-08-08 05:09:08,851 INFO [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: , Hostname: , Strict HTTPS: false, Path: , Strict BackChannel: false, Admin URL: , Admin: , Port: -1, Proxied: false 2024-08-08 05:09:10,248 WARN [io.quarkus.agroal.runtime.DataSources] (JPA Startup Thread) Datasource enables XA but transaction recovery is not enabled. Please enable transaction recovery by setting quarkus.transaction-manager.enable-recovery=true, otherwise data may be lost if the application is terminated abruptly 2024-08-08 05:09:10,849 INFO [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) 66bd8565b54a-31919: no members discovered after 2002 ms: creating cluster as coordinator 2024-08-08 05:09:10,860 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [66bd8565b54a-31919|0] (1) [66bd8565b54a-31919] 2024-08-08 05:09:10,876 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `66bd8565b54a-31919`, physical addresses are `[198.18.0.3:42779]` 2024-08-08 05:09:10,885 WARN [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled 2024-08-08 05:09:11,284 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: 66bd8565b54a-31919, Site name: null 2024-08-08 05:09:11,288 INFO [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener 2024-08-08 05:09:12,440 INFO [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Initializing database schema. Using changelog META-INF/jpa-changelog-master.xml UPDATE SUMMARY Run: 124 Previously run: 0 Filtered out: 0 ------------------------------- Total change sets: 124 2024-08-08 05:09:14,787 INFO [org.keycloak.services] (main) KC-SERVICES0050: Initializing master realm 2024-08-08 05:09:17,090 INFO [org.keycloak.services] (main) KC-SERVICES0009: Added user 'admin' to realm 'master' 2024-08-08 05:09:17,193 INFO [io.quarkus] (main) Keycloak 24.0.4 on JVM (powered by Quarkus 3.8.4) started in 10.155s. Listening on: http://0.0.0.0:8080 2024-08-08 05:09:17,194 INFO [io.quarkus] (main) Profile prod activated. 2024-08-08 05:09:17,194 INFO [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, keycloak, logging-gelf, narayana-jta, reactive-routes, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, vertx] 2024-08-08 05:10:33,811 WARN [org.keycloak.events] (executor-thread-4) type="LOGIN_ERROR", realmId="20028535-473e-4606-8d15-6cd721fefdad", clientId="null", userId="null", ipAddress="198.18.0.1", error="ssl_required" ```

also to verify we use the same keycloak image the relevant output of docker image ls

REPOSITORY                                                       TAG                        IMAGE ID       CREATED         SIZE
quay.io/keycloak/keycloak                                        24.0.4                     c8bfd0bc98f0   3 months ago    458MB
geoand commented 2 months ago

I'll let @sberyozkin comment when he is back from PTO

sberyozkin commented 2 months ago

Thanks @geoand for trying it out, @bulldog98, I'll give a try soon as well, I have a feeling there is some mix up in your case, may be like a 3.8.4 and Java 21 combo or something like that...

geoand commented 1 month ago

Do we know if this is still an issue?

sberyozkin commented 1 month ago

Let me check now

sberyozkin commented 1 month ago

@bulldog98 @geoand I've tried with Java 21 against the main branch and the latest 3.8.6 and, from Dev UI, I could use both the Keycloak admin link to login as admin:admin and SPA link and login as alice:alice, I'm seeing the container data Georgios pasted above.

I'm seeing the same docker ps output. @bulldog98 I think you may be seeing some KC specific issue which shows itself on your system.

Let me close this issue, please re-open if you can get more information which can help us reproduce. Please note there is also a devservice startup command configuration which you can use to experiment with various KC startup options

geoand commented 1 month ago

👍🏽