Closed
Description
Before reporting an issue
- I have read and understood the above terms for submitting issues, and I understand that my issue may be closed without action if I do not follow them.
Area
ldap
Describe the bug
When using multi-DC Active Directory and a msad-user-account-control-mapper, attempts to create new users are met with an error:
Could not create user: unknown_error
For more on this error consult the server log.
User does get created, but is disabled and is often missing properties (e.g. no First name or Last name)
Version
26.1.2
Regression
- The issue is a regression
Expected behavior
When creating a user while connected to Active Directory and a msad-user-account-control-mapper configured, there should be no error, and the user account should be enabled.
Actual behavior
User gets created, but is disabled and is missing properties.
UI error:
Could not create user: unknown_error
For more on this error consult the server log.
Error log:
2025-02-28 01:04:36,076 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-9) Uncaught server error: org.keycloak.models.ModelException: Could not modify attribute for DN [cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com]
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.modifyAttributes(LDAPOperationManager.java:604)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.modifyAttributes(LDAPOperationManager.java:115)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPIdentityStore.update(LDAPIdentityStore.java:155)
at org.keycloak.storage.ldap.mappers.LDAPTransaction.commitImpl(LDAPTransaction.java:59)
at org.keycloak.models.AbstractKeycloakTransaction.commit(AbstractKeycloakTransaction.java:46)
at org.keycloak.services.DefaultKeycloakTransactionManager.lambda$commitWithTracing$0(DefaultKeycloakTransactionManager.java:169)
at org.keycloak.tracing.NoopTracingProvider.trace(NoopTracingProvider.java:59)
at org.keycloak.tracing.NoopTracingProvider.trace(NoopTracingProvider.java:69)
at org.keycloak.services.DefaultKeycloakTransactionManager.commitWithTracing(DefaultKeycloakTransactionManager.java:168)
at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:146)
at org.keycloak.services.DefaultKeycloakSession.closeTransactionManager(DefaultKeycloakSession.java:396)
at org.keycloak.services.DefaultKeycloakSession.close(DefaultKeycloakSession.java:361)
at org.keycloak.models.KeycloakBeanProducer_ProducerMethod_getKeycloakSession_XoSEUTXOsE3bpqXlGMAykCiECUM_ClientProxy.close(Unknown Source)
at org.keycloak.quarkus.runtime.transaction.TransactionalSessionHandler.close(TransactionalSessionHandler.java:60)
at org.keycloak.quarkus.runtime.integration.jaxrs.CloseSessionFilter.closeSession(CloseSessionFilter.java:67)
at org.keycloak.quarkus.runtime.integration.jaxrs.CloseSessionFilter.filter(CloseSessionFilter.java:63)
at org.jboss.resteasy.reactive.server.handlers.ResourceResponseFilterHandler.handle(ResourceResponseFilterHandler.java:25)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:150)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:635)
at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: javax.naming.OperationNotSupportedException: [LDAP: error code 53 - 0000052D: SvcErr: DSID-031A124C, problem 5003 (WILL_NOT_PERFORM), data 0
]; remaining name 'cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com'
at java.naming/com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3333)
at java.naming/com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3206)
at java.naming/com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2997)
at java.naming/com.sun.jndi.ldap.LdapCtx.c_modifyAttributes(LdapCtx.java:1505)
at java.naming/com.sun.jndi.toolkit.ctx.ComponentDirContext.p_modifyAttributes(ComponentDirContext.java:277)
at java.naming/com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.modifyAttributes(PartialCompositeDirContext.java:192)
at java.naming/javax.naming.directory.InitialDirContext.modifyAttributes(InitialDirContext.java:213)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager$6.execute(LDAPOperationManager.java:585)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager$6.execute(LDAPOperationManager.java:581)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.execute(LDAPOperationManager.java:742)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.execute(LDAPOperationManager.java:714)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.modifyAttributesNaming(LDAPOperationManager.java:581)
at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.modifyAttributes(LDAPOperationManager.java:602)
... 26 more
Debug/trace logs (immediately preceding error):
2025-02-28 01:04:35,828 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:35,857 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: search
baseDn: OU=Users,OU=TEST,DC=test,DC=company,DC=com
filter: (&(mail=testuser@company.test)(objectclass=person)(objectclass=organizationalPerson)(objectclass=user))
searchScope: 1
returningAttrs: [userPrincipalName, sAMAccountName, mail, givenName, whenCreated, whenChanged, sn, pwdLastSet, userAccountControl]
resultSize: 0
took: 29 ms
2025-02-28 01:04:35,859 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:35,887 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: search
baseDn: OU=Users,OU=TEST,DC=test,DC=company,DC=com
filter: (&(sAMAccountName=testuser@company.test)(objectclass=person)(objectclass=organizationalPerson)(objectclass=user))
searchScope: 1
returningAttrs: [userPrincipalName, sAMAccountName, mail, givenName, whenCreated, whenChanged, sn, pwdLastSet, userAccountControl]
resultSize: 0
took: 28 ms
2025-02-28 01:04:35,898 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:35,927 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: search
baseDn: OU=Users,OU=TEST,DC=test,DC=company,DC=com
filter: (&(sAMAccountName=testuser)(objectclass=person)(objectclass=organizationalPerson)(objectclass=user))
searchScope: 1
returningAttrs: [userPrincipalName, sAMAccountName, mail, givenName, whenCreated, whenChanged, sn, pwdLastSet, userAccountControl]
resultSize: 0
took: 28 ms
2025-02-28 01:04:35,931 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Creating entry [cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com] with attributes: [
2025-02-28 01:04:35,931 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) sAMAccountName = testuser
2025-02-28 01:04:35,932 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) givenName =
2025-02-28 01:04:35,932 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) objectclass = person
2025-02-28 01:04:35,932 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) sn =
2025-02-28 01:04:35,932 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) cn = testuser
2025-02-28 01:04:35,932 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) ]
2025-02-28 01:04:35,932 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:35,991 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: create
dn: cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com
attributesSize: 5
took: 59 ms
2025-02-28 01:04:35,991 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPIdentityStore] (executor-thread-9) Type with identifier [4a29815c-e464-4fee-ad52-f61fc0ab574d] and dn [cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com] successfully added to LDAP store.
2025-02-28 01:04:36,007 TRACE [org.keycloak.storage.ldap.mappers.UserAttributeLDAPStorageMapper] (executor-thread-9) Pushing user attribute to LDAP. username: testuser, Model attribute name: email, LDAP attribute name: mail, Attribute value: testuser@company.test
2025-02-28 01:04:36,008 TRACE [org.keycloak.storage.ldap.mappers.TxAwareLDAPUserModelDelegate] (executor-thread-9) Starting and enlisting transaction for object cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com
2025-02-28 01:04:36,008 TRACE [org.keycloak.storage.ldap.mappers.TxAwareLDAPUserModelDelegate] (executor-thread-9) Pushing full name attribute to LDAP. Full name: test
2025-02-28 01:04:36,008 TRACE [org.keycloak.storage.ldap.mappers.UserAttributeLDAPStorageMapper] (executor-thread-9) Pushing user attribute to LDAP. username: testuser, Model attribute name: firstName, LDAP attribute name: givenName, Attribute value: [test]
2025-02-28 01:04:36,008 TRACE [org.keycloak.storage.ldap.mappers.TxAwareLDAPUserModelDelegate] (executor-thread-9) Pushing full name attribute to LDAP. Full name: test user
2025-02-28 01:04:36,008 TRACE [org.keycloak.storage.ldap.mappers.UserAttributeLDAPStorageMapper] (executor-thread-9) Pushing user attribute to LDAP. username: testuser, Model attribute name: lastName, LDAP attribute name: sn, Attribute value: [user]
2025-02-28 01:04:36,008 DEBUG [org.keycloak.storage.ldap.mappers.msad.MSADUserAccountControlStorageMapper] (executor-thread-9) Going to propagate enabled=true for ldapUser 'cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com' to MSAD
2025-02-28 01:04:36,008 DEBUG [org.keycloak.storage.ldap.mappers.msad.MSADUserAccountControlStorageMapper] (executor-thread-9) Updating userAccountControl of user 'cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com' to value '0'. Realm is 'master'
2025-02-28 01:04:36,012 TRACE [org.keycloak.storage.ldap.mappers.LDAPTransaction] (executor-thread-9) Transaction commit! Updating LDAP attributes for object cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com, attributes: {whenChanged=[], whenCreated=[], mail=[testuser@company.test], sAMAccountName=[testuser], givenName=[test], sn=[user], cn=[test user], userAccountControl=[0]}
2025-02-28 01:04:36,012 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPIdentityStore] (executor-thread-9) Renaming LDAP Object. Old DN: [cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com], New DN: [cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com]
2025-02-28 01:04:36,013 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:36,043 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: renameEntry
oldDn: cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com
newDn: cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com
took: 30 ms
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Modifying attributes for entry [cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com]: [
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Op [2]: userAccountControl = 0
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Op [2]: sAMAccountName = testuser
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Op [2]: mail = testuser@company.test
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Op [2]: givenName = test
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) Op [2]: sn = user
2025-02-28 01:04:36,044 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager] (executor-thread-9) ]
2025-02-28 01:04:36,044 DEBUG [org.keycloak.storage.ldap.idm.store.ldap.LDAPContextManager] (executor-thread-9) Creating LdapContext using properties: [{java.naming.security.authentication=simple, java.naming.ldap.attributes.binary=objectGUID, java.naming.provider.url=ldap://test-ldap-7320489d1afda54b.elb.us-gov-east-1.amazonaws.com, com.sun.jndi.ldap.connect.pool=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.credentials=**************************************, java.naming.security.principal=CN=Admin,OU=Users,OU=TEST,DC=test,DC=company,DC=com}]
2025-02-28 01:04:36,075 TRACE [org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf] (executor-thread-9)
LdapOperation: modify
dn: cn=test user,OU=Users,OU=TEST,DC=test,DC=company,DC=com
modificationsSize: 5
took: 31 ms
Notice the following two lines where MSADUserAccountControlStorageMapper logs that it will update userAccountControl to value '0':
2025-02-28 01:04:36,008 DEBUG [org.keycloak.storage.ldap.mappers.msad.MSADUserAccountControlStorageMapper] (executor-thread-9) Going to propagate enabled=true for ldapUser 'cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com' to MSAD
2025-02-28 01:04:36,008 DEBUG [org.keycloak.storage.ldap.mappers.msad.MSADUserAccountControlStorageMapper] (executor-thread-9) Updating userAccountControl of user 'cn=testuser,OU=Users,OU=TEST,DC=test,DC=company,DC=com' to value '0'. Realm is 'master'
How to Reproduce?
- Configure LDAP connection to Active Directory (I tested using a multi domain controller AWS Managed Microsoft AD) and ensure a msad-user-account-control-mapper is configured.
- Attempt to create a user in Keycloak
Anything else?
We upgraded from 26.0.1 to 26.1.2, at which point we started experiencing errors when creating users. In my investigation, I believe this is due to the changes made in PR 34470. Prior to this change, the userAccountControl wouldn't be modified at create time. I suspect the ldapUser in setEnabled is not updated with the real userAccountControl value from AD.
If a sync is introduced as part of the creation flow before setEnabled is run, it should be noted that AD implements eventual consistency and care should be taken to avoid introducing an issue similar to the UUID issue addressed in 29206 and fixed in PR 29470.