Alfresco CE 5.1.0 (r127059-b7). Wrong work of "ldap.synchronization.queryBatchSize"

[ruslan]

LDAP synchronization with Windows Active Directory cause error.

Alfresco enviroment:

alfresco@doc-server:/opt/alfresco-community$ uname -a
Linux doc-server 4.4.0-47-generic #68-Ubuntu SMP Wed Oct 26 19:39:52 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

alfresco@doc-server:/opt/alfresco-community$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 16.04.1 LTS
Release: 16.04
Codename: xenial

alfresco@doc-server:/opt/alfresco-community$ sysinfo
------------------ Java information ------------------
Java version: 1.8.0_111
Java supplier: Oracle Corporation
Java home folder: /usr/lib/jvm/java-8-oracle/jre

...

java.specification.name: Java Platform API Specification
java.specification.version: 1.8
java.runtime.version: 1.8.0_111-b14

Alfresco version:

Alfresco Community Edition 5.1.0 (r127059-b7)

###############################
## Common Alfresco Properties #
###############################

dir.root=/opt/alfresco-community/alf_data

alfresco.context=alfresco
alfresco.host=doc-server.***.local
alfresco.port=8080
alfresco.protocol=http

share.context=share
share.host=doc-server.***.local
share.port=8080
share.protocol=http

### database connection properties ###
db.driver=org.postgresql.Driver
db.username=***
db.password=***
db.name=***
db.url=jdbcostgresql://localhost/alfresco
# Note: your database must also be able to accept at least this many connections. Please see your database documentation for instructions on how to configure this.
db.pool.max=275
db.pool.validate.query=SELECT 1

# The server mode. Set value here
# UNKNOWN | TEST | BACKUP | PRODUCTION
system.serverMode=UNKNOWN

### CIFS Server Configuration ###
cifs.enabled=true
cifs.ipv6=disabled
cifs.serverName=${localname}
cifs.doman=***.LOCAL
cifs.hostannounce=true
cifs.WINS.autoDetectEnabled=true
cifs.urlfile.prefix=https://${localname}:8080/alfresco
#cifs.bindto=10.***.***.230
#cifs.broadcast=10.***.***.255
cifs.platforms=linux,solaris,macosx
cifs.disableNIO=false

### FTP Server Configuration ###
ftp.enabled=false
ftp.port=21

### RMI registry port for JMX ###
alfresco.rmi.services.port=50500
alfresco.rmi.services.host=doc-server.***.local

### External executable locations ###
# OpenOffice|LibreOffice configuration
ooo.exe=/usr/bin/soffice
ooo.enabled=true
ooo.port=8100

img.root=/opt/alfresco-community/common
img.dyn=${img.root}/lib
img.exe=${img.root}/bin/convert

jodconverter.enabled=true
jodconverter.officeHome=/usr/lib/libreoffice
jodconverter.portNumbers=8100

### Initial admin password ###
alfresco_user_store.adminpassword=***

### E-mail site invitation setting ###
notification.email.siteinvite=false

### License location ###
dir.license.external=/opt/alfresco-community

### Solr indexing ###
index.subsystem.name=solr4
dir.keystore=${dir.root}/keystore
solr.host=localhost
solr.port.ssl=8443

### Allow extended ResultSet processing
security.anyDenyDenies=false

### Smart Folders Config Properties ###
smart.folders.enabled=false

### Remote JMX (Default: disabled) ###
alfresco.jmx.connector.enabled=true
alfresco.jmx.dir=/opt/alfresco-community/tomcat/webapps/alfresco/WEB-INF/classes/alfresco

### Alfresco authentication sybsystem ###
authentication.chain=kerberos1:kerberos,ldap1:ldap-ad
synchronization.synchronizeChangesOnly=true

#__ Kerberos___#
kerberos.authentication.realm=***.LOCAL
kerberos.authentication.sso.enabled=true
kerberos.authentication.authenticateCIFS=true
kerberos.authentication.user.configEntryName=ShareHTTP
kerberos.authentication.cifs.configEntryName=AlfrescoHTTP
kerberos.authentication.http.configEntryName=AlfrescoCIFS
kerberos.authentication.defaultAdministratorUserNames=***,***
kerberos.authentication.browser.ticketLogons=true
kerberos.authentication.stripUsernameSuffix=true

#__ LDAP S __#
ldap.authentication.active=false
ldap.authentication.java.naming.security.authentication=DIGEST-MD5
ldap.authentication.userNameFormat=%s@***.local
ldap.authentication.allowGuestLogin=false
#dap.authentication.java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory
ldap.authentication.java.naming.provider.url=ldap://some-dc.***.local:389
ldap.authentication.escapeCommasInBind=false
ldap.authentication.escapeCommasInUid=false

ldap.synchronization.active=true
ldap.synchronization.java.naming.security.authentication=simple
ldap.synchronization.java.naming.security.principal=AlfrescoLDAP@***.local
ldap.synchronization.java.naming.security.credentials=***
ldap.synchronization.queryBatchSize=500
ldap.synchronization.timestampFormat=yyyyMMddHHmmss'.0Z'
ldap.synchronization.groupDifferentialQuery=(&(objectclass=nogroup)(!(modifyTimestamp<\={0})))
ldap.synchronization.personQuery=(&(objectclass\=user)(userAccountControl\:1.2.840.113556.1.4.803\:\=512))
ldap.synchronization.personDifferentialQuery=(&(objectclass\=user)(!(modifyTimestamp<\={0})))
ldap.synchronization.groupQuery=(objectclass\=group)
ldap.synchronization.groupSearchBase=ou=***,ou=***,dc=***,dc=local
ldap.synchronization.userSearchBase=ou=***,dc=***,dc=local

ldap.synchronization.com.sun.jndi.ldap.connect.pool=true
ldap.pooling.com.sun.jndi.ldap.connect.pool.authentication=DIGEST-MD5
ldap.pooling.com.sun.jndi.ldap.connect.pool.protocol=plain
ldap.pooling.com.sun.jndi.ldap.connect.pool.initsize=1
ldap.pooling.com.sun.jndi.ldap.connect.pool.maxsize=4
ldap.pooling.com.sun.jndi.ldap.connect.pool.prefsize=1000
ldap.pooling.com.sun.jndi.ldap.connect.pool.timeout=900
ldap.pooling.com.sun.jndi.ldap.connect.timeout=600

I have some experiments with ldap.synchronization.queryBatchSize value in range 500-2000

Active Directory Server:

Windows Server 2008 R2

C:\Windows\System32>ntdsutil
ntdsutil: ldap policies
ldap policy: connections
server connections: connect to server some-dc.***.local
...

server connections: q
ldap policy: Show values

policy                                     Current(New)

MaxPoolThreads                   4
MaxDatagramRecv                4096
MaxReceiveBuffer                 10485760
InitRecvTimeout                     120
MaxConnections                    5000
MaxConnIdleTime                  900
MaxPageSize                         1000
MaxQueryDuration                 120
MaxTempTableSize                10000
MaxResultSetSize                   262144
MinResultSets                         0
MaxResultSetsPerConn          0
MaxNotificationPerConn          5
MaxValRange                          1500
ThreadMemoryLimit                 0
SystemMemoryLimitPercent    0

Problem description:

If value of ldap.synchronization.queryBatchSize is 500 alfresco.log present error:

2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Processing query
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Search base: ou=***,ou=***,dc=***,dc=local
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Return result limit: 0
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] DerefLink: false
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Return named object: false
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Time limit for search: 0
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attributes to return: 4 items.
2016-11-28 13:18:19,056 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attribute: cn
2016-11-28 13:18:19,057 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attribute: displayName
2016-11-28 13:18:19,057 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attribute: member;range=0-999
2016-11-28 13:18:19,057 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attribute: whenChanged
2016-11-28 13:18:19,063 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Found 0
2016-11-28 13:18:19,070 INFO [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [localhost-startStop-1] Synchronization,Category=directory,id1=ldap1,id2=1 Group Analysis: Commencing batch of 0 entries
2016-11-28 13:18:19,071 INFO [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [localhost-startStop-1] Synchronization,Category=directory,id1=ldap1,id2=1 Group Analysis: Completed batch of 0 entries
2016-11-28 13:18:19,076 INFO [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [localhost-startStop-1] Retrieving users changed since 14.11.2016 23:35:36 from user registry 'ldap1'
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Processing query
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Search base: ou=***,dc=***,dc=local
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Return result limit: 0
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] DerefLink: false
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Return named object: false
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Time limit for search: 0
2016-11-28 13:18:19,078 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Attributes to return: 0 items.
2016-11-28 13:18:19,120 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Processing person: CN=***,OU=***,OU=***,OU=***,DC=***,DC=LOCAL

... 498 similar lines (500 total) ...

2016-11-28 13:18:19,213 DEBUG [org.alfresco.repo.security.sync.ldap.LDAPUserRegistry] [localhost-startStop-1] Processing perso n: CN=***,OU=***,OU=***,OU=***,DC=***,DC=LOCAL
2016-11-28 13:18:19,221 ERROR [org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer] [localhost-startStop-1] Synch ronization aborted due to error
org.alfresco.error.AlfrescoRuntimeException: 10280001 LDAP search error. Cause: [LDAP: error code 12 - 00002040: SvcErr : DSID-031401F1, problem 5010 (UNAVAIL_EXTENSION), data 0]
at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.processQuery(LDAPUserRegistry.java:1303)
at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.access$14(LDAPUserRegistry.java:1255)
at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry$PersonCollection.<init>(LDAPUserRegistry.java:1492)
at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.getPersons(LDAPUserRegistry.java:551)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.syncWithPlugin(ChainingUserRegistrySynchronizer.ja va:1755)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.synchronizeInternal(ChainingUserRegistrySynchroniz er.java:719)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.access$14(ChainingUserRegistrySynchronizer.java:45 1)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer$7.doWork(ChainingUserRegistrySynchronizer.java:208 5)
at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.onBootstrap(ChainingUserRegistrySynchronizer.java: 2079)
at org.springframework.extensions.surf.util.AbstractLifecycleBean.onApplicationEvent(AbstractLifecycleBean.java:56)
at org.alfresco.repo.security.sync.ChainingUserRegistrySynchronizer.onApplicationEvent(ChainingUserRegistrySynchronize r.java:2442)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaste r.java:96)
at org.alfresco.repo.management.subsystems.ChildApplicationContextFactory$ChildApplicationContext.publishEvent(ChildAp plicationContextFactory.java:559)
at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:950)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:482)
at org.alfresco.repo.management.subsystems.ChildApplicationContextFactory$ApplicationContextState.start(ChildApplicati onContextFactory.java:814)
at org.alfresco.repo.management.subsystems.AbstractPropertyBackedBean.start(AbstractPropertyBackedBean.java:1086)
at org.alfresco.repo.management.subsystems.AbstractPropertyBackedBean.onApplicationEvent(AbstractPropertyBackedBean.ja va:625)
at org.alfresco.repo.management.SafeApplicationEventMulticaster.multicastEventInternal(SafeApplicationEventMulticaster .java:207)
at org.alfresco.repo.management.SafeApplicationEventMulticaster.multicastEvent(SafeApplicationEventMulticaster.java:17 😎
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:334)
at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:950)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:482)
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:410)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
at org.alfresco.web.app.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:63)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5016)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5524)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649)
at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:672)
at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1859)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: javax.naming.OperationNotSupportedException: [LDAP: error code 12 - 00002040: SvcErr: DSID-031401F1, problem 5010 ( UNAVAIL_EXTENSION), data 0
]; remaining name 'ou=***,dc=***,dc=local'
at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3196)
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3082)
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2888)
at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1846)
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769)
at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:392)
at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358)
at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:341)
at javax.naming.directory.InitialDirContext.search(InitialDirContext.java:267)
at org.alfresco.repo.security.sync.ldap.LDAPUserRegistry.processQuery(LDAPUserRegistry.java:1282)
... 40 more

If value of ldap.synchronization.queryBatchSize is 1000 or great alfresco.log present 1000 succsesful queries and get error on 1001 entity.

How I can fix it?

By secure reason change policy of LDAP is not possible.

[afaust]

I don't think this is an issue of Alfresco. It looks very much like the LDAP / AD server does not support paginated queries at all (it reports an unavailable extension / unsupported operation). Please use a standalone LDAP client to verify if the LDAP / AD actually supports this kind of operation, and check the configuration of the server if that fails as well, proving my assumption / suspicion.

[ruslan]

I was check LDAP queries in Active Directory Console installed on remote PC. It return ~2000 entities without errors.

Also I was try to do this queries by the ldapsearch utility on my server. It return 1000 entities and say about limitation:

root@doc-server:~# ldapsearch -H ldap://some-dc.***.local:389 -x -LLL -D AlfrescoLDAP@***.LOCAL -w ***-b "ou=***,dc=***,dc=local" "(&(objectclass=user)(userAccountControl:1.2.840.113556.1.4.803:=512))" dn | grep -c "^dn:"
Size limit exceeded (4)
1000

I don't know how to interpret such different results.

[ruslan]

The problem was solved for me by this guide: