After a few hours of adding more Log.debug messages to pin down what is happening, here is what I’'ve learned.
The code call is coming in through
net/SASLAuthentication.java doPlainAuthentication()
auth/AuthFactory.java authenticate()
ldap/LdapAuthProvider.java authenticate()
Now here is where it gets strange.
I can track the code via debug messages as running once through the steps in LdapAuthProvider.authenticate(). So at the end of this routine I added a log message saying its done.
I can see this message in the logs, AND my client gets authenticated and hooks up.
BUT THEN, after a short pause (about 2-3 seconds) the log file takes off again and it seems that LdapManager.findUserDN(username); starts going mad and just checking out one user after another walking through the entire LDAP directory.
Now the code in LdapAuthProvider.authenticate() says something about needing to search all the subtree’'s of the baseDN for the username.
try {
// The username by itself won’'t help us much with LDAP since we
// need a fully qualified dn. We could make the assumption that
// the baseDN would always be the location of user profiles. For
// example if the baseDN was set to “ou=People, o=jivesoftare, o=com”
// then we would be able to directly load users from that node
// of the LDAP tree. However, it’'s a poor assumption that only a
// flat structure will be used. Therefore, we search all subtrees
// of the baseDN for the username. So, if the baseDN is set to
// “o=jivesoftware, o=com” then a search will include the “People”
// node as well all the others under the base.
Log.debug("LdapAuthProvider getting userDN "+userDN);
userDN = manager.findUserDN(username);
Log.debug("LdapAuthProvider authenticating userDN "+userDN);
// See if the user authenticates.
if (!manager.checkAuthentication(userDN, password)) {
throw new UnauthorizedException(“Username and password don’'t match”);
}
}
catch (Exception e) {
throw new UnauthorizedException(e);
}
// If cache is enabled, add the item to cache.
if (authCache != null) {
authCache.put(username, StringUtils.hash(password));
}
Log.debug("LdapAuthProvider DONE authenticating userDN "+userDN);
}
/code
But what I can’'t understand is the following
-
why do all these additional user lookups happen AFTER my user is already done being authenticated
-
why is LdapManager.findUserDN(username) getting called for all these other users in the directory
-
where are these calls being fired from? I don’'t see any loops in LdapAuthProvider.authenticate() that look like they could be the causes of the extra calls. Could there be possible threading problems with one of the ldap interface libraries?
Here are the logs that come out, you will see my user being authenticated. Then things go crazy and we start walking all users
2006.03.14 10:29:00 Connect Socket[addr=/10.23.80.143,port=45351,localport=5222] 2006.03.14 10:29:00 SASL calling AuthFactory authenticate
2006.03.14 10:29:00 AuthFactory 1 calling authenticate
2006.03.14 10:29:00 LdapAuthProvider getting userDN null
2006.03.14 10:29:00 Trying now, to find a user’'s DN based on their username. sAMAccountName: jschaube, Base DN: OU=OU_mycoUsers;DC=corp;DC=myco;DC=com…2006.03.14 10:29:00 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:00 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:00 … context created successfully, returning.
2006.03.14 10:29:00 Starting LDAP search…
2006.03.14 10:29:01 … search finished 2006.03.14 10:29:01 LdapAuthProvider authenticating userDN CN=Schaubert, Joel,OU=OU_2014ACE,OU=OU_0102Technology,OU=OU_0001myco
2006.03.14 10:29:01 In LdapManager.checkAuthentication(userDN, password), userDN is: CN=Schaubert, Joel,OU=OU_2014ACE,OU=OU_0102Technology,OU=OU_0001myco…
2006.03.14 10:29:01 Created context values, attempting to create context…
2006.03.14 10:29:01 … context created successfully, returning.
2006.03.14 10:29:01 LdapAuthProvider DONE authenticating userDN CN=Schaubert, Joel,OU=OU_2014ACE,OU=OU_0102Technology,OU=OU_0001myco
/code
Ok, now we have my user authenticated. This is where it gets weird. That DONE message above is one I added at the end of the LdapAuthProvider.authenticate() routine. So how/why would there still be calls to the routines in LdapManager running around and doing more work?
2006.03.14 10:29:01 Created context values, attempting to create context…
2006.03.14 10:29:01 … context created successfully, returning.
2006.03.14 10:29:01 LdapAuthProvider DONE authenticating userDN CN=Schaubert, Joel,OU=OU_2014ACE,OU=OU_0102Technology,OU=OU_0001ETradeGroup
2006.03.14 10:29:01 Trying now, to find a user’'s DN based on their username. sAMAccountName: jschaube, Base DN: OU=OU_myco;DC=corp;DC=myco;DC=com…
2006.03.14 10:29:01 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:01 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:01 … context created successfully, returning.
2006.03.14 10:29:01 Starting LDAP search…
2006.03.14 10:29:01 … search finished
2006.03.14 10:29:01 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:01 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:01 … context created successfully, returning.
2006.03.14 10:29:01 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:01 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:01 … context created successfully, returning.
/code
Now a 2-3 second pause before the logs start cranking out stuff again, then they never stop and wildfire cannot be shutdown
2006.03.14 10:29:07 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:07 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:07 … context created successfully, returning.
2006.03.14 10:29:07 Trying now, to find a user’'s DN based on their username. sAMAccountName: smountie, Base DN: OU=OU_myco;DC=corp;DC=myco;DC=com…
2006.03.14 10:29:07 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:07 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:07 … context created successfully, returning.
2006.03.14 10:29:07 Starting LDAP search…
2006.03.14 10:29:07 … search finished
2006.03.14 10:29:07 Creating a DirContext in LdapManager.getContext()…
2006.03.14 10:29:07 Created hashtable with context values, attempting to create context…
2006.03.14 10:29:07 … context created successfully, returning.
2006.03.14 10:29:08 Trying now, to find a user’'s DN based on their username. sAMAccountName: chenders, Base DN: OU=OU_myco;DC=corp;DC=myco;DC=com…
/code
So I just show enough here to show the loop that it’'s in, it repeats with a different user name each time until I use kill -9 to kill all the wildfire processes.
Anyone with any experience in the LDAP code of wildfire, I would be glad to have even speculation on how so many calls get turned loose as I could add more logging based on any decent theories.
thanks
Joel Schaubert