search

klausbetz / apple-identity-provider-keycloak

An extension for Keycloak, that enables web-based sign in with Apple and token exchange
Apache License 2.0
193 stars 27 forks source link

unable to login "Sign up not completed" #49

Closed deeeed closed 1 year ago

deeeed commented 1 year ago

Thanks for putting this project together. Unfortunately I have an issue after setting up everything, I am unable to activate the login:

image

I don't receive anything inside the keycloak logs, not any events are triggered. I have tried to play around with the provider settings but nothing help.

Any idea what I could be missing or how I could debug the issue?

deeeed commented 1 year ago

I actually did see some errors in the log but happening before I try to login.

    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:58)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:36)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)

2023-08-24 13:34:18,826 WARN  [org.keycloak.events] (executor-thread-64) type=IDENTITY_PROVIDER_LOGIN_ERROR, realmId=57f012d5-05c3-489f-8a88-eb0d2d1536f2, clientId=cantobroapp, userId=null, ipAddress=192.168.50.1, error=unexpectedErrorHandlingRequestMessage, identity_provider=apple, code_id=cbbd5a60-8430-4665-b9a0-ff7f0246ee9e
2023-08-24 13:34:18,826 ERROR [org.keycloak.services.resources.IdentityBrokerService] (executor-thread-64) unexpectedErrorHandlingRequestMessage: jakarta.ws.rs.WebApplicationException: HTTP 200 OK
    at org.keycloak.services.resources.IdentityBrokerService.parseSessionCode(IdentityBrokerService.java:1101)
    at org.keycloak.services.resources.IdentityBrokerService.performLogin(IdentityBrokerService.java:374)
    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.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
    at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
    at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:174)
    at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:131)
    at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:33)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:84)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:44)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:58)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:36)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)
2023-08-24T21:34:18.827078145+08:00
klausbetz commented 1 year ago

Hi @deeeed,

which Keycloak- and Extension-version do you use?

deeeed commented 1 year ago

Keycloak 22.0.1 Extension: 1.7.0

klausbetz commented 1 year ago

Alright.

Usually, the native dialogs do not show to much information what the actual error is.
Could you please try to log in via the web instead of native iOS (like Chrome on your machine)? You should be able to test this in the web by navigating to the account URL of your realm: <keycloak instance>/realms/<realm>/account

deeeed commented 1 year ago

Good point, using web I get: https://appleid.apple.com/auth/authorize?response_mode=form_post&scope=openid+name%20email&state=-AaW4dJOqTySxen8-otQRPGEpEBEQ7pE8h08t9wBtjM.T6T2DuF5xx4.2NR012VSTyKHiJ3INnI4Qw&response_type=code&client_id=net.siteed.cantobroios&redirect_uri=https%3A%2F%2Fauth.cantobro.app%2Frealms%2Fcantobro%2Fbroker%2Fapple%2Fendpoint&nonce=gg6loPe8P4_1NEyW019iDQ

image

deeeed commented 1 year ago

I may be misconfiguring something, I am confused about the token exchange documentation : image

I am not sure how this apply after editing the provider values?

klausbetz commented 1 year ago

Thx for the insights.

We need to tackle the error in the web first. Usually, this causes the token-exchange to break as well.

Yeah, I assume there's misconfiguration, too.

Let's see.

deeeed commented 1 year ago

Yes I tried that and the error is different if I change the service id meaning it is correct. Both seem correct: image image

klausbetz commented 1 year ago

Thx for sharing all these screenshots.

You can ignore the Server-to-Server Notification Endpoint.

The configuration we are looking for is located in Identifiers -> Service IDs (dropdown on the right side). There you can configure a new Service with the corresponding redirect URI.

Bildschirmfoto 2023-08-25 um 08 37 03
deeeed commented 1 year ago

Yes it seems my endpoint are setup correctly/

If I change my ClientID in keycloak provider config:

image

It would be great if the extension could send event or print out some debug information

klausbetz commented 1 year ago

Ok. Did you get any logs from Keycloak?

Debug log would be awesome in this extension. I need to look into that. I'm not entirely sure if that's possible in keycloak.

klausbetz commented 1 year ago

You might find these articles useful:

deeeed commented 1 year ago

I did also check the other lib but hasn't had any activity in years, I thought it would probably be invalid. Regarding logs, i receive nothing in keycloak.

keycloak 06:26:58.46 
keycloak 06:26:58.46 Welcome to the Bitnami keycloak container
keycloak 06:26:58.46 Subscribe to project updates by watching https://github.com/bitnami/containers
keycloak 06:26:58.46 Submit issues and feature requests at https://github.com/bitnami/containers/issues
keycloak 06:26:58.46 
keycloak 06:26:58.46 INFO  ==> ** Starting keycloak setup **
keycloak 06:26:58.46 INFO  ==> Validating settings in KEYCLOAK_* env vars...
/opt/bitnami/scripts/libvalidations.sh: line 245: return: : numeric argument required
keycloak 06:26:58.47 INFO  ==> Trying to connect to PostgreSQL server postgres-postgresql.postgres.svc.cluster.local...
keycloak 06:26:58.47 INFO  ==> Found PostgreSQL server listening at postgres-postgresql.postgres.svc.cluster.local:5432
keycloak 06:26:58.47 INFO  ==> Configuring database settings
keycloak 06:26:58.48 INFO  ==> Enabling statistics
keycloak 06:26:58.49 INFO  ==> Enabling health endpoints
keycloak 06:26:58.49 INFO  ==> Configuring http settings
keycloak 06:26:58.50 INFO  ==> Configuring hostname settings
keycloak 06:26:58.50 INFO  ==> Configuring cache count
keycloak 06:26:58.50 INFO  ==> Configuring log level
keycloak 06:26:58.51 INFO  ==> Configuring proxy
keycloak 06:26:58.51 INFO  ==> ** keycloak setup finished! **

keycloak 06:26:58.51 INFO  ==> ** Starting keycloak **
Appending additional Java properties to JAVA_OPTS: -Djgroups.dns.query=keycloak-headless.keycloak.svc.cluster.local
Updating the configuration and installing your custom providers, if any. Please wait.
2023-08-25 06:26:58,863 INFO  [org.keycloak.common.Profile] (main) Preview features enabled: scripts, token-exchange
2023-08-25 06:26:59,635 INFO  [org.keycloak.common.Profile] (main) Preview features enabled: scripts, token-exchange
2023-08-25 06:27:00,168 WARN  [org.keycloak.services] (build-16) KC-SERVICES0047: metrics (org.jboss.aerogear.keycloak.metrics.MetricsEndpointFactory) is implementing the internal SPI realm-restapi-extension. This SPI is internal and may change without notice
2023-08-25 06:27:00,350 WARN  [org.keycloak.services] (build-16) KC-SERVICES0047: apple-username-template-mapper (at.klausbetz.provider.AppleUsernameTemplateMapper) is implementing the internal SPI identity-provider-mapper. This SPI is internal and may change without notice
2023-08-25 06:27:00,546 WARN  [org.keycloak.services] (build-16) KC-SERVICES0047: metrics-listener (org.jboss.aerogear.keycloak.metrics.MetricsEventListenerFactory) is implementing the internal SPI eventsListener. This SPI is internal and may change without notice
2023-08-25 06:27:00,639 WARN  [org.keycloak.services] (build-16) KC-SERVICES0047: apple (at.klausbetz.provider.AppleIdentityProviderFactory) is implementing the internal SPI social. This SPI is internal and may change without notice
2023-08-25 06:27:06,182 INFO  [io.quarkus.deployment.QuarkusAugmentor] (main) Quarkus augmentation completed in 6715ms
2023-08-25 06:27:06,551 INFO  [org.keycloak.common.Profile] (main) Preview features enabled: scripts, token-exchange
2023-08-25 06:27:06,765 INFO  [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: <unset>, Hostname: <request>, Strict HTTPS: false, Path: <request>, Strict BackChannel: false, Admin URL: <unset>, Admin: <request>, Port: -1, Proxied: true
2023-08-25 06:27:07,427 WARN  [io.quarkus.agroal.runtime.DataSources] (main) Datasource <default> 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
2023-08-25 06:27:07,741 WARN  [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2023-08-25 06:27:07,769 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2023-08-25 06:27:07,874 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN` with stack `kubernetes`
2023-08-25 06:27:07,875 INFO  [org.jgroups.JChannel] (keycloak-cache-init) local_addr: c5389359-99e0-4886-ad46-7f7b202d3bd4, name: keycloak-0-34221
2023-08-25 06:27:07,879 INFO  [org.jgroups.protocols.FD_SOCK2] (keycloak-cache-init) server listening on *.57800
2023-08-25 06:27:07,914 WARN  [io.quarkus.vertx.http.runtime.VertxHttpRecorder] (main) The X-Forwarded-* and Forwarded headers will be considered when determining the proxy address. This configuration can cause a security issue as clients can forge requests and send a forwarded header that is not overwritten by the proxy. Please consider use one of these headers just to forward the proxy address in requests.
2023-08-25 06:27:08,064 INFO  [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
2023-08-25 06:27:09,883 INFO  [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) keycloak-0-34221: no members discovered after 2001 ms: creating cluster as coordinator
2023-08-25 06:27:09,899 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [keycloak-0-34221|0] (1) [keycloak-0-34221]
2023-08-25 06:27:09,920 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `keycloak-0-34221`, physical addresses are `[10.1.249.84:7800]`
2023-08-25 06:27:10,090 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: keycloak-0-34221, Site name: null
2023-08-25 06:27:10,484 INFO  [io.quarkus] (main) Keycloak 22.0.1 on JVM (powered by Quarkus 3.2.0.Final) started in 4.243s. Listening on: http://0.0.0.0:8080
2023-08-25 06:27:10,484 INFO  [io.quarkus] (main) Profile dev activated. 
2023-08-25 06:27:10,485 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, jdbc-mariadb, jdbc-mssql, jdbc-mysql, jdbc-oracle, jdbc-postgresql, keycloak, logging-gelf, micrometer, narayana-jta, reactive-routes, resteasy, resteasy-jackson, smallrye-context-propagation, smallrye-health, vertx]
2023-08-25 06:27:10,488 WARN  [org.keycloak.quarkus.runtime.KeycloakMain] (main) Running the server in development mode. DO NOT use this configuration in production.
Logs from 25/08/2023, 14:26:58
deeeed commented 1 year ago

I was using the older keycloak version env variable to change log level, I can now see them but nothing helpful:

2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.resources.IdentityBrokerService] (executor-thread-5) Sending authentication request to identity provider [apple].
2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.resources.SessionCodeChecks] (executor-thread-5) Will use client 'account-console' in back-to-application link
2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.util.CookieHelper] (executor-thread-5) AUTH_SESSION_ID cookie found in the request header
2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.util.CookieHelper] (executor-thread-5) AUTH_SESSION_ID cookie found in the cookie field
2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (executor-thread-5) Found AUTH_SESSION_ID cookie with value 677fce85-694e-49e5-b53c-a4f1f268f9c7.keycloak-0-447
2023-08-25 07:15:04,851 DEBUG [org.keycloak.services.resources.IdentityBrokerService] (executor-thread-5) Authorization code is valid.
2023-08-25 07:15:04,855 DEBUG [org.keycloak.services.resources.IdentityBrokerService] (executor-thread-5) Identity provider [at.klausbetz.provider.AppleIdentityProvider@6cf5eb76] is going to send a request [org.jboss.resteasy.specimpl.BuiltResponse@121792ec].

There are only 3 references to the IdentityBrokerService

deeeed commented 1 year ago

Closing this as I was stupidly using an app id instead of service id for my client....