Exception while trying to run a LDAP sync with a group importer and a batch size less then the actual number of groups #29784
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
After the first sync of users from a new LDAP federation, we encounter an exception on further updates, when the federation has a group-ldap-mapper configured and the batch size is configured to be less then the actual amount of groups contained in the LDAP server. I added the occuring log trace containing both the initial import as well as an update with a batch size of 1 under Anything else?.
We fixed the issue by increasing the batch size to be higher then the actual number of groups. The issue doesn't occur in the user sync, but as part of the group sync. If the issue occurs, the user sync isn't started.
After some recherche, it looks to me like the problem mentioned in the following Quarkus issues, which suggests an issue between agroal and hibernate:
- Invalid WARNING: Closing open connection prior to commit quarkusio/quarkus#6770
- Incorrect "WARN Closing open connection prior to commit" when handling BEFORE_COMMIT event quarkusio/quarkus#18737
I'm not sure, if this is really the cause of the issue.
Version
24.0.4
Regression
- The issue is a regression
Expected behavior
The batched group import of the LDAP user sync is working and doesn't throw an exception.
Actual behavior
An exception is thrown while Keycloak is updating the second batch of groups. Sometimes, the log trace doesn't contain an exception, but multiple warnings are logged and the sync fails nontheless.
How to Reproduce?
I created a Gist containing both a docker-compose file with a Open-LDAP instance and a LDAP-UI application, a LDIF file containing 50 groups with 1 user each and a realm export with a user-federation using the Open-LDAP and a group-ldap-mapper.
Using this setup, the issue can be reproduced as follows:
- If necessary, delete all groups and remove all imported users
- Go to the
ldapuser federation and trigger a user import by selectingSync all usersunderActions- The user import works as intended and no exception occurs
- Go to the
ldapuser federation and trigger a user import by selectingSync all usersunderActions- A log message by agroal occurs after the first batch, that
Closing open connection(s) prior to commit - An exception is thrown, that the
Connection is closed
- A log message by agroal occurs after the first batch, that
Anything else?
Log trace:
// Initial Import
2024-05-22 08:43:05,478 INFO [org.keycloak.storage.ldap.LDAPStorageProviderFactory] (executor-thread-49) Sync of federation mapper 'groups' finished. Status: UserFederationSyncResult [ 50 imported groups, 0 updated groups, 0 removed groups ] {realmId=ldap-test, traceId=01303ccb-09f0-483b-a2f5-49d943dd427a}
2024-05-22 08:43:05,479 INFO [org.keycloak.storage.ldap.LDAPStorageProviderFactory] (executor-thread-49) Sync all users from LDAP to local store: realm: ldap-test, federation provider: ldap {realmId=ldap-test, traceId=01303ccb-09f0-483b-a2f5-49d943dd427a}
2024-05-22 08:43:05,909 INFO [org.keycloak.storage.ldap.LDAPStorageProviderFactory] (executor-thread-49) Sync all users finished: 50 imported users, 0 updated users {realmId=ldap-test, traceId=01303ccb-09f0-483b-a2f5-49d943dd427a}
2024-05-22 08:43:05,927 INFO [org.keycloak.events] (executor-thread-49) {"realmId":"40c8bb32-fe77-47a4-b86f-8b2f6ba90d67","clientId":"543366a5-0dfb-4952-af91-6f73eaacd891","event_type":"admin","resourcePath":"user-storage/62e35ce0-c2f6-44cc-84ef-5797b4caae5b/sync","ipAddress":"172.20.0.1","operationType":"ACTION","userId":"36d04f9f-66a3-4db8-96a6-b4996c5f3f5b","resourceType":"REALM"} {realmId=ldap-test, traceId=01303ccb-09f0-483b-a2f5-49d943dd427a}
// Update with batch size 1
2024-05-22 08:43:08,978 INFO [org.keycloak.storage.ldap.LDAPIdentityStoreRegistry] (executor-thread-49) Creating new LDAP Store for the LDAP storage provider: 'ldap', LDAP Configuration: {pagination=[true], fullSyncPeriod=[-1], startTls=[false], usersDn=[ou=users,dc=example,dc=org], connectionPooling=[true], cachePolicy=[DEFAULT], useKerberosForPasswordAuthentication=[false], importEnabled=[true], enabled=[true], usernameLDAPAttribute=[cn], bindDn=[cn=admin,dc=example,dc=org], changedSyncPeriod=[-1], lastSync=[1716367385], vendor=[other], uuidLDAPAttribute=[entryUUID], allowKerberosAuthentication=[false], connectionUrl=[ldap://host.docker.internal:1389], syncRegistrations=[false], authType=[simple], debug=[false], searchScope=[1], useTruststoreSpi=[never], usePasswordModifyExtendedOp=[false], trustEmail=[false], priority=[0], userObjectClasses=[person], rdnLDAPAttribute=[cn], editMode=[READ_ONLY], validatePasswordPolicy=[false], batchSizeForSync=[1]}, binaryAttributes: [] {realmId=ldap-test, traceId=acaf8145-db4a-46e1-a657-ba56108df2c7}
// Connections are closed after the first batch
2024-05-22 08:43:09,082 WARN [io.agroal.pool] (executor-thread-49) Datasource '<default>': Closing open connection(s) prior to commit {realmId=ldap-test, traceId=acaf8145-db4a-46e1-a657-ba56108df2c7}
// An excpetion occurs, because database connection is closed
2024-05-22 08:43:09,082 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (executor-thread-49) SQL Error: 0, SQLState: null {realmId=ldap-test, traceId=acaf8145-db4a-46e1-a657-ba56108df2c7}
2024-05-22 08:43:09,083 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (executor-thread-49) Connection is closed {realmId=ldap-test, traceId=acaf8145-db4a-46e1-a657-ba56108df2c7}
2024-05-22 08:43:09,083 WARN [com.arjuna.ats.arjuna] (executor-thread-49) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffffac140003:95e5:664c72fb:3e15, org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@5070c130 > {realmId=ldap-test, traceId=acaf8145-db4a-46e1-a657-ba56108df2c7} : org.hibernate.exception.GenericJDBCException: could not prepare statement [Connection is closed] [insert into public.GROUP_ATTRIBUTE (GROUP_ID,NAME,VALUE,ID) values (?,?,?,?)]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:63)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:108)
at org.hibernate.engine.jdbc.internal.MutationStatementPreparerImpl$StatementPreparationTemplate.prepareStatement(MutationStatementPreparerImpl.java:117)
at org.hibernate.engine.jdbc.internal.MutationStatementPreparerImpl.prepareStatement(MutationStatementPreparerImpl.java:38)
at org.hibernate.engine.jdbc.mutation.internal.ModelMutationHelper.standardStatementPreparation(ModelMutationHelper.java:145)
at org.hibernate.engine.jdbc.mutation.internal.ModelMutationHelper.lambda$standardPreparation$0(ModelMutationHelper.java:118)
at org.hibernate.engine.jdbc.mutation.internal.PreparedStatementDetailsStandard.resolveStatement(PreparedStatementDetailsStandard.java:87)
at org.hibernate.engine.jdbc.mutation.internal.JdbcValueBindingsImpl.lambda$beforeStatement$0(JdbcValueBindingsImpl.java:88)
at java.base/java.lang.Iterable.forEach(Iterable.java:75)
at org.hibernate.engine.jdbc.mutation.spi.BindingGroup.forEachBinding(BindingGroup.java:51)
at org.hibernate.engine.jdbc.mutation.internal.JdbcValueBindingsImpl.beforeStatement(JdbcValueBindingsImpl.java:85)
at org.hibernate.engine.jdbc.mutation.internal.AbstractMutationExecutor.performNonBatchedMutation(AbstractMutationExecutor.java:104)
at org.hibernate.engine.jdbc.mutation.internal.MutationExecutorSingleNonBatched.performNonBatchedOperations(MutationExecutorSingleNonBatched.java:40)
at org.hibernate.engine.jdbc.mutation.internal.AbstractMutationExecutor.execute(AbstractMutationExecutor.java:52)
at org.hibernate.persister.entity.mutation.InsertCoordinator.doStaticInserts(InsertCoordinator.java:175)
at org.hibernate.persister.entity.mutation.InsertCoordinator.coordinateInsert(InsertCoordinator.java:113)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2873)
at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:632)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:499)
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:363)
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:41)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:127)
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1403)
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:484)
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2319)
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:1976)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:439)
at org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:336)
at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47)
at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37)
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:52)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:351)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:69)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:138)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1271)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104)
at io.quarkus.narayana.jta.runtime.NotifyingTransactionManager.commit(NotifyingTransactionManager.java:70)
at org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:90)
at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136)
at org.keycloak.services.DefaultKeycloakSession.closeTransactionManager(DefaultKeycloakSession.java:407)
at org.keycloak.services.DefaultKeycloakSession.close(DefaultKeycloakSession.java:372)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:384)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:256)
at org.keycloak.storage.ldap.mappers.membership.group.GroupLDAPStorageMapper.syncFlatGroupStructure(GroupLDAPStorageMapper.java:262)
at org.keycloak.storage.ldap.mappers.membership.group.GroupLDAPStorageMapper.syncDataFromFederationProviderToKeycloak(GroupLDAPStorageMapper.java:189)
at org.keycloak.storage.ldap.LDAPStorageProviderFactory$1.lambda$run$0(LDAPStorageProviderFactory.java:535)
at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625)
at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
at org.keycloak.storage.ldap.LDAPStorageProviderFactory$1.run(LDAPStorageProviderFactory.java:533)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:257)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:379)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:256)
at org.keycloak.storage.ldap.LDAPStorageProviderFactory.syncMappers(LDAPStorageProviderFactory.java:525)
at org.keycloak.storage.ldap.LDAPStorageProviderFactory.sync(LDAPStorageProviderFactory.java:489)
at org.keycloak.storage.managers.UserStorageSyncManager$2$1.call(UserStorageSyncManager.java:110)
at org.keycloak.storage.managers.UserStorageSyncManager$2$1.call(UserStorageSyncManager.java:105)
at org.keycloak.cluster.infinispan.InfinispanClusterProvider.executeIfNotExecuted(InfinispanClusterProvider.java:78)
at org.keycloak.storage.managers.UserStorageSyncManager$2.run(UserStorageSyncManager.java:105)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:257)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:379)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:256)
at org.keycloak.storage.managers.UserStorageSyncManager.syncAllUsers(UserStorageSyncManager.java:95)
at org.keycloak.services.resources.admin.UserStorageProviderResource.syncUsers(UserStorageProviderResource.java:154)
at org.keycloak.services.resources.admin.UserStorageProviderResource$quarkusrestinvoker$syncUsers_829c6a5669165dd17b06580d8f9aee0b2c398098.invoke(Unknown Source)
at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582)
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:840)
Caused by: java.sql.SQLException: Connection is closed
at io.agroal.pool.wrapper.ConnectionWrapper.lambda$static$0(ConnectionWrapper.java:51)
at jdk.proxy3/jdk.proxy3.$Proxy69.prepareStatement(Unknown Source)
at io.agroal.pool.wrapper.ConnectionWrapper.prepareStatement(ConnectionWrapper.java:647)
at org.hibernate.engine.jdbc.internal.MutationStatementPreparerImpl$1.doPrepare(MutationStatementPreparerImpl.java:48)
at org.hibernate.engine.jdbc.internal.MutationStatementPreparerImpl$StatementPreparationTemplate.prepareStatement(MutationStatementPreparerImpl.java:106)
... 72 more