Wednesday October 07, 2009

About LDAP connections in Sun Web Server 7.0

About LDAP connections in Sun Web Server 7.0 

When I have in my server.xml confiured an Sun LDAP server as given below  :

  <auth-db>
    <name>ldap</name>
    <url>ldap://localhost:1369/o%3DTestCentral</url>
    <property>
        <name>binddn</name>
        <value>cn=Directory Manager</value>
    </property>
    <property>
        <name>bindpw</name>
        <value>...</value><encoded/>
    </property>
  </auth-db>

When I have ACL set

acl "uri=/";
deny (all) user="anyone"; 
allow (all) user="all";  

When I send a request via browser as user "alpha" and its correct password.
First it binds as the user specified in server.xml "binddn" property ( in this case "cn=Directory Manager")
Then sends a LDAP search query with filter "uid=alpha".
Third step it does is it binds as that user "alpha" with the password user specified. If bind is successful, access is allowed.

Here are the entries I get in LDAP server access logs:

[07/Oct/2009:13:16:16 +051800] conn=2 op=-1 msgId=-1 - fd=34 slot=34 LDAP connection from 127.0.0.1 to 127.0.0.1
[07/Oct/2009:13:16:16 +051800] conn=2 op=0 msgId=1 - BIND dn="cn=Directory Manager" method=128 version=3
[07/Oct/2009:13:16:16 +051800] conn=2 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"

[07/Oct/2009:13:16:16 +051800] conn=2 op=1 msgId=2 - SRCH base="o=testcentral" scope=2 filter="(uid=alpha)" attrs="c"
[07/Oct/2009:13:16:16 +051800] conn=2 op=1 msgId=2 - RESULT err=0 tag=101 nentries=1 etime=0

[07/Oct/2009:13:16:16 +051800] conn=2 op=2 msgId=3 - BIND dn="uid=alpha,o=TestCentral" method=128 version=3
[07/Oct/2009:13:16:16 +051800] conn=2 op=2 msgId=3 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=alpha,o=testcentral"

To understand why we see these three entries, I started debugging Web Server from LASUserEval function and came at get_is_valid_password_ldap function. Note that line numbers in Open Web Server may differ but the concepts are the same :

t@16 (l@16) stopped in get_is_valid_password_ldap at line 455 in file "ldapacl.cpp"
  467       if ((rv = ld->find_userdn(raw_user, basedn, &userdn)) == LDAPU_SUCCESS) {
(dbx) p filter
filter = "uid=alpha"
... 
t@16 (l@16) stopped in LdapSession::find_userdn at line 1253 in file "LdapOps.cpp"
 1253           retval = find(base, LDAP_SCOPE_SUBTREE, filter, attrs, 1 /* no attrs */, res);
(dbx) s
...
t@16 (l@16) stopped in LdapSession::find at line 1174 in file "LdapOps.cpp"
 1174       res = search(base, scope, filter, (char **)attrs, attrsonly, 0);
(dbx) p base
base = 0x6ed6048 "o=TestCentral"
(dbx) p filter
filter = 0xfbfbc98c "uid=alpha"
...
(dbx) n
t@16 (l@16) stopped in LdapSession::search at line 289 in file "LdapSession.cpp"  
289           rv = bindAsDefault();
(dbx) s
t@16 (l@16) stopped in LdapSession::bindAsDefault at line 235 in file "LdapSession.cpp"
  235       int msg_id = ldap_simple_bind(session, ldapRealm->getBindName(), ldapRealm->getBindPwd());
(dbx) p msg_id
msg_id = 1
...
(dbx) n
t@16 (l@16) stopped in LdapSession::bindAsDefault at line 240 in file "LdapSession.cpp"
  240       int ret = ldap_result( session, msg_id, 0, &time_out, &res);
(dbx) p ret
ret = 97
...

As we can see Web Server first tries to bindAsDefault ie. bind as cn=Directory Manager. by looking at LDAP Server logs, we confirm this.

[07/Oct/2009:14:52:03 +051800] conn=4 op=-1 msgId=-1 - fd=34 slot=34 LDAP connection from 127.0.0.1 to 127.0.0.1
[07/Oct/2009:14:52:03 +051800] conn=4 op=0 msgId=1 - BIND dn="cn=Directory Manager" method=128 version=3
[07/Oct/2009:14:52:03 +051800] conn=4 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"

When bind is successful, now it tries LDAP search on basedn="o=TestCentra" with filter "uid=alpha"

...
(dbx) n
t@16 (l@16) stopped in LdapSession::search at line 296 in file "LdapSession.cpp"  
296           rv = lastoprv = ldap_search_ext_s(session, base, scope, filter,
297                                      attrs, attrsonly,
298                                      NULL, NULL, &time_out, LDAP_NO_LIMIT, &search_results);
(dbx) p base
base = 0x6ed6048 "o=TestCentral"
(dbx) p scope
scope = 2
(dbx) p filter
filter = 0xfbfbc98c "uid=alpha"
...
(dbx) n
t@16 (l@16) stopped in LdapSession::find at line 1178 in file "LdapOps.cpp"
 1178           break;
(dbx) n
t@16 (l@16) stopped in LdapSession::find at line 1187 in file "LdapOps.cpp"
 1187       numEntries = res->entries();
(dbx) n
t@16 (l@16) stopped in LdapSession::find at line 1189 in file "LdapOps.cpp"
 1189       if (numEntries == 1) {
(dbx) p numEntries
numEntries = 1
(dbx) n
...
(dbx) n
t@16 (l@16) stopped in LdapSession::find_userdn at line 1278 in file "LdapOps.cpp"
 1278       *dn = entry->DN();
(dbx) p *dn
*dn = 0x2d87b0 "uid=alpha,o=TestCentral"
(dbx)
...

Looking at LDAP server access logs it has created this "SRCH" entry :

[07/Oct/2009:14:55:51 +051800] conn=4 op=1 msgId=2 - SRCH base="o=testcentral" scope=2 filter="(uid=alpha)" attrs="c"
[07/Oct/2009:14:55:51 +051800] conn=4 op=1 msgId=2 - RESULT err=0 tag=101 nentries=1 etime=0

So at the end of find_userdn function, we get our userdn "uid=alpha,o=TestCentral". Coming back to debugger

(dbx) p userdn
userdn = 0x2d87b0 "uid=alpha,o=TestCentral"
(dbx)
t@16 (l@16) stopped in get_is_valid_password_ldap at line 531 in file "ldapacl.cpp"
  531                   rv = ld->userdn_password(userdn, raw_pw);
(dbx) s
...
(dbx) n
t@16 (l@16) stopped in LdapSession::userdn_password at line 1052 in file "LdapOps.cpp"
 1052       int msgid = ldap_simple_bind(session, userdn, password);
(dbx) p userdn
userdn = 0x2d87b0 "uid=alpha,o=TestCentral"
...
(dbx) n
t@16 (l@16) stopped in LdapSession::userdn_password at line 1058 in file "LdapOps.cpp"
 1058           rc = ldap_result(session, msgid, 0, &zerotime, &res );
(dbx) n
(dbx) p rc
rc = 97
...

As we can see Web Server tries to bind to LDAP server with userdn "uid=alpha,o=TestCentral" and we can confirm that by looking at LDAP server logs :

[07/Oct/2009:15:00:37 +051800] conn=4 op=2 msgId=3 - BIND dn="uid=alpha,o=TestCentral" method=128 version=3
[07/Oct/2009:15:00:37 +051800] conn=4 op=2 msgId=3 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=alpha,o=testcentral"

Also refer Jyri's blog for troubleshooting