3:32 a.m.
Hi,
I configured LDAP for user federation with Kerberos integrated, then I added external
identify Providers via the broker feature.If a user was previously imported to local
Keycloak db, the account linking process will work successfully while users login via
external providers.However if the user was not imported to local keycloak db yet,
following 'First Broker Login' auth flow, once users logged in via external
provider and updated their profile, during 'Create User if Unique' stage
(importing users), if the email address with the user associated with multiple accounts in
LDAP, the importing will fail.
As the symptom, the browser throws error ' We’re sorry...Unexpected error when
handling authentication request to identity provider. '
I'm attaching the debugging log as a reference at the bottom of this email as well.But
in reality it's pretty common to have multiple accounts associated with the same email
address (at least in our case), for example, some accounts there are for running
programs/services but associated with particular person's email for convenience. I
wonder if there is a work-around or some ways to configure and avoid this issue. Does
someone have the same experience and have advices on that?
Ex, debugging log is attached (with the error portion high lighted)
2019-04-24 15:45:04,220 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-04-24 15:45:04,220 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-04-24 15:45:04,220 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-04-24 15:45:04,220 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-04-24 15:45:04,220 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$776/1511347521
2019-04-24 15:45:09,220 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-04-24 15:45:09,221 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-04-24 15:45:09,221 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-04-24 15:45:09,221 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-04-24 15:45:09,221 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$776/1511347521
2019-04-24 15:45:12,488 DEBUG [io.undertow.request] (default I/O-7) Matched prefix path
/auth for path /auth/realms/SDCC2/login-actions/first-broker-login
2019-04-24 15:45:12,488 DEBUG [io.undertow.request.security] (default task-260) Attempting
to authenticate /auth/realms/SDCC2/login-actions/first-broker-login, authentication
required: false
2019-04-24 15:45:12,488 DEBUG [io.undertow.request.security] (default task-260)
Authentication outcome was NOT_ATTEMPTED with method
io.undertow.security.impl.CachedAuthenticatedSessionMechanism@6854b209 for
/auth/realms/SDCC2/login-actions/first-broker-login
2019-04-24 15:45:12,488 DEBUG [io.undertow.request.security] (default task-260)
Authentication result was ATTEMPTED for
/auth/realms/SDCC2/login-actions/first-broker-login
2019-04-24 15:45:12,488 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-260) new JtaTransactionWrapper
2019-04-24 15:45:12,488 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-260) was existing? false
2019-04-24 15:45:12,489 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-260)
RESTEASY002315: PathInfo: /realms/SDCC2/login-actions/first-broker-login
2019-04-24 15:45:12,489 DEBUG [org.keycloak.services.resources.SessionCodeChecks] (default
task-260) Will use client 'test2-oidc' in back-to-application link
2019-04-24 15:45:12,489 DEBUG [org.keycloak.services.util.CookieHelper] (default task-260)
{1} cookie found in the requests header
2019-04-24 15:45:12,489 DEBUG [org.keycloak.services.util.CookieHelper] (default task-260)
{1} cookie found in the cookies field
2019-04-24 15:45:12,489 DEBUG
[org.keycloak.services.managers.AuthenticationSessionManager] (default task-260) Found
AUTH_SESSION_ID cookie with value a1069878-5c31-41d6-9d29-9cfa61e6b806.mktst1
2019-04-24 15:45:12,490 DEBUG [org.keycloak.authentication.AuthenticationProcessor]
(default task-260) authenticationAction
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) processAction: e3d20da0-9a2a-49ba-aeaf-c7503a648d67
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) check: idp-review-profile requirement: REQUIRED
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) action: idp-review-profile
2019-04-24 15:45:12,491 DEBUG
[org.keycloak.authentication.authenticators.broker.IdpReviewProfileAuthenticator] (default
task-260) Profile updated successfully after first authentication with identity provider
'CILogon' for broker user 'http://cilogon.org/serverA/users/2706181'.
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) authenticator SUCCESS: idp-review-profile
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) processFlow
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) check execution: idp-create-user-if-unique requirement: ALTERNATIVE
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) authenticator: idp-create-user-if-unique
2019-04-24 15:45:12,491 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow]
(default task-260) invoke authenticator.authenticate: idp-create-user-if-unique
2019-04-24 15:45:12,492 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl]
(default task-260) Hibernate RegisteredSynchronization successfully registered with JTA
platform
2019-04-24 15:45:12,492 DEBUG [org.hibernate.SQL] (default task-260)
select
userentity0_.ID as ID1_75_,
userentity0_.CREATED_TIMESTAMP as CREATED_2_75_,
userentity0_.EMAIL as EMAIL3_75_,
userentity0_.EMAIL_CONSTRAINT as EMAIL_CO4_75_,
userentity0_.EMAIL_VERIFIED as EMAIL_VE5_75_,
userentity0_.ENABLED as ENABLED6_75_,
userentity0_.FEDERATION_LINK as FEDERATI7_75_,
userentity0_.FIRST_NAME as FIRST_NA8_75_,
userentity0_.LAST_NAME as LAST_NAM9_75_,
userentity0_.NOT_BEFORE as NOT_BEF10_75_,
userentity0_.REALM_ID as REALM_I11_75_,
userentity0_.SERVICE_ACCOUNT_CLIENT_LINK as SERVICE12_75_,
userentity0_.USERNAME as USERNAM13_75_
from
USER_ENTITY userentity0_
where
userentity0_.EMAIL=?
and userentity0_.REALM_ID=?
2019-04-24 15:45:12,492 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(default task-260) KeycloakDS: getConnection(null,
WrappedConnectionRequestInfo@1f75e0ca[userName=sa]) [0/20]
2019-04-24 15:45:12,492 DEBUG
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-260)
Initiating JDBC connection release from afterStatement
2019-04-24 15:45:12,503 WARN [org.keycloak.services] (default task-260) KC-SERVICES0013:
Failed authentication: org.keycloak.models.ModelDuplicateException: Error - multiple LDAP
objects found but expected just one
at
org.keycloak.storage.ldap.idm.query.internal.LDAPQuery.getFirstResult(LDAPQuery.java:189)
at
org.keycloak.storage.ldap.LDAPStorageProvider.queryByEmail(LDAPStorageProvider.java:540)
at
org.keycloak.storage.ldap.LDAPStorageProvider.getUserByEmail(LDAPStorageProvider.java:546)
at org.keycloak.storage.UserStorageManager.getUserByEmail(UserStorageManager.java:408)
at
org.keycloak.models.cache.infinispan.UserCacheSession.getUserByEmail(UserCacheSession.java:380)
at
org.keycloak.authentication.authenticators.broker.IdpCreateUserIfUniqueAuthenticator.checkExistingUser(IdpCreateUserIfUniqueAuthenticator.java:123)
at
org.keycloak.authentication.authenticators.broker.IdpCreateUserIfUniqueAuthenticator.authenticateImpl(IdpCreateUserIfUniqueAuthenticator.java:69)
at
org.keycloak.authentication.authenticators.broker.AbstractIdpAuthenticator.authenticate(AbstractIdpAuthenticator.java:74)
at
org.keycloak.authentication.DefaultAuthenticationFlow.processFlow(DefaultAuthenticationFlow.java:221)
at
org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:117)
at
org.keycloak.authentication.AuthenticationProcessor.authenticationAction(AuthenticationProcessor.java:873)
at
org.keycloak.services.resources.LoginActionsService.processFlow(LoginActionsService.java:292)
at
org.keycloak.services.resources.LoginActionsService.brokerLoginFlow(LoginActionsService.java:779)
at
org.keycloak.services.resources.LoginActionsService.firstBrokerLoginPost(LoginActionsService.java:702)
at sun.reflect.GeneratedMethodAccessor1032.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
at
org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:509)
at
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:399)
at
org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:363)
at
org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:355)
at
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:365)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:337)
at
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:137)
at
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:100)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:439)
at
org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:229)
at
org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:135)
at
org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:355)
at
org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:138)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:215)
at
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:227)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at
org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at
io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at
io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at
org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at
io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
at
io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at
io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at
io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at
io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at
io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at
io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
at
io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at
org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at
org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at
io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
at
io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
at
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
at
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at
io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at
io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at
org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
at
io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at
io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at
org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378)
at java.lang.Thread.run(Thread.java:748)
2019-04-24 15:45:12,504 WARN [org.keycloak.events] (default task-260)
type=UPDATE_PROFILE_ERROR, realmId=SDCC2, clientId=test2-oidc, userId=null, ipAddress=443,
error=invalid_user_credentials, identity_provider=CILogon, auth_method=openid-connect,
updated_email=mizuki(a)yahoo.com, redirect_uri=https://test2.racf.bnl.gov/*,
identity_provider_identity=http://cilogon.org/serverA/users/2706181,
code_id=be-xYIYKAlCQjhk3D28GVOorE8krIRO-XhMM79zYQOI
2019-04-24 15:45:12,505 DEBUG [freemarker.cache] (default task-260) Couldn't find
template in cache for "error.ftl"("en_US", UTF-8, parsed); will try to
load it.
Thanks!
Mizuki Karasawa