how to debug ldap login performance

Sometimes the LDAP login works pretty well, login is very fast.

However, there are times (I know this is the worst, the nondeterministic problem) when it is horribly slow, around 25-30 seconds. Turned on the debugging level to max, and I got this:

[2013-08-28 14:56:10,786]  DEBUG -     jetbrains.buildServer.LDAP - ------ Starting login sequence for user-entered login: 'dszabo' ------
[2013-08-28 14:56:10,786]  DEBUG -     jetbrains.buildServer.LDAP - Constructed filter '(sAMAccountName=myuser)' from teamcity.users.login.filter=(sAMAccountName=myuser)
[2013-08-28 14:56:10,786]  DEBUG -     jetbrains.buildServer.LDAP - Base environment properties: {java.naming.security.authentication=simple, java.naming.referral=follow, java.naming.provider.url=ldap://mydc:389/DC=mydomain,DC=net, java.naming.security.principal=CN=Collab Service,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net}
[2013-08-28 14:56:10,786]  DEBUG -     jetbrains.buildServer.LDAP - Performing search in LDAP: base='', filter='(sAMAccountName=myuser)', scope=2, attributes=[sAMAccountName, distinguishedName]
[2013-08-28 14:56:10,786]  DEBUG -     jetbrains.buildServer.LDAP - LDAP search result: CN=MyFullUserName,OU=MyOUName,OU=MyOyherOuName: null:null:{samaccountname=sAMAccountName: myuser, distinguishedname=distinguishedName: CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net}
[2013-08-28 14:56:34,061]   WARN -     jetbrains.buildServer.LDAP - Total results: 1
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - Retrieving attribute sAMAccountName set by teamcity.users.username in LDAP entry CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName: null:null:{samaccountname=sAMAccountName: myuser, distinguishedname=distinguishedName: CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net}
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - Found username for 'dszabo': dszabo
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - Set CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net as principal
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - Performing LDAP bind with principal: CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net, context environment: {java.naming.security.principal=CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net, java.naming.referral=follow, teamcity.options.createUsers=true, teamcity.options.users.synchronize=true, teamcity.options.syncTimeout=3600000, teamcity.users.property.email=mail, java.naming.security.authentication=simple, java.naming.provider.url=ldap://mydc:389/DC=mydomain,DC=net, teamcity.options.groups.synchronize=false, teamcity.users.login.filter=(sAMAccountName=$capturedLogin$), java.naming.security.credentials=<hidden>, teamcity.options.deleteUsers=true, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, teamcity.users.filter=(objectClass=user), teamcity.users.username=sAMAccountName, teamcity.users.property.displayName=displayName}
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - LDAP bind for principal CN=MyFullUserName,OU=MyOUName,OU=MyOtherOUName,DC=mydomain,DC=net successful
[2013-08-28 14:56:34,061]  DEBUG -     jetbrains.buildServer.LDAP - Previous username is null or equals to teamcityUsername

You can see that between the 'LDAP search result: ..." line and the 'WARN - total results: 1' line more than 20 seconds have elapsed. I really would like to find out why. Note this must be something with teamcity, because querying the LDAP with other tool (ldp.exe) is fast always (well, connect and bind takes 1-2 sec but then later the querying is fast).

2 comments
Comment actions Permalink

Also, out of the thin air, I am getting now the following error:

[2013-08-28 16:15:59,233]   WARN -     jetbrains.buildServer.LDAP - Search in LDAP: base='', filter='(sAMAccountName=myuser)', scope=2, attributes=[sAMAccountName, distinguishedName] resulted in error
[2013-08-28 16:15:59,233]   INFO -     jetbrains.buildServer.LDAP - Failed to find user in LDAP by 'dszabo'. Cause: nested exception is javax.naming.PartialResultException [Root exception is javax.naming.CommunicationException: mydomain.net:389 [Root exception is java.net.ConnectException: Connection timed out: connect]]
Most common reason for this error: LDAP server doesn't process referrals.
Please verify the following property:
  java.naming.referral
and try to set it to 'follow'

+++

* it is already set to follow in ldap.config
* don't understand the communication exception. the java.naming.provider.url is set up as ldap://mydc:389/DC=mydomain,DC=net, not ldap://mydomain.net:389
* it is working sometimes... really frustrating

0
Comment actions Permalink

Well, it has been sorted out. Changing the LDAP port from 389 to 3268 (did not know about its existence at all) made ldap queries lightning fast all the time.

I don't know the explanation, it must be something with our ldap setup (dc's, catalogs, etc)...

0

Please sign in to leave a comment.