LDAP users unable to login randomly

[Patrick Sinclair]

I'm using Jira 5.2.5, running on Linux, and i am using Delegated Authentication with the JIRA internal DB for user accounts and groups.

we have 3 directories setup, 1 for each office.

for unknown reasons, 1 of the directories users are randomly not getting authenticated. Without changing anything, they will attempt over and over again, and eventually they will be authenticated.

The number of attempts required varies, some times it takes2 or 3 tries, some times more than 20 tries. Eventually, all users do get authenticated.

The logs always show the same pattern in atlassian-jira.log

(userIds, Ldap directory location, and IPs were removed, but they are all identical)

Failed logs always look like this :

===================

2013-11-13 12:50:06,096 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [atlassian.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = dc=csr,dc=corp - filter = (&(sAMAccountName=user))

2013-11-13 12:50:06,097 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Got Ldap context on server 'ldap://LDAP1:389'

2013-11-13 12:50:06,115 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [springframework.ldap.core.LdapTemplate] PartialResultException encountered and ignored javax.naming.PartialResultException: Unprocessed Continuation Reference(s); remaining name 'dc=csr,dc=corp'

(NOTE: following referrals has caused us issues in the past, so we leave follow referrals disabled)

2013-11-13 12:50:06,116 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [transaction.compensating.manager.TransactionAwareDirContextInvocationHandler] Closing context

2013-11-13 12:50:06,116 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] AuthenticationSource not set - using default implementation

2013-11-13 12:50:06,116 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Not using LDAP pooling

2013-11-13 12:50:06,116 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Trying provider Urls: ldap://LDAP1:389

2013-11-13 12:50:06,117 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

2013-11-13 12:50:06,119 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

2013-11-13 12:50:06,120 http-bio-8082-exec-7 DEBUG anonymous 770x746848x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

=====================

Successful logs look like this:

===================

2013-11-13 12:50:26,967 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [atlassian.crowd.directory.SpringLDAPConnector] Performing user search: baseDN = dc=csr,dc=corp - filter = (&(sAMAccountName=user))

2013-11-13 12:50:26,967 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Got Ldap context on server 'ldap://LDAP1:389'

2013-11-13 12:50:26,986 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [springframework.ldap.core.LdapTemplate] PartialResultException encountered and ignored javax.naming.PartialResultException: Unprocessed Continuation Reference(s); remaining name 'dc=csr,dc=corp'

(NOTE: following referrals has caused us issues in the past, so we leave follow referrals disabled)

2013-11-13 12:50:26,987 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [transaction.compensating.manager.TransactionAwareDirContextInvocationHandler] Closing context

2013-11-13 12:50:26,987 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] AuthenticationSource not set - using default implementation

2013-11-13 12:50:26,987 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Not using LDAP pooling

2013-11-13 12:50:26,987 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Trying provider Urls: ldap://LDAP1:389

*****this is the only difference******

2013-11-13 12:50:27,131 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [ldap.core.support.AbstractContextSource] Got Ldap context on server 'ldap://LDAP1:389'

2013-11-13 12:50:27,132 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

2013-11-13 12:50:27,134 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

2013-11-13 12:50:27,135 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

2013-11-13 12:50:27,137 http-bio-8082-exec-16 DEBUG anonymous 770x746865x1 1mrzxqc /login.jsp [crowd.manager.application.ApplicationServiceGeneric] Storing user attributes for user <user> and application <crowd-embedded>

=====================

I am not sure why the logs do not provide more details on the result of connecting to the ldap server, but that appears to be the only difference.

Based on the timestamps, i do not believe this is a timeout issue.

for Logging:

com.atlassian.crowd

com.atlassian.crowd.directory

com.atlassian.crowd.directory.SpringLDAPConnector

org.springwork

org.springwork.ldap are all set to DEBUG.

Does anyone know what can cause this, and how i can increase the logging level to get more detailed info?

Are there more packages i can add to the logging list to get more details on the connection and the results?

Thanks in advance for any info

[Erik Saline [BlackPearl PDM]]

I had issues with LDAP before, the problem was the time difference between the JIRA and LDAP server were more then 5 minutes a part. We would use ntp pointed at the same ntp server to keep the times less than 5 minutes apart.

You can use the linux date on each server to verify the times are only a few minutes apart.

[Andy Brook [Plugin People]]

Well, you seem familiar with referrals, that you have had problems 'with' them seems to indicate a problem with the ldap infrastructure. In the past, I would have auth fails because referrals were not enabled.

Why not set java.naming.referral = follow and see if the current problem goes away?

At an infrastructure level, do you have any kind of ldap server load balancing (F5 for example), if load balancing is occuring to one busy/flaky server that isn't responding/configured, this could be a factor.

[Patrick Sinclair]

Thanks for the input Andy, we have tried adding follow references, and paging (together and independantly) neither have improved the situation.

There shouldn't be a load balancer involved.

[Andy Brook [Plugin People]]

Flakey DNS can also cause issues, setup a ping on the server to your ldap, with a 10s delay, run that 24hrs, grep for fail.

[Jason Hensler]

Try enabling diagnostic profile in the "Logging and Profiling" admin section. Then take a look at <conf-bin-dir>/logs/*stdout.2013-11-11.log. This log file should contain a large amount of information from the application server itself instead of the application.