LSWS 1.5 + LDAP : it works BUT....

[bogus]

Hello,
I'm back !

Well, LSWS now works with LDAP here but... it takes 2'30 to grant access ! Moreover, the results are not cached, so it takes another 2'30 each time... :cry:

By the way, the same query made with ldapsearch takes less than 1 second !

When I take a look at the logs, I see that LSWS retrieves the object attributes one by one, with a delay of exactly 8 seconds between each. Curious, isn't it ?

LSWS LDAP conf :
Realm Name
SampleProtectedArea

DB Type
LDAP

User DB Location
ldap://myldap.com/dc=people,dc=myco,dc=net??sub?(uid=$k )

User DB Max Cache Size
200

User DB Cache Timeout(secs)
60

Group DB Location
N/A

Group DB Max Cache Size
200

Group DB Cache Timeout(secs)
60

LDAP Bind DN
uid=eos,o=myco,dc=people,dc=myco,dc=net


LDAP Bind Password
XXXXX

========> 2'30 (= 150 seconds)


The ldapsearch command

ldapsearch -x -h myldap.com -D "uid=eos,o=myco,dc=people,dc=myco,dc=net" -w XXXX -b dc=people,dc=myco,dc=net "(uid=niceuser)"

=========> less than 1 second.


Sincerely,

Darned Nuisance

[mistwang]

Welcome back! :-)

Well, LSWS now works with LDAP here but... it takes 2'30 to grant access ! Moreover, the results are not cached, so it takes another 2'30 each time...

Holy crap! :-(
I setup a remote LDAP server across internet, the authentication speed is very fast!

When I take a look at the logs, I see that LSWS retrieves the object attributes one by one, with a delay of exactly 8 seconds between each. Curious, isn't it ?

The delay is caused by openldap client library as all attributes are retrived inside a loop calling openldap API. You can try disable debug log or set log level to "medium", when log level set to "high", openldap library dumps a lot of debug information into stderr.log, that will cause a little delay, but I only see a couple milli-seconds delay in our log file.

Also, you can try "tcpdump", see if there is any network activities during the delay, I bet there is no activity at all.

If it does not take that long, the result should be cached.

Best regards,
George Wang

[bogus]

Hello,

According to tcpdump, the LDAP query itself over the networks only takes a fraction of a second. All remaining 2'30 are happenning inside LSWS. And on each request.

That's what LSWS log says too, by the way (first line), all the rest is offline :

2004-07-06 12:02:49.207 [DEBUG] [127.0.0.1:33590-0] Received search result for request 3, found entries 1, references 0
2004-07-06 12:02:49.207 [DEBUG] dn: uid=someone,o=mycorp,dc=people,dc=elikya,dc=net
2004-07-06 12:02:49.207 [DEBUG] Attr carLicense:Permis B
2004-07-06 12:02:50.774 [DEBUG] Attr cn:Joe Bar
2004-07-06 12:02:53.546 [DEBUG] Attr description:R'nD
2004-07-06 12:02:56.801 [DEBUG] Attr displayName:J.Bar
2004-07-06 12:03:00.563 [DEBUG] Attr objectClass:inetOrgPerson
2004-07-06 12:03:00.563 [DEBUG] Attr objectClass:organizationalPerson
2004-07-06 12:03:00.563 [DEBUG] Attr objectClasserson
2004-07-06 12:03:00.563 [DEBUG] Attr objectClass:top
2004-07-06 12:03:04.731 [DEBUG] Attr sn:Bar
2004-07-06 12:03:09.306 [DEBUG] Attr uid:jbar
2004-07-06 12:03:14.300 [DEBUG] Attr givenName:Joe
2004-07-06 12:03:19.612 [DEBUG] Attr homePhone:0 299 45 67 89
2004-07-06 12:03:25.320 [DEBUG] Attr homePostalAddress:20 rue des glands$39170 Brice
2004-07-06 12:03:31.303 [DEBUG] Attr l:Brice
2004-07-06 12:03:37.682 [DEBUG] Attr labeledURI:http://lab.mycorp.com
2004-07-06 12:03:44.490 [DEBUG] Attr mail:lab@mycorp.com
2004-07-06 12:03:52.222 [DEBUG] Attr o:MyCorp
2004-07-06 12:03:59.393 [DEBUG] Attr ou:MyLab
2004-07-06 12:04:06.761 [DEBUG] Attr postalAddress:80 avenue des buttes de Cogles$39700 Gruel
2004-07-06 12:04:14.295 [DEBUG] Attr postalCode:39700
2004-07-06 12:04:22.005 [DEBUG] Attr preferredLanguage:fr
2004-07-06 12:04:29.891 [DEBUG] Attr st:FR
2004-07-06 12:04:37.942 [DEBUG] Attr street:80 avenue des buttes de Cogles
2004-07-06 12:04:46.344 [DEBUG] Attr telephoneNumber:0 299 789 987
2004-07-06 12:04:54.615 [DEBUG] Attr title:Monsieur le chargé de recherches
2004-07-06 12:05:02.930 [DEBUG] Attr userPassword:XX
2004-07-06 12:05:11.289 [DEBUG] Attr businessCategory:Services
2004-07-06 12:05:19.856 [DEBUG] Attr facsimileTelephoneNumber:0 223 123 456
2004-07-06 12:05:19.944 [DEBUG] Search completed successfully.
EEntries found: 1
Search references returned: 0


Sincerely,

[mistwang]

So, it exactly matches my analysis. The the delay is caused by Openldap client library! For debuging purpose, we enabled openldap LDAP and BER debug logging when the debug level of LSWS is set to "high", you can find tons of LDAP log entries in "lsws/logs/stderr.log".

I have two suggestions:

1. turn off LSWS debug logging, that will turn off Openldap debug logging as well, see how long is the delay, I bet the delay will dissappear. :roll:

2. change User DB Location to

ldap://myldap.com/dc=people,dc=myco,dc=net?userPassword?sub?(uid=$k)

to only request "userPassword" attribute, as all the other attributes are uesless for authentication, if the delay still exists, it should be much shorter and the result should be cached.

We probably will write our own asynchronize LDAP client code when we have time later.

Best Regards,
George Wang

[bogus]

You're right, disabling DEBUG works great !

Thank you very much !