OpenLDAP users get removed from Jira, sporadically

Dee Heffemm October 31, 2017

We've been testing Jira for a month or so with users provisioned via OpenLDAP (Read Only, with Local Groups). It's been working well, however from time-to-time (maybe every couple days) users are getting sporadically removed from either/or the local groups in Jira, or their User account is displayed in a Strike-Through text attribute. We suspect a synchronization issue since manually synchronizing seems to correct the problem.

I've looked in the atlassian-jira.log on our Jira server and it seems that the LDAP communications are OK (below).  What would some possible causes of this be? Is this a known issue? Would an LDAP/Network issue turn up in a different logfile somewhere?

Thanks!

2017-10-31 00:07:56,196 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 57 ms ]
2017-10-31 00:07:56,259 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 55 ms ]
2017-10-31 00:07:56,266 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 01:07:56,193 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 55 ms ]
2017-10-31 01:07:56,247 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 49 ms ]
2017-10-31 01:07:56,255 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 02:07:56,215 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 76 ms ]
2017-10-31 02:07:56,269 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 48 ms ]
2017-10-31 02:07:56,278 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 2ms ]
2017-10-31 03:07:56,187 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 59 ms ]
2017-10-31 03:07:56,243 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 51 ms ]
2017-10-31 03:07:56,249 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 2ms ]
2017-10-31 04:07:56,187 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 56 ms ]
2017-10-31 04:07:56,244 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 50 ms ]
2017-10-31 04:07:56,251 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 2ms ]
2017-10-31 05:07:56,190 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 60 ms ]
2017-10-31 05:07:56,247 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 49 ms ]
2017-10-31 05:07:56,255 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 06:07:56,196 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 60 ms ]
2017-10-31 06:07:56,249 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 47 ms ]
2017-10-31 06:07:56,256 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 07:07:56,191 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 54 ms ]
2017-10-31 07:07:56,356 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 49 ms ]
2017-10-31 07:07:56,363 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 08:07:56,195 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 60 ms ]
2017-10-31 08:07:56,357 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 50 ms ]
2017-10-31 08:07:56,367 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 09:07:56,193 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 59 ms ]
2017-10-31 09:07:56,249 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 51 ms ]
2017-10-31 09:07:56,257 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 4ms ]
2017-10-31 10:07:56,192 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 57 ms ]
2017-10-31 10:07:56,250 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 49 ms ]
2017-10-31 10:07:56,257 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 11:07:56,192 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 61 ms ]
2017-10-31 11:07:56,249 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 51 ms ]
2017-10-31 11:07:56,256 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 12:07:56,200 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 54 ms ]
2017-10-31 12:07:56,254 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 48 ms ]
2017-10-31 12:07:56,262 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
2017-10-31 13:07:56,199 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 59 ms ]
2017-10-31 13:07:56,255 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 51 ms ]
2017-10-31 13:07:56,261 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]

 

1 answer

0 votes
Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
November 1, 2017

Hi Dave,

Looking at that part of the log, I don't see a problem that clearly explains the behavior you report.  But given what you are reporting happening I have a theory that Jira might be stuck doing a sync, in which case either the account is missing or the group membership is missing or both.  Either way, it could account for why those users can't login when this happens.

I would be interested to learn if the logs you show here correspond to a time when this problem happened.  If it did, then it might help to increase the verbosity of the logs Jira is creating.   To do this you can go into Logging and Profiling in Jira.   From there I would recommend finding the entry for:

com.atlassian.crowd.directory 

and you can then set this entry to DEBUG. By doing so, you should be able to see more detailed information of what Jira is doing when this problem happens again.

Regards,
Andy

Dee Heffemm November 6, 2017

Thanks Andy. I checked the logs last Friday and noticed the log entries below (have not enabled DEBUG logging yet).  Is there some LDAP setting that would cause this? I had everything fixed up Friday morning (after re-adding users to their correct groups/re-synching manually) around 9am but then again around 10:22am, there is "INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL"

2017-11-03 06:37:58,891 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete for directory [ 10000 ] in [ 654ms ]
2017-11-03 07:25:23,741 Caesium-1-3 INFO ServiceRunner     [c.a.j.p.h.service.connect.InstallGlancesJobHandler] Running InstallGlancesJobHandler...
2017-11-03 07:25:23,741 Caesium-1-3 INFO ServiceRunner     [c.a.j.p.h.service.connect.InstallGlancesJobHandler] There is no link to HipChat, no need to install glances.
2017-11-03 07:25:26,574 Caesium-1-2 INFO ServiceRunner     [c.a.j.p.h.service.ping.RefreshConnectionStatusJobHandler] Running RefreshConnectionStatusJobHandler...
2017-11-03 07:28:07,660 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-03 07:28:07,661 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-03 07:28:07,661 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-03 07:28:07,661 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-03 07:28:07,720 Caesium-1-4 INFO ServiceRunner     [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 59 ms ]
2017-11-03 07:28:07,723 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 2ms ]
2017-11-03 07:28:07,723 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 9 ] users
2017-11-03 07:28:07,806 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 9 ] users in [ 83ms ]
2017-11-03 07:28:07,806 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 85ms ]
2017-11-03 07:28:07,808 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update
2017-11-03 07:28:07,808 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10 ] users for update in DB cache in [ 2ms ]
2017-11-03 07:28:07,808 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] adding [ 3 ] users
2017-11-03 07:28:07,838 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] added [ 3 ] users successfully in [ 30ms ]
2017-11-03 07:28:07,838 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10 ] users in [ 32ms ]
2017-11-03 07:28:07,888 Caesium-1-4 INFO ServiceRunner     [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 50 ms ]
2017-11-03 07:28:07,896 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 8 ] groups for delete in DB cache in [ 3ms ]
2017-11-03 07:28:07,896 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 8 ] groups to add or update
2017-11-03 07:28:07,897 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 8 ] groups for update in DB cache in [ 1ms ]
2017-11-03 07:28:07,897 Caesium-1-4 INFO ServiceRunner     [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 8 ] groups in [ 1ms ]
2017-11-03 07:28:07,900 Caesium-1-4 INFO ServiceRunner     [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 3ms ]
Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
November 6, 2017

Hi Dave,

The failed incremental sync is not uncommon to see with Jira.   That by itself is not really an indication of a problem here.   I would be interested to learn if there have been other reported problems with users being unable to login since Friday.   I can't say yet if this might be something to do with a setting in LDAP, or a performance problem in LDAP and/or Jira.   But if we can reproduce this problem with the debug logging enabled, it might tell us more about what is happening from Jira's side when these users get in a stuck state where they cannot login.

Andy

Dee Heffemm November 7, 2017

Hi Andrew,

I have some debug logs (snippet below). What I suspect is happening is our HR import is running at 7am to refresh user accounts in LDAP. These accounts may or may not be available for a couple minutes while the process is running.

Under 'User Directories -> Advanced Settings' I see there are some options regarding sychronization. Perhaps adjusting some of these could help? Wondering if there's a way to tell Jira to not sync with LDAP for 5 minutes after 7am?

 

...
2017-11-07 07:07:58,243 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-07 07:07:58,243 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-07 07:07:58,243 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-07 07:07:58,243 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-07 07:07:58,243 Caesium-1-1 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote users
2017-11-07 07:07:58,244 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = ou=people,dc=my,dc=org - filter = (memberof=cn=jira-ldap,ou=groups,dc=my,dc=org)
2017-11-07 07:07:58,245 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Name checking SSLSocketFactory created
2017-11-07 07:07:58,247 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Creating disconnected socket
2017-11-07 07:07:58,295 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Paged results are enabled with a paging size of: 500
2017-11-07 07:07:58,299 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ldap.SpringLdapTemplateWrapper] Timed call for search with handler on ou=people,dc=my,dc=org took 3ms
2017-11-07 07:07:58,299 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Iterating a search result size of: 500
2017-11-07 07:07:58,300 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 57 ms ]
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ csmith ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jdavidson ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ ljohnson ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jwilson ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ aarcher ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ avermont ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jericson ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jklaus ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ tbrown ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ mfarmer ] not found, deleting
2017-11-07 07:07:58,304 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 4ms ]
2017-11-07 07:07:58,304 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 10 ] users
2017-11-07 07:07:58,403 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 10 ] users in [ 99ms ]
2017-11-07 07:07:58,403 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 103ms ]
2017-11-07 07:07:58,405 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update 
...

 

UPDATE: After posting, I noticed these same log entries happening again at 7:43am. This is long after the HR import has finished. Not sure why that is (second snippet below).

2017-11-07 07:43:15,647 Caesium-1-3 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-07 07:43:15,648 Caesium-1-3 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-07 07:43:15,648 Caesium-1-3 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-07 07:43:15,648 Caesium-1-3 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-07 07:43:15,648 Caesium-1-3 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote users
2017-11-07 07:43:15,648 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = ou=people,dc=my,dc=org - filter = (memberof=cn=jira-ldap,ou=groups,dc=my,dc=org)
2017-11-07 07:43:15,649 Caesium-1-3 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Name checking SSLSocketFactory created
2017-11-07 07:43:15,650 Caesium-1-3 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Creating disconnected socket
2017-11-07 07:43:15,699 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Paged results are enabled with a paging size of: 500
2017-11-07 07:43:15,703 Caesium-1-3 DEBUG ServiceRunner [c.a.c.directory.ldap.SpringLdapTemplateWrapper] Timed call for search with handler on ou=people,dc=my,dc=org took 3ms
2017-11-07 07:43:15,703 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Iterating a search result size of: 500
2017-11-07 07:43:15,704 Caesium-1-3 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 56 ms ]
2017-11-07 07:43:15,706 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ csmith ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jdavidson ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jwilson ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ avermont ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jericson ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jklaus ] not found, deleting
2017-11-07 07:43:15,707 Caesium-1-3 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 3ms ]

 

 

Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
November 7, 2017

Hi Dave,

Thanks for these logs.  I can see where Jira is syncing with this directory and in turn it is removing these users from Jira.   I would only expect this to happen when the directory itself does not contain the user accounts at the time of that sync, or the accounts exist but are not matching your filters configured in Jira.

So there is certainly something strange going on with the LDAP server.  To help narrow the focus here, it would help if you had some other means to connect to this LDAP instance and verify that the user accounts exist with all the attributes at the same time that Jira is doing a sync like this.  I suspect that the LDAP instance is correct, but having the verification of another application helps confirm this.

It might be worth looking more closely at your directory configuration in Jira.  Specifically I would be interested to focus on the basedn, userdn (if used), as well as the User schema settings: in particular the user object filter.  That filter can be used to more provide more granularity when trying to refine while user accounts to sync over.   Depending on the attributes being filtered there might help to identify if maybe the account exists in LDAP, but say it's missing a key attribute during this LDAP import process, and subsequently Jira is looking for that specific attribute in order to bring that user into Jira.

To answer you other question, yes you can change the interval at which Jira syncs to this directory under the advanced settings.  By default this is set to 60 minutes.   This sync starts the first time immediately after Jira starts up.   So we can't exactly control the sync times manually with Jira, but if you were to start Jira at 6:30, you could expect the sync to occur about every 60 minutes from that point (7:30, 8:30, 9:30 etc).   You can change this interval as well, but it becomes a delicate balance between how much overhead this sync takes, and how often changes are happening to your LDAP instance.   Sync too often, and you tend to have performance problems (especially with large directories with thousands of users/groups), sync too infrequently, and Jira might not be aware of the changes to your LDAP instance for that period of time.

I took another look at this and found that your sync seems to be paging the results to only 500 user at a time:

2017-11-07 07:07:58,299 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Iterating a search result size of: 500

I am concerned to learn if this is a factor in the problem here.  By default, Jira is set to limit the results to 1000 per page.   I'd be interested to learn more about the number of total users being added into this Jira instance, and whether or not you can either increase this page level to a higher range, or even uncheck the "Use paged results" option in the advanced settings of the directory.   I am curious to learn if this forces the sync to take longer, and/or if the results are more accurate.

Dee Heffemm November 7, 2017

Andrew,

Thanks again for the timely reponse.

When the HR import is running, it removes then re-creates "ou=people" and re-populates it from the HR data. This is likely the culprit.  We don't have any other applications which "sync" to the LDAP directory like Jira does; they only do LDAP binds to authenticate users. If the user doesn't exist at the time of the bind, authentication just fails. For the couple minutes it takes for the HR import to run (at 7am) nobody has every tried logging in that early in the morning so it's never been a problem.

In the paste above, I've obfuscated the basedn to be "dc=my,dc=org" with users residing in "ou=people,dc=my,dc=org".  The user filter we have place is "memberof=cn=jira-ldap,ou=groups,dc=my,dc=org".  Users in the jira-ldap group are placed in local groups within Jira. 

The LDAP server has a hard query limit of 500 results. If we issue (at a *nix cli for instance) `ldapsearch -x -ZZ -b dc=my,dc=org objectClass=*` the maximum number of results returned is 500 so without paging, I'm not sure how an application could scan for new users in the DIT without paging or getting a full dump. The admin account for the LDAP server can do a full dump, without paging, and that returns 828 users under ou=people so Jira definitely isn't getting all it's info about all users in one connection.

The import process was intended as an interim solution which has been running for years now.  Likely we need to address it as I have a strong suspicion this is what is causing the trouble. It seems odd that Jira wouldn't eventually find the "missing" people and put them back where they belong since it doesn't actually remove the users from Jira (user fonts are in strikethrough).  That would understandably have been an unusual corner-case for a  design choice however.

Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
November 7, 2017

Ah, Thanks for clarifying Dave.  When you see a username in Jira with a strikethrough, the account itself actually has been deleted from LDAP. But Jira tends to create these when the user is deleted because to have a deleted user in Jira poses other historical integrity problems when it comes to Jira.  So by creating this placeholder, Jira can still make sure to avoid nullpointer exceptions that might otherwise occur and still keep historical info.

The account name might still exist in cwd_user or the app_user tables of the database, but the account itself is not able to be activated in Jira and that user certainly can't login.

I would expect that if Jira is doing a full sync, provided the LDAP directory isn't making changes during this full sync that Jira would be able to correct this problem.

How long does it take for this LDAP import process to complete?   I am just wondering if we can avoid this process by tweaking the interval that Jira users to Sync this in conjunction with the time Jira is started up to completely avoid this problem for Jira.   If that doesn't work out then perhaps this is something that can be adjusted from the LDAP side of things.

Dee Heffemm November 8, 2017

Ok, thanks for clarifying what the strikethrough users represent to Jira. That's clearer now.

Now that I think about it, what might be complicating matters is that DNS entry for "ldap.my.org" actually returns one of two servers; a master and a replica.  The import runs on the master. If the replica has not finished updating by the time Jira tries a sync, it may only get partial records returned (I've attached screenshots below of our ldap settings). I've noticed the Jira configuration is using the entryUUID attribute for "tracking user identity" and wondering if this may play a part as well. Looking at a some of the DIT dumps over the past week, it seems this attribute *does* change for any given user. Likely it's based on a timestamp but I can't confirm. If the import is run at different times of the day, users may have an entirely different entryUUID generated on their account. Perhaps this entry in Jira would work better set to a Posix uidNumber ? That would never change for a given user, everyone has one and they aren't duplicated.

The import launches at 7am via cron. When run at the console, it only takes a couple minutes to run so I would assume cron had finished long before 7:07 (in the log entries above) but the replica may have still been updating. 

I've disabled the import this morning and users in Jira are unchanged from yesterday afternoon. Our nightly backups are a bit network intensive so I was curious if that might be part of the problem but it doesn't seem so. Despite holding off on the import, the INCREMENTAL synchronization still shows "was not completed" in the logs, however there were no users deleted this time (also below).

This morning, I waited for Jira to do a FULL sync, and then ran the import by hand. It completed within two minutes.  After the import, I checked the contextCSN attribute (a timestamp which indicates LDAP synchronization of master/replica) on both LDAP servers and these attributes were the same so this seems to indicate there isn't a remarkable lag in synchronization (at ~8:09am anyway).  I'll wait for Jira to do it's normal sync interval and see what happens.

UPDATE: After Jira ran it's FULL sync at 9:22am the logs (added to the end of this post) report "user not found". The LDAP master/replica were (ostensibly) fully synchronized by this time and it had been over an hour since the import ran. I'm now wondering if entryUUID was different after import for the users Jira reported as "not found".

 

2017-11-08 08:07:58,252 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-08 08:07:58,252 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-08 08:07:58,252 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-08 08:07:58,252 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-08 08:07:58,252 Caesium-1-4 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote users
2017-11-08 08:07:58,253 Caesium-1-4 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = ou=people,dc=my,dc=org - filter = (memberof=cn=jira-ldap,ou=groups,dc=my,dc=org)
2017-11-08 08:07:58,254 Caesium-1-4 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Name checking SSLSocketFactory created
2017-11-08 08:07:58,256 Caesium-1-4 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Creating disconnected socket
2017-11-08 08:07:58,306 Caesium-1-4 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Paged results are enabled with a paging size of: 500
2017-11-08 08:07:58,309 Caesium-1-4 DEBUG ServiceRunner [c.a.c.directory.ldap.SpringLdapTemplateWrapper] Timed call for search with handler on ou=people,dc=my,dc=org took 2ms
2017-11-08 08:07:58,309 Caesium-1-4 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Iterating a search result size of: 500
2017-11-08 08:07:58,311 Caesium-1-4 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 59 ms ]
2017-11-08 08:07:58,314 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 3ms ]
2017-11-08 08:07:58,314 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 3ms ]
2017-11-08 08:07:58,315 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update
2017-11-08 08:07:58,315 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10 ] users for update in DB cache in [ 1ms ]
2017-11-08 08:07:58,315 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10 ] users in [ 1ms ]
2017-11-08 08:07:58,315 Caesium-1-4 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote groups
...
2017-11-08 08:07:58,853 Caesium-1-4 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete for directory [ 10000 ] in [ 601ms ]

 

ldap1.pngldap2.pngldap3.pngldap4.pngldap5.png

 

LOG UPDATE:

 

 

2017-11-08 09:22:58,258 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-08 09:22:58,258 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-08 09:22:58,258 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-08 09:22:58,258 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-08 09:22:58,258 Caesium-1-1 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote users
2017-11-08 09:22:58,258 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = ou=people,dc=my,dc=org - filter = (memberof=cn=jira-ldap,ou=groups,dc=my,dc=org)
2017-11-08 09:22:58,259 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Name checking SSLSocketFactory created
2017-11-08 09:22:58,261 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ssl.LdapHostnameVerificationSSLSocketFactory] Creating disconnected socket
2017-11-08 09:22:58,309 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Paged results are enabled with a paging size of: 500
2017-11-08 09:22:58,317 Caesium-1-1 DEBUG ServiceRunner [c.a.c.directory.ldap.SpringLdapTemplateWrapper] Timed call for search with handler on ou=people,dc=my,dc=org took 6ms
2017-11-08 09:22:58,317 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.SpringLDAPConnector] Iterating a search result size of: 500
2017-11-08 09:22:58,318 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 60 ms ]
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ csmith ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jdavidson ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ ljohnson ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jklaus ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ aarcher ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ avermont ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jericson ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ mfarmer ] not found, deleting
2017-11-08 09:22:58,322 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 4ms ]
2017-11-08 09:22:58,322 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 8 ] users
2017-11-08 09:22:58,383 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 8 ] users in [ 61ms ]
2017-11-08 09:22:58,383 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 65ms ]
2017-11-08 09:22:58,394 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jdavidson ] has been updated since the synchronisation started, skipping
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ mfarmer ] not found, adding
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jericson ] has been updated since the synchronisation started, skipping
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ aarcher ] not found, adding
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ csmith ] has been updated since the synchronisation started, skipping
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ avermont ] has been updated since the synchronisation started, skipping
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ jklaus ] has been updated since the synchronisation started, skipping
2017-11-08 09:22:58,394 Caesium-1-1 DEBUG ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] user [ ljohnson ] not found, adding
2017-11-08 09:22:58,394 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10 ] users for update in DB cache in [ 11ms ]
2017-11-08 09:22:58,394 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] adding [ 3 ] users
2017-11-08 09:22:58,415 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] added [ 3 ] users successfully in [ 21ms ]
2017-11-08 09:22:58,415 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10 ] users in [ 32ms ]
2017-11-08 09:22:58,415 Caesium-1-1 DEBUG ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] loading remote groups
...
2017-11-08 09:22:59,207 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete for directory [ 10000 ] in [ 949ms ]

 

Dee Heffemm November 10, 2017

@Andy Heinzer,

Would you know if changing the 'user Unique ID Attribute' field to something else may help here?

Thanks

Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
November 10, 2017

Hi Dave,

Thanks for the update.  The fact that we now know your LDAP address could be referring to two different instance certainly helps make sense of the problems we see here.

The approach I would recommend would be to try to remove the ambiguity as to which LDAP instance Jira is using.   In order to do that I would recommend replacing the address in the configuration Jira has for this User directory with the explicit address of one of these LDAP instances.

The reason I think this approach is best is because we don't know which LDAP instance Jira will reach when it tries to do its sync each time.   If it happens to get the reply from a different server, with different data than the last sync, it can certainly then be expected to go through and remove the users not found in that LDAP instance.   By selecting a single LDAP instance, I think you will get much more consistent results during these syncs.

The unique user id attribute should not effect this just yet.   That attribute is more important when renaming users in LDAP to make sure Jira understands it is the same account just with a different name.   It's possible to migrate user directories in Jira, as long as the same username exists in the new top directory when doing a migration, the user account gets pulled into Jira when syncing with the new top directory.  I know you're not exactly doing a migration, but the fact that your LDAP address has a master/replica setup means that Jira could be connecting to either of these during any given sync.  So the behavior is somewhat similar to what we see when admins change user directories in Jira.

When Jira changes these kinds of LDAP directory connections, only if the user account does not exist in the (BaseDN + UserDN +User object LDAP filter) on that LDAP directory would the user account be expected to get removed when syncing with that address.   That is what I think is happening here.  These users accounts either are not in the other LDAP directory, or are not matching the user object filter criteria at the time Jira syncs with that directory.

I understand that it might be desirable to try to connect to this one address for the sake of redundancy or reliability of the LDAP, but in this case I think it might be causing problems. 

Regards,
Andy

Dee Heffemm November 10, 2017

@Andy HeinzerHmmm.. I went into our testing environment  where we only have one LDAP server answering queries (clone of our production master) and a clone of our Jira setup as well. I ran the production HR import and then a manual sync.  A handful of users suddenly showed up in strikethrough font, two did not. Forcing a second manual sync, everyone was back in. Tried it a second time and the same thing happened - only two users active, second manual sync, everyone is there.  I looked in the logs and that seems to confirm; 10 users found, 10 users deleted, two users added (logs here):

2017-11-10 11:36:55,927 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-10 11:36:55,988 Caesium-1-1 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 61 ms ]
2017-11-10 11:36:55,991 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 3ms ]
2017-11-10 11:36:55,991 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleting [ 10 ] users
2017-11-10 11:36:56,071 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] deleted [ 10 ] users in [ 80ms ]
2017-11-10 11:36:56,071 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 83ms ]
2017-11-10 11:36:56,073 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update
2017-11-10 11:36:56,073 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10 ] users for update in DB cache in [ 2ms ]
2017-11-10 11:36:56,073 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] adding [ 2 ] users
2017-11-10 11:36:56,085 Caesium-1-1 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] added [ 2 ] users successfully in [ 12ms ]

 

I then configured Jira to use only the single master LDAP server and ran another import. Only two users showed up active again. I forced a second sync, and everyone re-appeared in normal font. This is using a single LDAP server..hmm..

After getting everyone synced up again, I changed the 'user Unique ID Attribute' to uidNumber and ran an import then two manual syncs - (the first showed strikethrough'd users, second fixed it). I've done three more subsequent imports and I've not had any users show up in strikethrough.  This is what the logs show during the sync now:

2017-11-10 13:15:26,470 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] starting
2017-11-10 13:15:26,470 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Attempting INCREMENTAL synchronisation for directory [ 10000 ]
2017-11-10 13:15:26,470 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2017-11-10 13:15:26,470 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL
2017-11-10 13:15:26,524 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 10 ] remote users in [ 54 ms ]
2017-11-10 13:15:26,526 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10 ] users for delete in DB cache in [ 2ms ]
2017-11-10 13:15:26,527 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 3ms ]
2017-11-10 13:15:26,528 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10 ] users to add or update
2017-11-10 13:15:26,528 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10 ] users for update in DB cache in [ 1ms ]
2017-11-10 13:15:26,528 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10 ] users in [ 1ms ]
2017-11-10 13:15:26,576 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.RemoteDirectoryCacheRefresher] found [ 8 ] remote groups in [ 48 ms ]
2017-11-10 13:15:26,579 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 8 ] groups for delete in DB cache in [ 3ms ]
2017-11-10 13:15:26,579 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 8 ] groups to add or update
2017-11-10 13:15:26,580 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 8 ] groups for update in DB cache in [ 1ms ]
2017-11-10 13:15:26,580 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 8 ] groups in [ 1ms ]
2017-11-10 13:15:26,582 Caesium-1-2 INFO ServiceRunner [c.a.c.d.ldap.cache.AbstractCacheRefresher] finished group attribute sync with 0 failures in [ 2ms ]
2017-11-10 13:15:27,034 Caesium-1-2 INFO ServiceRunner [c.a.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete for directory [ 10000 ] in [ 565ms ]

 

I do realize it's hard to troubleshoot this from your end only getting snips of information but it sure seems like Jira is looking at the entryUUID attribute to determine valid users. Is there any more information you could use from my system to help determine the root cause?

Thanks

Suggest an answer

Log in or Sign up to answer