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)