LDAP login takes 2 minutes the first time

Hi.

We are using Sonarqube version 7.1.0.11001 as a docker container.

It sometimes happens that the LDAP login takes about 2 minutes to successfully login. Any subsequent logins don’t have this problem, until after some time, where it takes 2 minutes to log in again.

Unfortunately, I don’t know how to reproduce the problem reliably. Sometimes only a restart of the container is necessary and sometimes it just happens over time (maybe some sort of cache ran out for the user?)

Here is the truncated log file right before clicking log in and after that. There is more than a 2 minute silence (aside from the two entries at 10:39:51; Not sure if they contribute to the problem but they seem to appear always when the problem happens).

....
2018.08.06 **10:39:01** DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.p.l.LdapContextFactory] Initializing LDAP context {java.naming.provider.url=ldap://ldapsrv1, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.principal=CN=app_sonar_ldap,OU=app,OU=op,DC=cp,DC=wien, com.sun.jndi.ldap.connect.pool=true, java.naming.security.authentication=simple, java.naming.referral=follow}

2018.08.06 10:39:51 DEBUG ce[][o.s.c.c.CeCleaningSchedulerImpl] Deleting any worn out task
2018.08.06 10:39:51 DEBUG ce[][o.s.c.c.CeCleaningSchedulerImpl] Resetting state of tasks with unknown worker UUIDs

2018.08.06 **10:41:08** DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.a.UserIdentityAuthenticator] List of groups returned by the identity provider '[... grp_sec_sonarqube_admin, ...]'
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.a.UserIdentityAuthenticator] Adding group 'grp_sec_sonarqube_admin' to user 'sonar_admin'
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.u.NewUserNotifier] User created: sonar_admin. Notifying NewUserHandler handlers...
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][auth.event] login success [method|FORM][provider|REALM|LDAP][IP|10.116.0.4|10.116.6.90][login|sonar_admin]
...

LDAP Config:

sonar.forceAuthentication=true

sonar.security.realm=LDAP
sonar.authenticator.downcase=true

ldap.servers=server1,server2

ldap.server1.url=ldap://ldapsrv1
ldap.server1.bindDn=CN=app_sonar_ldap,OU=app,OU=op,DC=cp,DC=wien
ldap.server1.bindPassword=*********
ldap.server1.user.baseDn=OU=USR,DC=cp,DC=wien
ldap.server1.user.realNameAttribute=cn
ldap.server1.user.emailAttribute=mail
ldap.server1.user.request=(&(objectClass=user)(sAMAccountName={login})(|(memberOf:1.2.840.113556.1.4.1941:=CN=grp_sec_sonarqube_user,OU=SEC,OU=OP,DC=cp,DC=wien)(memberOf:1.2.840.113556.1.4.1941:=CN=grp_sec_sonarqube_admin,OU=SEC,OU=OP,DC=cp,DC=wien)))
ldap.server1.group.baseDn=DC=cp,DC=wien
ldap.server1.group.request=(&(objectClass=group)(member={dn}))
ldap.server1.group.idAttribute=sAMAccountName

ldap.server2.url=ldap://ldapsrv2
ldap.server2.bindDn=CN=app_sonar_ldap,OU=app,OU=op,DC=cp,DC=wien
ldap.server2.bindPassword=*********
ldap.server2.user.baseDn=OU=USR,DC=cp,DC=wien
ldap.server2.user.realNameAttribute=cn
ldap.server2.user.emailAttribute=mail
ldap.server2.user.request=(&(objectClass=user)(sAMAccountName={login})(|(memberOf:1.2.840.113556.1.4.1941:=CN=grp_sec_sonarqube_user,OU=SEC,OU=OP,DC=cp,DC=wien)(memberOf:1.2.840.113556.1.4.1941:=CN=grp_sec_sonarqube_admin,OU=SEC,OU=OP,DC=cp,DC=wien)))
ldap.server2.group.baseDn=DC=cp,DC=wien
ldap.server2.group.request=(&(objectClass=group)(member={dn}))
ldap.server2.group.idAttribute=sAMAccountName

My observations are the following: I don’t think it’s the search that takes so long since a non-existent user fails to login immediately (on both ldap servers). Only when a user exists and logs in with correct credentials, the waiting starts (also, during the waiting process, every other user that wants to login, no matter if the user exists or not, has to wait).

I’m grateful for any help. Thanks!

Hi,

Have you investigated this on the LDAP side? You’ve configured group synchronization, so I wonder if your LDAP server is returning that data in a timely manner.

Ann

Hi!

I’ve tried the following on the command line:

ldapsearch -D CN=app_sonar_ldap,OU=app,OU=op,DC=cp,DC=wien -W -h ldapsrv1 -b “OU=USR,DC=cp,DC=wien” “(&(objectClass=user)(sAMAccountName=sonar_admin))”

the result was returned instantly with all info of the user and what groups it is member of.

We have other apps/devices that support ldap and they work normally, with no login delay.

Also, we’ve ran another test and looked at the event log of the ldap server (Windows) and it only shows that the user successfully authenticated right when I clicked login:
Login clicked at: 11:09:24
Login successfull at: 11:13:41
Event shows “successfully logged on” at 11:09:26.

The event log didn’t show any other errors.

Hi,

From the logs you’ve sent, we can see that the 2 minutes are between LdapContextFactory and UserIdentityAuthenticator, which means that the problem is not on SonarQube side but on LDAP side :

2018.08.06 10:39:01 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.p.l.LdapContextFactory] Initializing LDAP context {java.naming.provider.url=ldap://ldapsrv1, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.principal=CN=app_sonar_ldap,OU=app,OU=op,DC=cp,DC=wien, com.sun.jndi.ldap.connect.pool=true, java.naming.security.authentication=simple, java.naming.referral=follow}

2018.08.06 10:39:51 DEBUG ce[o.s.c.c.CeCleaningSchedulerImpl] Deleting any worn out task
2018.08.06 10:39:51 DEBUG ce[o.s.c.c.CeCleaningSchedulerImpl] Resetting state of tasks with unknown worker UUIDs

2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.a.UserIdentityAuthenticator] List of groups returned by the identity provider ‘[… grp_sec_sonarqube_admin, …]’
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.a.UserIdentityAuthenticator] Adding group ‘grp_sec_sonarqube_admin’ to user ‘sonar_admin’
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][o.s.s.u.NewUserNotifier] User created: sonar_admin. Notifying NewUserHandler handlers…
2018.08.06 10:41:08 DEBUG web[AWUO0Y4Ownk8MHVXAAAG][auth.event] login success [method|FORM][provider|REALM|LDAP][IP|10.116.0.4|10.116.6.90][login|sonar_admin]

Then I would suggest to investigate the network, maybe you’re using a proxy ? Or something that could limit the bandwidth ?

Regards

Hi!

I’ve experimented with two configuration options in sonar.properties:

  • A different port: ldap.server1.url=ldap://ldapsrv1:3268
  • ldap.server1.followReferrals=false

With any of these options (not both at the same time) active, the problem didn’t apear (or at least, no matter what I tried, the problem didn’t manifest itself).

I’m guessing the default port used for LDAP is 389, and for some reason it doesn’t work well with that.

Not sure why ldap.server1.followReferrals=false helped, since we don’t have any sort of referrals in place.

So for now, it seems that it’s working.

Anyway, thanks for your time.

3 Likes