LDAP sync with multiple subsytems connection timeout

[booltrue]

I am using alfresco Community - 5.1.0 (r127059-b7)

and synchronizing currently 4 ldap subsytems ad1,ad2,ad3,ad4.

ad1 is our domain, ad2,ad3,ad4 is not our domain.

From time to time I get a connection timeout from a subsytem.

Synchronization and authentication, both work so far.

I also tried to increase the timeout value, also to infinitely,

but without any effect.

thx for your help

properties for ldap ad2:

ldap.authentication.active=true
ldap.authentication.java.naming.read.timeout=0
ldap.authentication.allowGuestLogin=false
ldap.authentication.userNameFormat=%s@a.b.c
ldap.authentication.java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory
ldap.authentication.java.naming.provider.url=ldap://33.333.33.333:389
ldap.authentication.java.naming.security.authentication=simple
ldap.authentication.escapeCommasInBind=false
ldap.authentication.escapeCommasInUid=false
ldap.authentication.defaultAdministratorUserNames=Administrator
ldap.synchronization.active=true
ldap.synchronization.java.naming.security.authentication=simple
ldap.synchronization.java.naming.security.principal=admin@a.b.c
ldap.synchronization.java.naming.security.credentials=Alfresco123
ldap.synchronization.queryBatchSize=1000
ldap.synchronization.attributeBatchSize=1000
ldap.synchronization.groupQuery=(&(objectclass\=group)(CN\=TESTGROUP))
ldap.synchronization.groupDifferentialQuery=(&(objectclass\=group)(CN\=TESTGROUP))
ldap.synchronization.personQuery=(&(objectclass\=user)(memberOf=CN\=TESTGROUP,OU\=OUR GROUPS,DC\=a,DC\=b,DC\=c)(userAccountControl\:1.2.840.113556.1.4.803\:\=512))
ldap.synchronization.personDifferentialQuery=(&(objectclass\=user)(memberOf=CN\=TESTGROUP,OU\=OUR GROUPS,DC\=a,DC\=b,DC\=c)(userAccountControl\:1.2.840.113556.1.4.803\:\=512))
ldap.synchronization.groupSearchBase=DC\=a,DC\=b,DC\=c
ldap.synchronization.userSearchBase=DC\=a,DC\=b,DC\=c
ldap.synchronization.modifyTimestampAttributeName=modifyTimestamp
ldap.synchronization.timestampFormat=yyyyMMddHHmmss'.0Z'
ldap.synchronization.userIdAttributeName=sAMAccountName
ldap.synchronization.userFirstNameAttributeName=givenName
ldap.synchronization.userLastNameAttributeName=sn
ldap.synchronization.userEmailAttributeName=mail
ldap.synchronization.userOrganizationalIdAttributeName=company
ldap.synchronization.defaultHomeFolderProvider=largeHomeFolderProvider
ldap.synchronization.groupIdAttributeName=cn
ldap.synchronization.groupDisplayNameAttributeName=displayName
ldap.synchronization.groupType=group
ldap.synchronization.personType=user
ldap.synchronization.groupMemberAttributeName=member
ldap.synchronization.enableProgressEstimation=true

alfresco-global.properties:

authentication.chain=alfrescoNtlm1:alfrescoNtlm,ad1:ldap-ad,ad2:ldap-ad,ad3ldap-ad,ad4:ldap-ad
synchronization.synchronizeChangesOnly=true
synchronization.syncWhenMissingPeopleLogIn=false
synchronization.autoCreatePeopleOnLogin=false
synchronization.authCreatePeopleOnLogin=false
synchronization.syncOnStartup=true
synchronization.import.cron=0 0/15 * ? * *

alfresco.log:

2017-06-29 12:45:00,203 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronizing users and groups with user registry 'ad1'
2017-06-29 12:45:00,203 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Full synchronization with user registry 'ad1'
2017-06-29 12:45:00,203 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Some users and groups previously created by synchronization with this user registry may be removed.
2017-06-29 12:45:00,218 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving groups changed since 21.06.2017 14:34:21 from user registry 'ad1'
2017-06-29 12:45:00,234 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=1 Group Analysis: Commencing batch of 1 entries
2017-06-29 12:45:00,250 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=1 Group Analysis: Processed 1 entries out of 1. 100% complete. Rate: 62 per second. 0 failures detected.
2017-06-29 12:45:00,250 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=1 Group Analysis: Completed batch of 1 entries
2017-06-29 12:45:00,265 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving users changed since 29.06.2017 11:35:19 from user registry 'ad1'
2017-06-29 12:45:00,265 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=6 User Creation and Association: Commencing batch of 17 entries
2017-06-29 12:45:00,312 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=6 User Creation and Association: Processed 17 entries out of 17. 100% complete. Rate: 361 per second. 0 failures detected.
2017-06-29 12:45:00,312 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad1,id2=6 User Creation and Association: Completed batch of 17 entries
2017-06-29 12:45:00,312 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Finished synchronizing users and groups with user registry 'ad1'
2017-06-29 12:45:00,312 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] 7 user(s) and 1 group(s) processed
2017-06-29 12:45:00,328 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronizing users and groups with user registry 'ad2'
2017-06-29 12:45:00,328 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Full synchronization with user registry 'ad2'
2017-06-29 12:45:00,328 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Some users and groups previously created by synchronization with this user registry may be removed.
2017-06-29 12:45:00,343 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving groups changed since 27.06.2017 15:08:13 from user registry 'ad2'
2017-06-29 12:45:21,466 WARN  [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [DefaultScheduler_Worker-3] Failed to resolve member of group 'TESTGROUP' with distinguished name: CN=TESTUSER,OU=OUR USERS,OU=OUR GROUPS,DC=A,DC=B,DC=C
javax.naming.CommunicationException: A.B.C:389 [Root exception is java.net.ConnectException: Connection timed out: connect]
    at com.sun.jndi.ldap.LdapReferralContext.<init>(Unknown Source)
    at com.sun.jndi.ldap.LdapReferralException.getReferralContext(Unknown Source)
    at com.sun.jndi.ldap.LdapCtx.c_getAttributes(Unknown Source)
    at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_getAttributes(Unknown Source)
    at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(Unknown Source)
    at javax.naming.directory.InitialDirContext.getAttributes(Unknown Source)
    at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry$3.doProcess(LDAPUserRegistry.java:803)
    at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry$AbstractSearchCallback.process(LDAPUserRegistry.java:1834)
    at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.processQuery(LDAPUserRegistry.java:1287)
    at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.getGroups(LDAPUserRegistry.java:691)
    at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.syncWithPlugin(ChainingUserRegistrySynchronizer.java:973)
    at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronizeInternal(ChainingUserRegistrySynchronizer.java:719)
    at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronize(ChainingUserRegistrySynchronizer.java:448)
    at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob$1.doWork(UserRegistrySynchronizerJob.java:46)
    at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
    at org.alfresco.repo.security.sync.UserRegistrySynchronizerJob.execute(UserRegistrySynchronizerJob.java:42)
    at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:563)
Caused by: java.net.ConnectException: Connection timed out: connect
    at java.net.DualStackPlainSocketImpl.connect0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source)
    at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source)
    at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source)
    at java.net.AbstractPlainSocketImpl.connect(Unknown Source)
    at java.net.PlainSocketImpl.connect(Unknown Source)
    at java.net.SocksSocketImpl.connect(Unknown Source)
    at java.net.Socket.connect(Unknown Source)
    at java.net.Socket.connect(Unknown Source)
    at java.net.Socket.<init>(Unknown Source)
    at java.net.Socket.<init>(Unknown Source)
    at com.sun.jndi.ldap.Connection.createSocket(Unknown Source)
    at com.sun.jndi.ldap.Connection.<init>(Unknown Source)
    at com.sun.jndi.ldap.LdapClient.<init>(Unknown Source)
    at com.sun.jndi.ldap.LdapClientFactory.createPooledConnection(Unknown Source)
    at com.sun.jndi.ldap.pool.Connections.getOrCreateConnection(Unknown Source)
    at com.sun.jndi.ldap.pool.Connections.get(Unknown Source)
    at com.sun.jndi.ldap.pool.Pool.getPooledConnection(Unknown Source)
    at com.sun.jndi.ldap.LdapPoolManager.getLdapClient(Unknown Source)
    at com.sun.jndi.ldap.LdapClient.getInstance(Unknown Source)
    at com.sun.jndi.ldap.LdapCtx.connect(Unknown Source)
    at com.sun.jndi.ldap.LdapCtx.<init>(Unknown Source)
    at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(Unknown Source)
    at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(Unknown Source)
    at com.sun.jndi.url.ldap.ldapURLContextFactory.getObjectInstance(Unknown Source)
    at javax.naming.spi.NamingManager.getURLObject(Unknown Source)
    at javax.naming.spi.NamingManager.processURL(Unknown Source)
    at javax.naming.spi.NamingManager.processURLAddrs(Unknown Source)
    at javax.naming.spi.NamingManager.getObjectInstance(Unknown Source)
    ... 18 more
2017-06-29 12:45:24,274 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=1 Group Analysis: Commencing batch of 1 entries
2017-06-29 12:45:24,274 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=1 Group Analysis: Processed 1 entries out of 1. 100% complete. 0 failures detected.
2017-06-29 12:45:24,274 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=1 Group Analysis: Completed batch of 1 entries
2017-06-29 12:45:24,368 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving users changed since 28.06.2017 16:00:38 from user registry 'ad2'
2017-06-29 12:45:24,399 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=6 User Creation and Association: Commencing batch of 1 entries
2017-06-29 12:45:24,524 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=6 User Creation and Association: Processed 1 entries out of 1. 100% complete. Rate: 8 per second. 0 failures detected.
2017-06-29 12:45:24,524 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad2,id2=6 User Creation and Association: Completed batch of 1 entries
2017-06-29 12:45:24,524 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Finished synchronizing users and groups with user registry 'ad2'
2017-06-29 12:45:24,524 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] 1 user(s) and 1 group(s) processed
2017-06-29 12:45:24,539 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronizing users and groups with user registry 'ad3'
2017-06-29 12:45:24,539 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Full synchronization with user registry 'ad3'
2017-06-29 12:45:24,539 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Some users and groups previously created by synchronization with this user registry may be removed.
2017-06-29 12:45:24,539 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving groups changed since 31.01.2017 19:26:46 from user registry 'ad3'
2017-06-29 12:45:37,097 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=1 Group Analysis: Commencing batch of 2 entries
2017-06-29 12:45:37,097 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=1 Group Analysis: Processed 2 entries out of 2. 100% complete. 0 failures detected.
2017-06-29 12:45:37,097 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=1 Group Analysis: Completed batch of 2 entries
2017-06-29 12:45:40,857 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving users changed since 29.06.2017 12:20:28 from user registry 'ad3'
2017-06-29 12:45:42,745 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=6 User Creation and Association: Commencing batch of 22 entries
2017-06-29 12:45:44,632 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=6 User Creation and Association: Processed 22 entries out of 22. 100% complete. Rate: 11 per second. 0 failures detected.
2017-06-29 12:45:44,632 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad3,id2=6 User Creation and Association: Completed batch of 22 entries
2017-06-29 12:45:44,648 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Finished synchronizing users and groups with user registry 'ad3'
2017-06-29 12:45:44,648 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] 9 user(s) and 2 group(s) processed
2017-06-29 12:45:44,663 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronizing users and groups with user registry 'ad4'
2017-06-29 12:45:44,663 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Full synchronization with user registry 'ad4'
2017-06-29 12:45:44,663 WARN  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Some users and groups previously created by synchronization with this user registry may be removed.
2017-06-29 12:45:44,663 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving groups changed since 16.06.2017 08:01:58 from user registry 'ad4'
2017-06-29 12:46:37,189 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=1 Group Analysis: Commencing batch of 1 entries
2017-06-29 12:46:37,205 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=1 Group Analysis: Processed 1 entries out of 1. 100% complete. Rate: 62 per second. 0 failures detected.
2017-06-29 12:46:37,205 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=1 Group Analysis: Completed batch of 1 entries
2017-06-29 12:46:38,344 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Retrieving users changed since 29.06.2017 10:32:21 from user registry 'ad4'
2017-06-29 12:46:38,827 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=6 User Creation and Association: Commencing batch of 201 entries
2017-06-29 12:46:39,327 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=6 User Creation and Association: Processed 100 entries out of 201. 50% complete. Rate: 200 per second. 0 failures detected.
2017-06-29 12:46:39,545 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=6 User Creation and Association: Processed 200 entries out of 201. 100% complete. Rate: 278 per second. 0 failures detected.
2017-06-29 12:46:39,779 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=6 User Creation and Association: Processed 201 entries out of 201. 100% complete. Rate: 211 per second. 0 failures detected.
2017-06-29 12:46:39,779 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Synchronization,Category=directory,id1=ad4,id2=6 User Creation and Association: Completed batch of 201 entries
2017-06-29 12:46:39,795 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] Finished synchronizing users and groups with user registry 'ad4'
2017-06-29 12:46:39,795 INFO  [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [DefaultScheduler_Worker-3] 19 user(s) and 1 group(s) processed

[afaust]

Is your service only connecting to the LDAP or also processing all the data just like Alfresco would? Also your service is likely not going to exhibit the same behaviour as Alfresco, e.g. Alfresco may have periods where no call is being made to LDAP while the data loaded from the last batch is being processed.

Apart from a verification script, you could also set up a network capturing process to record the exchanges between Alfresco and LDAP (e.g. tcpdump). With that data you could then use Wireshark to analyse the low-level communication behaviour and determine e.g. what side introduces a delay that leads to the timeout.

[booltrue]

Alfresco is configured that the scheduler is synchronizing with ldap all 15min.

I thought the synchronization process will only update the groups and users from ldap ?

The connection timeout occurs only in relation with the synchronization trigger.

My service only synchronizes the groups and users as configured in Alfresco, but not more.

I wanted to figure out, if network or ldap connection errors occur in the synced domain.

[booltrue]

I observed the behaviour for 2 weeks. Sometimes quite stable, but today I got within 9h 10 timeouts.

I am synchronizing all 15 min. What data could be processed a lot that causes the timeouts, specially today ?

The timeout only occurs at one domain. But the domain and network is available due my service gets positive response.

If ldap synchronization is not working several times do I still can login ?? Or only new added users are not synced to Alfresco ?

What more effects does aborted sync have to the functionality of Alfresco ?

Didn't anyone have the same problem before?

If still connecton errors occur I try to figure out by capturing the network traffic.