Problem with directory sync (Active Directory)

[k3ns0h]

For my Bitbucker server -> under Administration -> ACCOUNTS - > User Directories, I have a Active Directory server set up.

However, I keep getting this error 'Synchronisation failed. See server logs for details.' even though the setup is the same for my JIRA server.

When I test settings with a user, everything works. Below are screenshots of the error messages for synchronization and the test remote connection which is successful.

[Christian Glockner]

Hi Ken,

What do you find in <BitbucketHome>/log/atlassian-bitbucket.log after you try to synchronize?

Cheers,

Christian

Premier Support Engineer

Atlassian

[k3ns0h]

Thanks Christian! Actually the logs folder looks empty -

drwxr-xr-x 7 atlbitbucket atlbitbucket  4096 Apr 25 00:35 app

drwxr-xr-x 2 atlbitbucket atlbitbucket  4096 Apr 25 00:35 bin

drwxr-xr-x 7 atlbitbucket atlbitbucket  4096 Apr 25 00:35 elasticsearch

-rw-r--r-- 1 atlbitbucket atlbitbucket   127 Mar 19 07:47 Launch Bitbucket in browser.url

drwxr-xr-x 3 atlbitbucket atlbitbucket  4096 Apr 25 00:35 lib

drwxr-xr-x 2 atlbitbucket atlbitbucket 49152 Apr 25 00:35 licenses

drwx------ 2 atlbitbucket atlbitbucket  4096 Apr 25 00:35 logs

-rw-r--r-- 1 atlbitbucket atlbitbucket  2588 Mar 19 07:47 README.txt

drwx------ 2 atlbitbucket atlbitbucket  4096 Apr 25 00:35 temp

drwx------ 2 atlbitbucket atlbitbucket  4096 Apr 25 00:35 work

atlbitbucket@ai3-aisg-collab-tools:/opt/atlassian/bitbucket/5.9.0$ pwd

/opt/atlassian/bitbucket/5.9.0

atlbitbucket@ai3-aisg-collab-tools:/opt/atlassian/bitbucket/5.9.0$ ls -l logs

total 0

[k3ns0h]

Below update of the log and highlights for Bitbucket which LDAP active directory fails and log for JIRA which succeeds. Both configurations are the same but Bitbucket's fail -

the bitbucket log is in: /var/atlassian/application-data/bitbucket/log/atlassian-bitbucket.log  and we get this stack trace on sync:

2018-04-30 13:57:44,353 ERROR [Caesium-1-4]  c.a.c.d.DbCachingRemoteDirectory Incremental synchronisation for directory [ 229377 ] was unexpectedly interrupted, falling back to a full synchronisationcom.atlassian.crowd.exception.OperationFailedException: Error looking up attributes for highestCommittedUSN at com.atlassian.crowd.directory.MicrosoftActiveDirectory.fetchHighestCommittedUSN(MicrosoftActiveDirectory.java:851) at com.atlassian.crowd.directory.ldap.cache.UsnChangedCacheRefresher.synchroniseChanges(UsnChangedCacheRefresher.java:116) at com.atlassian.crowd.directory.DbCachingRemoteDirectory.synchroniseCache(DbCachingRemoteDirectory.java:1160) at com.atlassian.crowd.manager.directory.DirectorySynchroniserImpl.synchronise(DirectorySynchroniserImpl.java:78) at com.atlassian.crowd.directory.DbCachingDirectoryPoller.pollChanges(DbCachingDirectoryPoller.java:50) at com.atlassian.crowd.manager.directory.monitor.poller.DirectoryPollerJobRunner.runJob(DirectoryPollerJobRunner.java:96) at com.atlassian.scheduler.core.JobLauncher.runJob(JobLauncher.java:153) at com.atlassian.scheduler.core.JobLauncher.launchAndBuildResponse(JobLauncher.java:118) at com.atlassian.scheduler.core.JobLauncher.launch(JobLauncher.java:97) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.launchJob(CaesiumSchedulerService.java:443) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJob(CaesiumSchedulerService.java:438) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJobWithRecoveryGuard(CaesiumSchedulerService.java:462) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:390) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:285) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:282) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34) at java.lang.Thread.run(Thread.java:745) ... 12 frames trimmedCaused by: org.springframework.ldap.UncategorizedLdapException: Uncategorized exception occured during LDAP processing; nested exception is javax.naming.NamingException: LDAP response read timed out, timeout used:120000ms.; remaining name '/' at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:228) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:397) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:440) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$2.timedCall(SpringLdapTemplateWrapper.java:205) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$TimedCallable.call(SpringLdapTemplateWrapper.java:146) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper.invokeWithContextClassLoader(SpringLdapTemplateWrapper.java:109) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper.lookup(SpringLdapTemplateWrapper.java:194) at com.atlassian.crowd.directory.MicrosoftActiveDirectory.fetchHighestCommittedUSN(MicrosoftActiveDirectory.java:827) ... 19 common frames omittedCaused by: javax.naming.NamingException: LDAP response read timed out, timeout used:120000ms. at com.sun.jndi.ldap.Connection.readReply(Connection.java:490) at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638) at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561) at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985) at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844) 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 javax.naming.directory.InitialDirContext.search(InitialDirContext.java:276) at org.springframework.ldap.transaction.compensating.manager.TransactionAwareDirContextInvocationHandler.invoke(TransactionAwareDirContextInvocationHandler.java:90) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$2.lambda$timedCall$0(SpringLdapTemplateWrapper.java:202) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:363) ... 25 common frames omitted


the jira log is in:  /opt/atlassian/jira/logs/catalina.out and when I sync from there I get:

2018-04-30 14:06:54,186 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10001 ] starting2018-04-30 14:06:54,186 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10001 ]2018-04-30 14:06:54,426 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] scanned and compared [ 0 ] users to delete, [ 0 ] users to add, [ 0 ] users to update in DB cache in [ 166ms ]2018-04-30 14:06:54,426 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 0 ] users2018-04-30 14:06:54,427 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 0 ] users in [ 0ms ]2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 0 ] users to add or update2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 0 ] users for update in DB cache in [ 8ms ]2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 0 ] users in [ 8ms ]2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 0 ] users to add or update2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 0 ] users for update in DB cache in [ 5ms ]2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 0 ] users in [ 5ms ]2018-04-30 14:06:54,638 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] found [ 0 ] changed remote groups in [ 198ms ]2018-04-30 14:06:54,638 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 0 ] groups to add or update2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 0 ] groups for update in DB cache in [ 8ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 0 ] groups in [ 8ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] scanned and compared [ 0 ] groups for delete in DB cache in [ 0ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] removing [ 0 ] groups2018-04-30 14:06:54,647 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] removed [ 0 ] groups successfully in [ 1ms ]2018-04-30 14:06:54,647 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation complete for directory [ 10001 ] in [ 461ms ]

so no issues for jira but the LDAP configs are the same as far as I can tell.

[k3ns0h]

The highlight is this strange part:

Caused by: org.springframework.ldap.UncategorizedLdapException: Uncategorized exception occured during LDAP processing; nested exception isjavax.naming.NamingException: LDAP response read timed out, timeout used:120000ms.; remaining name '/'

an extra slash somewhere??

[k3ns0h]

Below are the full logs -

the bitbucket log is in: /var/atlassian/application-data/bitbucket/log/atlassian-bitbucket.log  and we get this stack trace on sync:

2018-04-30 13:57:44,353 ERROR [Caesium-1-4]  c.a.c.d.DbCachingRemoteDirectory Incremental synchronisation for directory [ 229377 ] was unexpectedly interrupted, falling back to a full synchronisationcom.atlassian.crowd.exception.OperationFailedException: Error looking up attributes for highestCommittedUSN at com.atlassian.crowd.directory.MicrosoftActiveDirectory.fetchHighestCommittedUSN(MicrosoftActiveDirectory.java:851) at com.atlassian.crowd.directory.ldap.cache.UsnChangedCacheRefresher.synchroniseChanges(UsnChangedCacheRefresher.java:116) at com.atlassian.crowd.directory.DbCachingRemoteDirectory.synchroniseCache(DbCachingRemoteDirectory.java:1160) at com.atlassian.crowd.manager.directory.DirectorySynchroniserImpl.synchronise(DirectorySynchroniserImpl.java:78) at com.atlassian.crowd.directory.DbCachingDirectoryPoller.pollChanges(DbCachingDirectoryPoller.java:50) at com.atlassian.crowd.manager.directory.monitor.poller.DirectoryPollerJobRunner.runJob(DirectoryPollerJobRunner.java:96) at com.atlassian.scheduler.core.JobLauncher.runJob(JobLauncher.java:153) at com.atlassian.scheduler.core.JobLauncher.launchAndBuildResponse(JobLauncher.java:118) at com.atlassian.scheduler.core.JobLauncher.launch(JobLauncher.java:97) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.launchJob(CaesiumSchedulerService.java:443) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJob(CaesiumSchedulerService.java:438) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJobWithRecoveryGuard(CaesiumSchedulerService.java:462) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:390) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:285) at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:282) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59) at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34) at java.lang.Thread.run(Thread.java:745) ... 12 frames trimmedCaused by: org.springframework.ldap.UncategorizedLdapException: Uncategorized exception occured during LDAP processing; nested exception is javax.naming.NamingException: LDAP response read timed out, timeout used:120000ms.; remaining name '/' at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:228) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:397) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:440) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$2.timedCall(SpringLdapTemplateWrapper.java:205) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$TimedCallable.call(SpringLdapTemplateWrapper.java:146) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper.invokeWithContextClassLoader(SpringLdapTemplateWrapper.java:109) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper.lookup(SpringLdapTemplateWrapper.java:194) at com.atlassian.crowd.directory.MicrosoftActiveDirectory.fetchHighestCommittedUSN(MicrosoftActiveDirectory.java:827) ... 19 common frames omittedCaused by: javax.naming.NamingException: LDAP response read timed out, timeout used:120000ms. at com.sun.jndi.ldap.Connection.readReply(Connection.java:490) at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638) at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561) at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985) at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844) 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 javax.naming.directory.InitialDirContext.search(InitialDirContext.java:276) at org.springframework.ldap.transaction.compensating.manager.TransactionAwareDirContextInvocationHandler.invoke(TransactionAwareDirContextInvocationHandler.java:90) at com.atlassian.crowd.directory.ldap.SpringLdapTemplateWrapper$2.lambda$timedCall$0(SpringLdapTemplateWrapper.java:202) at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:363) ... 25 common frames omitted
this part is strange:

Caused by: org.springframework.ldap.UncategorizedLdapException: Uncategorized exception occured during LDAP processing; nested exception isjavax.naming.NamingException: LDAP response read timed out, timeout used:120000ms.; remaining name '/'

an extra slash somewhere??

the jira log is in:  /opt/atlassian/jira/logs/catalina.out and when I sync from there I get:

2018-04-30 14:06:54,186 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10001 ] starting2018-04-30 14:06:54,186 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10001 ]2018-04-30 14:06:54,426 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] scanned and compared [ 0 ] users to delete, [ 0 ] users to add, [ 0 ] users to update in DB cache in [ 166ms ]2018-04-30 14:06:54,426 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 0 ] users2018-04-30 14:06:54,427 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 0 ] users in [ 0ms ]2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 0 ] users to add or update2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 0 ] users for update in DB cache in [ 8ms ]2018-04-30 14:06:54,435 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 0 ] users in [ 8ms ]2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 0 ] users to add or update2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 0 ] users for update in DB cache in [ 5ms ]2018-04-30 14:06:54,440 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 0 ] users in [ 5ms ]2018-04-30 14:06:54,638 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] found [ 0 ] changed remote groups in [ 198ms ]2018-04-30 14:06:54,638 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 0 ] groups to add or update2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 0 ] groups for update in DB cache in [ 8ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 0 ] groups in [ 8ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.c.d.ldap.cache.UsnChangedCacheRefresher] scanned and compared [ 0 ] groups for delete in DB cache in [ 0ms ]2018-04-30 14:06:54,646 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] removing [ 0 ] groups2018-04-30 14:06:54,647 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] removed [ 0 ] groups successfully in [ 1ms ]2018-04-30 14:06:54,647 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation complete for directory [ 10001 ] in [ 461ms ]

so no issues for jira but the LDAP configs are the same as far as I can tell

[Christian Glockner]

Hi Ken,

The underlying problem is LDAP response read timed out, and the timeout is 2 minutes. This means your LDAP server didn't send a full response within 2 minutes of Bitbucket Server querying it - now this could be due to a large response, so I wonder if all of the configuration options (user and group filters) in Jira and Bitbucket Server are identical.

Cheers,

Christian

Premier Support Engineer

Atlassian

[k3ns0h]

Thanks Christian! I found the following difference, lemme check with my colleague who set it up for advice what should be used. Or you could advise on the recommend template / settings if you have experience on this?

- no incremental sync on Bitbucket

- user instead of User

- member instead of members

[k3ns0h]

Thanks Christian! I think this kinda sorts it out. We'll see if this stabilizes and give good performance. I set to incremental for the Bitbucket sync.