[keycloak-user] trouble importing user from ldap when using broker feature

Thu Apr 25 14:32:12 EDT 2019

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 at 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 at 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 at 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