Confluence AD sync adding and deleting few users

[Neeraj Malik]

Hi team,

we are facing issue with User AD sync in confluence we have around 1000 users in our AD those synced to Confluence and we are facing issue suddenly now with 30-40 users.

as can see in audit log. sync automatically added these users and after some time remove them as well.

and i have also change the user synchronization time to 10 min. and now it behaves like it adding users in one sync and after 10 min deleting the same user. i can see all these users in unsynched directory.

kindly help!

[Neeraj Malik]

PFB Log file.

2019-08-09 14:53:09,742 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache INCREMENTAL synchronisation for directory [ 1343489 ] starting
2019-08-09 14:53:09,742 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache Attempting INCREMENTAL synchronisation for directory [ 1343489 ]
2019-08-09 14:53:11,757 INFO [Caesium-1-1] [crowd.directory.ldap.SpringLdapTemplateWrapper] call Timed call for search with handler on dc=dhl,dc=com took 1205ms
2019-08-09 14:53:12,335 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseUserChangesGuid scanned and compared [ 10 ] users to delete, [ 0 ] users to add, [ 0 ] users to update in DB cache in [ 1828ms ]
2019-08-09 14:53:12,349 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedUsersByName deleting [ 10 ] users
2019-08-09 14:53:12,405 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedUsersByName deleted [ 10 ] users in [ 56ms ]
2019-08-09 14:53:12,445 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] getUsersToAddAndUpdate scanning [ 0 ] users to add or update
2019-08-09 14:53:12,448 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers scanned and compared [ 0 ] users for update in DB cache in [ 39ms ]
2019-08-09 14:53:12,451 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers synchronised [ 0 ] users in [ 42ms ]
2019-08-09 14:53:12,490 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] getUsersToAddAndUpdate scanning [ 0 ] users to add or update
2019-08-09 14:53:12,492 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers scanned and compared [ 0 ] users for update in DB cache in [ 40ms ]
2019-08-09 14:53:12,496 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers synchronised [ 0 ] users in [ 44ms ]
2019-08-09 14:53:14,266 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseGroupChanges found [ 0 ] changed remote groups in [ 1770ms ]
2019-08-09 14:53:14,266 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedGroups scanning [ 0 ] groups to add or update
2019-08-09 14:53:14,271 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] findGroupsToUpdate scanned and compared [ 0 ] groups for update in DB cache in [ 3ms ]
2019-08-09 14:53:14,278 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedGroups synchronized [ 0 ] groups in [ 12ms ]
2019-08-09 14:53:14,281 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseGroupChanges scanned and compared [ 0 ] groups for delete in DB cache in [ 0ms ]
2019-08-09 14:53:14,282 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedGroups removing [ 0 ] groups
2019-08-09 14:53:14,283 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedGroups removed [ 0 ] groups successfully in [ 1ms ]
2019-08-09 14:53:14,284 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache INCREMENTAL synchronisation complete for directory [ 1343489 ] in [ 4542ms ]
2019-08-09 14:55:12,994 INFO [http-nio-8090-exec-17] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=20771814}
2019-08-09 14:55:12,998 INFO [http-nio-8090-exec-17] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-20771814?state-at=@head&state-format=html HTTP/1.1 for 20771814
2019-08-09 14:56:39,756 WARN [http-nio-8090-exec-21] [common.security.jersey.XsrfResourceFilter] passesAllXsrfChecks XSRF checks failed for request: https://confluence.dhl.com/rest/viewtracker/1.0/visits , origin: null , referrer: https://confluence.dhl.com/display/FLC/Fully+Landed+Cost+Home
-- referer: https://confluence.dhl.com/display/FLC/Fully+Landed+Cost+Home | url: /rest/viewtracker/1.0/visits | traceId: 79e6066c265b8a79 | userName: anonymous
2019-08-09 14:57:59,842 WARN [http-nio-8090-exec-1] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions:
->[com.atlassian.confluence.api.impl.service.relation.RelationServiceImpl.delete]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #44613632)
-- referer: https://confluence.dhl.com/pages/resumedraft.action?draftId=20771860&draftShareId=70b2925b-a7fe-4df8-969d-2c66881ac104 | url: /rest/experimental/relation/user/25c8b8076c604843016c62374889007b/touched/toContent/20771860 | traceId: f525ee86e0d69a54 | userName: lusuchan
2019-08-09 14:58:38,827 INFO [http-nio-8090-exec-18] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=20771814}
2019-08-09 14:58:38,833 INFO [http-nio-8090-exec-18] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-20771814?state-at=@head&state-format=html HTTP/1.1 for 20771814
2019-08-09 14:58:48,570 INFO [http-nio-8090-exec-15] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=15667099}
2019-08-09 14:58:48,585 INFO [http-nio-8090-exec-15] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-15667099?state-at=@head&state-format=html HTTP/1.1 for 15667099
2019-08-09 14:58:52,429 WARN [Caesium-1-4] [com.atlassian.trackback.DefaultTrackbackFinder] findPingUrls Unable to connect to 'http://agilecoach.de/themen/werte-prinzipien-und-praktiken/': java.net.ConnectException: Connection timed out (Connection timed out)
java.net.ConnectException: Connection timed out (Connection timed out)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at java.net.Socket.connect(Socket.java:538)
at java.net.Socket.<init>(Socket.java:434)
at java.net.Socket.<init>(Socket.java:286)
at org.apache.commons.httpclient.protocol.DefaultProtocolSocketFactory.createSocket(DefaultProtocolSocketFactory.java:80)
at org.apache.commons.httpclient.protocol.DefaultProtocolSocketFactory.createSocket(DefaultProtocolSocketFactory.java:122)
at org.apache.commons.httpclient.HttpConnection.open(HttpConnection.java:707)
at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:387)
at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
at com.atlassian.trackback.TrackbackUtils.getUrlContent(TrackbackUtils.java:149)
at com.atlassian.trackback.DefaultTrackbackFinder.findPingUrls(DefaultTrackbackFinder.java:52)
at com.atlassian.confluence.util.task.TrackbackQueueItem.execute(TrackbackQueueItem.java:38)
at com.atlassian.core.task.AbstractTaskQueue.flush(AbstractTaskQueue.java:32)
at com.atlassian.confluence.schedule.jobs.TaskQueueFlushJob.runJob(TaskQueueFlushJob.java:34)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.doRunJob(JobRunnerWrapper.java:120)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.lambda$runJob$0(JobRunnerWrapper.java:91)
at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContextInternal(VCacheRequestContextManager.java:87)
at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:71)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.runJob(JobRunnerWrapper.java:91)
at com.atlassian.scheduler.core.JobLauncher.runJob(JobLauncher.java:134)
at com.atlassian.scheduler.core.JobLauncher.launchAndBuildResponse(JobLauncher.java:106)
at com.atlassian.scheduler.core.JobLauncher.launch(JobLauncher.java:90)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.launchJob(CaesiumSchedulerService.java:443)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeLocalJob(CaesiumSchedulerService.java:410)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:388)
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:748)
2019-08-09 14:58:59,916 INFO [http-nio-8090-exec-6] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=20771860}
2019-08-09 14:58:59,923 INFO [http-nio-8090-exec-6] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-20771860?state-at=@head&state-format=html HTTP/1.1 for 20771860
2019-08-09 15:01:37,651 INFO [http-nio-8090-exec-5] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=20771502}
2019-08-09 15:01:37,663 INFO [http-nio-8090-exec-5] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-20771502?state-at=@head&state-format=html HTTP/1.1 for 20771502
2019-08-09 15:03:09,743 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache INCREMENTAL synchronisation for directory [ 1343489 ] starting
2019-08-09 15:03:09,743 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache Attempting INCREMENTAL synchronisation for directory [ 1343489 ]
2019-08-09 15:03:11,482 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseUserChangesGuid scanned and compared [ 0 ] users to delete, [ 0 ] users to add, [ 0 ] users to update in DB cache in [ 1166ms ]
2019-08-09 15:03:11,485 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedUsersByName deleting [ 0 ] users
2019-08-09 15:03:11,492 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedUsersByName deleted [ 0 ] users in [ 7ms ]
2019-08-09 15:03:11,551 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] getUsersToAddAndUpdate scanning [ 0 ] users to add or update
2019-08-09 15:03:11,555 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers scanned and compared [ 0 ] users for update in DB cache in [ 59ms ]
2019-08-09 15:03:11,568 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers synchronised [ 0 ] users in [ 72ms ]
2019-08-09 15:03:11,612 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] getUsersToAddAndUpdate scanning [ 0 ] users to add or update
2019-08-09 15:03:11,615 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers scanned and compared [ 0 ] users for update in DB cache in [ 46ms ]
2019-08-09 15:03:11,619 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedUsers synchronised [ 0 ] users in [ 50ms ]
2019-08-09 15:03:12,994 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseGroupChanges found [ 0 ] changed remote groups in [ 1375ms ]
2019-08-09 15:03:12,994 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedGroups scanning [ 0 ] groups to add or update
2019-08-09 15:03:13,004 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] findGroupsToUpdate scanned and compared [ 0 ] groups for update in DB cache in [ 7ms ]
2019-08-09 15:03:13,016 INFO [Caesium-1-1] [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] addOrUpdateCachedGroups synchronized [ 0 ] groups in [ 20ms ]
2019-08-09 15:03:13,020 INFO [Caesium-1-1] [directory.ldap.cache.UsnChangedCacheRefresher] synchroniseGroupChanges scanned and compared [ 0 ] groups for delete in DB cache in [ 0ms ]
2019-08-09 15:03:13,021 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedGroups removing [ 0 ] groups
2019-08-09 15:03:13,022 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteChangeOperations] deleteCachedGroups removed [ 0 ] groups successfully in [ 1ms ]
2019-08-09 15:03:13,023 INFO [Caesium-1-1] [atlassian.crowd.directory.DbCachingRemoteDirectory] synchroniseCache INCREMENTAL synchronisation complete for directory [ 1343489 ] in [ 3280ms ]
2019-08-09 15:03:27,273 INFO [http-nio-8090-exec-21] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=15667099}
2019-08-09 15:03:27,290 INFO [http-nio-8090-exec-21] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-15667099?state-at=@head&state-format=html HTTP/1.1 for 15667099
2019-08-09 15:03:33,842 INFO [http-nio-8090-exec-22] [plugins.synchrony.service.SynchronyExternalChangesManager] performExternalChange Started external change for ContentId{id=20771814}
2019-08-09 15:03:33,848 INFO [http-nio-8090-exec-22] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:8091/synchrony/v1/data/Synchrony-13bbc890-ecd7-3783-ac6c-718204992e44/confluence-20771814?state-at=@head&state-format=html HTTP/1.1 for 20771814
2019-08-09 15:05:45,524 ERROR [http-nio-8090-exec-5] [atlassian.troubleshooting.confluence.ConfluenceApplicationInfo] addSynchronyConfiguration com.atlassian.confluence.core.ConfluenceSystemProperties.isSynchronyProxyEnabled()
-- referer: https://confluence.dhl.com/plugins/servlet/troubleshooting/view/ | url: /plugins/servlet/troubleshooting/view/atst-detect-issues/view | traceId: 3709574d547190f6 | userName: confadmin
2019-08-09 15:05:45,530 ERROR [http-nio-8090-exec-5] [confluence.status.service.DefaultSystemInformationService] getModifications
-- referer: https://confluence.dhl.com/plugins/servlet/troubleshooting/view/ | url: /plugins/servlet/troubleshooting/view/atst-detect-issues/view | traceId: 3709574d547190f6 | userName: confadmin
2019-08-09 15:07:21,485 WARN [Caesium-1-4] [com.atlassian.trackback.DefaultTrackbackFinder] findPingUrls Unable to connect to 'https://retrospectivewiki.org/index.php?title=Retrospective_Plans': java.net.ConnectException: Connection timed out (Connection timed out)
java.net.ConnectException: Connection timed out (Connection timed out)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:666)
at sun.security.ssl.SSLSocketImpl.<init>(SSLSocketImpl.java:471)
at sun.security.ssl.SSLSocketFactoryImpl.createSocket(SSLSocketFactoryImpl.java:153)
at org.apache.commons.httpclient.protocol.SSLProtocolSocketFactory.createSocket(SSLProtocolSocketFactory.java:117)
at org.apache.commons.httpclient.protocol.SSLProtocolSocketFactory.createSocket(SSLProtocolSocketFactory.java:157)
at org.apache.commons.httpclient.HttpConnection.open(HttpConnection.java:707)
at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:387)
at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
at com.atlassian.trackback.TrackbackUtils.getUrlContent(TrackbackUtils.java:149)
at com.atlassian.trackback.DefaultTrackbackFinder.findPingUrls(DefaultTrackbackFinder.java:52)
at com.atlassian.confluence.util.task.TrackbackQueueItem.execute(TrackbackQueueItem.java:38)
at com.atlassian.core.task.AbstractTaskQueue.flush(AbstractTaskQueue.java:32)
at com.atlassian.confluence.schedule.jobs.TaskQueueFlushJob.runJob(TaskQueueFlushJob.java:34)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.doRunJob(JobRunnerWrapper.java:120)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.lambda$runJob$0(JobRunnerWrapper.java:91)
at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContextInternal(VCacheRequestContextManager.java:87)
at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:71)
at com.atlassian.confluence.impl.schedule.caesium.JobRunnerWrapper.runJob(JobRunnerWrapper.java:91)
at com.atlassian.scheduler.core.JobLauncher.runJob(JobLauncher.java:134)
at com.atlassian.scheduler.core.JobLauncher.launchAndBuildResponse(JobLauncher.java:106)
at com.atlassian.scheduler.core.JobLauncher.launch(JobLauncher.java:90)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.launchJob(CaesiumSchedulerService.java:443)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeLocalJob(CaesiumSchedulerService.java:410)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:388)
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:748)