In the last two articles I was working through OSP log from an issue I had. Much of it worked properly and is useful to review to see what a properly working OSP session should look like. Reading through the logs offers some interesting insights into the product you would not see elsewhere so I find it entertaining and educational to work through. I hope you find this helpful, and if nothing else, when you run into an issue, and have a class name throwing an error, maybe Google will find this article and show you what it SHOULD look like to give you a hint as to what might be broken.

When last we left our intrepid spelunkers through the depths of the OSP log with the level set to ALL (Heavens! The horror!) OSP had just decided that we were not logged in, and was about to try to log us in via LDAP to eDirectory, our user store.

[OIDP] 2016-08-12T13:02:49.713-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIConnectionPool.retireOldConnections() [830] thread=http-bio-8443-exec-4
Message: Closing LDAP connection due to connection timeout! Interval: 60641147, Timeout: 10000, Connection: Id: c5c212b4-ea83-4348-986a-d5451b7a99a5, host: ldaps://myServer.acme.com

What is interesting is that OSP decides my server's LDAP connection has timed out and will refresh it. This is a bit odd, since I had just restarted OSP, so I guess it had not yet tried an LDAP connection and possibly it tried to persist the connection through a Tomcat restart? Not sure, but it knows how to fix it. In fact, they might use absence of a connection (due to restart, server down, or timeout) as all the same thing and fix it the same way, try again. That might just be a simpler code path to have followed, so I guess that makes sense.

[OIDP] 2016-08-12T13:02:49.716-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIConnection.<init>() [219] thread=http-bio-8443-exec-4
Message: 
   Connection: 340d9ffb-623d-4722-a39d-27e21f77efb3, Environment Parameters for InitialDirContext() method call:
   Key: java.naming.factory.initial, Value: com.sun.jndi.ldap.LdapCtxFactory
   Key: java.naming.provider.url, Value: ldaps://myServer.acme.com:636
   Key: com.sun.jndi.ldap.connect.timeout, Value: 0
   Key: java.naming.security.principal, Value: cn=admin,o=acme
   Key: java.naming.security.authentication, Value: simple
   Key: java.naming.security.credentials, Value: *****
   Key: java.naming.security.protocol, Value: ssl
   Key: java.naming.ldap.factory.socket, Value: com.novell.osp.util.net.client.OSP_SSLSocketFactory

This trace output is nice to see, since it shows you a number of the Java parameters it sets for the bind. Which SSL class it is calling, an OSP specific one, not the base standard class. This probably means they just wrapped it with some extra error checking and handling. But otherwise this is a standard JNDI connection which means you can try to troubleshoot it as a JNDI connection when an issue comes up. This also means there might be a way to pass in parameters to Java when you start Tomcat that might help if you have odd authentication issues, like needing a specific setting for certificates or timeouts. I am not sure, but it seems likely that it might be possible. I suspect the issue would be so long as OSP or any other WAR file does not already use that value and internally override its value.

[OIDP] 2016-08-12T13:02:49.716-0400
Level: ALL
Code: com.novell.identity.common.ldap.jndi.JNDIConnection.<init>() [249] thread=http-bio-8443-exec-4
Message: 
   JNDI Debug Event:
   Create Connection: cId: 340d9ffb-623d-4722-a39d-27e21f77efb3,usId: idm_idv, rId: 5533b844-40b2-4a1e-9b1b-8988e3d9b4d4, U: cn=admin,o=acme, T: ADMIN_CONNECTION

One thing to note here is that in the eDirectory world, in qualified slash notation, you use fully qualified descriptions, so it might be CN=uaadmin\OU=admins\OU=system\O=acme but it turns out there is actually one more level, T= for the tree name. Now LDAP per se does not quite have that same construct. But you can see here that the T: value is being used to note that this is an Admin connection. That is, almost tagging the connection with an identifiable name, by using the tree indicator. Clever. Later on we will see that when the Admin connection is used to find the user, get the DN, and finally bind as that user, the T: value is USER_CONNECTION. I missed this on my first pass through and this is kind of a clever way to handle and track this issue.

[OIDP] 2016-08-12T13:02:49.807-0400
Level: TRACE
Code: comw.novell.identity.common.ldap.jndi.JNDIConnection.setContextEnvironmentProperties() [1875] thread=http-bio-8443-exec-4
Message: Added property to DirContext Environment: Property Name: java.naming.ldap.attributes.binary, Value: GUID nDSPKITrustedRootCertificate

So the InitialDirContext() call above showed us the standard JNDI properties set, but here we see one more that defines another property that shows two attributes as binary.

[OIDP] 2016-08-12T13:02:49.808-0400
Level: DEBUG
Code: com.novell.oidp.source.ldap.LDAPSource.accept() [1592] thread=http-bio-8443-exec-4
Message: CreateConnection

[OIDP] 2016-08-12T13:02:49.851-0400
Level: ALL
Code: com.novell.identity.common.ldap.jndi.JNDIConnectionPool.getAdminConnection() [533] thread=http-bio-8443-exec-4
Message: 
   JNDI Debug Event:
   Leaving: CreatedNewAdminConn:340d9ffb-623d-4722-a39d-27e21f77efb3, Interval:133

[OIDP] 2016-08-12T13:02:49.852-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIStore.doAdminSearch() [1118] thread=http-bio-8443-exec-4
Message: Try connection: ldaps://myServer.acme.com

[OIDP] 2016-08-12T13:02:49.853-0400
Level: ALL
Code: com.novell.identity.common.ldap.jndi.JNDIConnection.doSearch() [1708] thread=http-bio-8443-exec-4
Message: 
   JNDI Debug Event:
   Search: cId: 340d9ffb-623d-4722-a39d-27e21f77efb3, DN: o=acme, F: (&(objectClass=User)(|(cn=uaadmin)(mail=uaadmin))), A:GUID, cn, nrfMemberOf, srvprvPreferredLocale, mail, mail, initials, givenName, mobile, {$dn}, cn, sn, {$dn}, objectClass, loginIntruderAttempts, S: 2

Here you see the JNDI class log out the call it is making as opposed to before it was a class calling JNDI that was logging it. Same basic information, slightly different format. F instead of filter, S instead of Scope, A instead of attribute list, DN instead of Base DN, but otherwise the same thing. So this is the point where we actually do the connections.

As you can imagine if there were a bind issue or something else (Bad certificate? Bad password, bad Bind DN, etc) this is where it would start showing up in the trace.

[OIDP] 2016-08-12T13:02:49.857-0400
Level: DEBUG
Code: com.novell.oidp.source.ldap.LDAPSource.accept() [1592] thread=http-bio-8443-exec-4
Message: SearchObject

[OIDP] 2016-08-12T13:02:49.858-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIStore.doAdminSearch() [1138] thread=http-bio-8443-exec-4
Message: Found 1 results!

It connected, no error, it found a result. Personally I would like it to show the DN of the object (or objects when more than 1) that it found in this level of trace. This would be helpful in diagnosing issues of duplicate users or people with the same email address or the like.

I decided to snip out what seems like a complete repeat of the entire LDAP process but there is a difference between the two. In configupdate.sh you define the Users container, which in my case is o=acme since I was not sure where I was going to end placing my users. The second container you define is for Admins. In my example it is ou=admins, ou=system, o=acme and this second time through the search process was to see if my user is an Admin, because of the defined container. I suspect the Auto Admin Role code is looking at that sort of thing as part of this process.

[OIDP] 2016-08-12T13:02:49.867-0400
Level: TRACE
Code: com.novell.oidp.source.ldap.LDAPAuthenticationSource.searchUser() [1178] thread=http-bio-8443-exec-4
Message: After searching context "ou=admins,ou=system,o=acme" the number of hits is 2

Now even though it found my user twice, since my search bases overlapped and were not distinct trees, it still managed to figure out I was just one user, which is clever. I have seen systems that cannot do that and it is painful. Thus two hits is not a problem. But you can see that like NAM it can chain LDAP searches in the OSP product if needed, but the IDM version is just cut down a bit.

[OIDP] 2016-08-12T13:02:49.867-0400
Level: TRACE
Code: com.novell.oidp.attributes.cache.CacheAttributeSource.addAttributes() [86] thread=http-bio-8443-exec-4
Message: 
   Adding cached attributes:
      nrfMemberOf
      srvprvPreferredLocale
      mail
      saml2-mapping-attr
      initials
      givenName
      mobile
      dn
      userCN
      Surname
      userDN
      {$authsource.ObjectNameAttr}

Now it caches the data it just recovered, which is nice to boost performance and stop hammering the LDAP server all day long.

[OIDP] 2016-08-12T13:02:49.868-0400
Level: TRACE
Code: com.novell.oidp.source.ldap.LDAPAuthenticationSource.searchUser() [1232] thread=http-bio-8443-exec-4
Message: LDAP search objects found: 1

[OIDP] 2016-08-12T13:02:49.868-0400
Level: TRACE
Code: com.novell.oidp.authentication.classes.AuthenticationClass.findPrincipals() [483] thread=http-bio-8443-exec-4
Message: Found 1 principal(s) in Authentication Source IDM eDir(id=bisadus)

[OIDP] 2016-08-12T13:02:49.868-0400
Level: TRACE
Code: com.novell.oidp.authentication.classes.AuthenticationClass.findPrincipals() [495] thread=http-bio-8443-exec-4
Message: Found 1 principals.

Here is where you see that even though earlier it found two objects by searching, it knows to consider them as one, and use the one principal to login. The search until now was trying to get from a CN or email address to an LDAP DN, like most LDAP implementations, first the service account is used to locate the user object, then you bind as that user.

[OIDP] 2016-08-12T13:02:49.869-0400
Level: INFO
Code: com.novell.oidp.authentication.classes.PasswordAuthenticationClass.authenticatePrincipal() [222] thread=http-bio-8443-exec-4
Message: Attempting to authenticate user cn=uaadmin,ou=admins,ou=system,o=acme with provided credentials.

[OIDP] 2016-08-12T13:02:49.869-0400
Level: ALL
Code: com.novell.identity.common.ldap.jndi.JNDIStore.authenticateUser() [1327] thread=http-bio-8443-exec-4
Message: 
   JNDI Debug Event:
   AuthenticateUser: User Store: IDM eDir, User DN: cn=uaadmin,ou=admins,ou=system,o=acme

Now that it has found your DN it uses it to bind with your password to the LDAP directory to know if your credentails are valid. Interstingly it binds and authenticates, and does not do a compare password, which LDAP supports. One benefit to this is that a disabled (Login Disabled = true) user, an Intruder Locked (Locked By Intruder = true) user, an expired user (Login Expiration Time is in the past), an expired password (Password Expiration Time in the past) will all fail to bind and often with a specific error, whereas a compare password would succeed in all those cases, since all it cares about is, does the password actually match the value being tested with. Though I am not 100% sure how eDirectory handles the LDAP Compare Password call in one of those cases where the login should fail.

If this were using NCP there are functions to use to test effective rights to objects and attributes that could be helpful in managing Authorization (AuthZ). Right now we are focused on Authentication (AuthN) but AuthZ is important as well.

So now it tries to log in as my user:

[OIDP] 2016-08-12T13:02:49.871-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIConnection.<init>() [219] thread=http-bio-8443-exec-4
Message: 
   Connection: 71ffe6a8-d662-4077-8d68-0fc7f83dc26b, Environment Parameters for InitialDirContext() method call:
   Key: java.naming.factory.initial, Value: com.sun.jndi.ldap.LdapCtxFactory
   Key: java.naming.provider.url, Value: ldaps://myServer.acme.com:636
   Key: com.sun.jndi.ldap.connect.timeout, Value: 0
   Key: java.naming.security.principal, Value: cn=uaadmin,ou=admins,ou=system,o=acme
   Key: java.naming.security.authentication, Value: simple
   Key: java.naming.security.credentials, Value: *****
   Key: java.naming.security.protocol, Value: ssl
   Key: java.naming.ldap.factory.socket, Value: com.novell.osp.util.net.client.OSP_SSLSocketFactory

[OIDP] 2016-08-12T13:02:49.872-0400
Level: ALL
Code: com.novell.identity.common.ldap.jndi.JNDIConnection.<init>() [249] thread=http-bio-8443-exec-4
Message: 
   JNDI Debug Event:
   Create Connection: cId: 71ffe6a8-d662-4077-8d68-0fc7f83dc26b,usId: idm_idv, rId: 5533b844-40b2-4a1e-9b1b-8988e3d9b4d4, U: cn=uaadmin,ou=admins,ou=system,o=acme, T: USER_CONNECTION

[OIDP] 2016-08-12T13:02:49.925-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.MethodProfile.authenticateMethod() [682] thread=http-bio-8443-exec-4
Message: Authentication Method Name/Password Method succeeded

Looks like it succeeded. You can see the difference in the bind event, by the T= value. It says USER_CONNECTION here as opposed to T=ADMIN_CONNECTION when finding the user's DN by searching for the CN or email address.

[OIDP] 2016-08-12T13:02:49.926-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.checkAuthenticated() [2489] thread=http-bio-8443-exec-4
Message: 
   Session Id: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6
   Session has zero consumed authentications! Not Authenticated!
   Authenticated: false

These trace messages, above are shown a lot, and confuse me. On the one hand we just saw the message, "Authentication Method Name/Password Method succeeded" and yet the next message is that it is not authenticated. Now it may be, that the LDAP authentication succeeded, but this has yet to be registered with OSP as a 'registered' authentication session to cache. Regardless, this message shows up far more often than I would like to see.

So now it looks like it is using the next contract for logins in order, as we have seen, OSP can chain authentication methods, and we know we have three in the line at least. SSPR must register into this chain somehow, since you can run IDM Apps without SSPR. This may just be a hard coded configuration choice in the OSP bundled with IDM. Looks like it makes a REST call to SSPR.

[OIDP] 2016-08-12T13:02:49.926-0400
Level: DEBUG
Code: com.novell.oidp.profile.authentication.MethodProfile.getNextExecutable() [615] thread=http-bio-8443-exec-4
Message: 
   Get next contract executable:
      Executables count: 3
      Counter: 1
      Executable: SSPR Check Method(id=sspr-checks-method)
         Type: non-user
         Session authenticated: false
         Valid on session: false
         Method selected for execution.

I am sure the counter started at 0, since the username password check was the first contract executable we ran. The type of non-user probably refers to the various other factors possible in an authentication system. I would imagine a two factor system like an RSA token, Vasco token, Smart Card login or the like would count as non-user as well.

[OIDP] 2016-08-12T13:02:49.926-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.MethodProfile.authenticateMethod() [658] thread=http-bio-8443-exec-4
Message: Authentication Method  executing: SSPR Check Method

[OSP] 2016-08-12T13:02:49.927-0400
Level: TRACE
Code: com.novell.osp.util.URLUtil.connectToURL() [840] thread=http-bio-8443-exec-4
Message: Attempting to connect to URL: https://myserver.acme.com:8443/sspr/public/rest/status via GET (len:0)

Here we see it making a connection to a URL that has rest in the name, and is part of SSPR. It is worth trying that URL on your own system to see what is offered. SSPR is nice in that when you use a browser to look at a REST endpoint URL the parameters to send in, and what is returned is shown. Almost like they want to make it easy to use. How novel. This should be passing in the DN of the user trying to login, and SSPR should be checking their status for various lock parameters and returning the state of the user. If they are in one of the various problem states, then OSP could use that information to force them to fix it, before being allowed to login.

[OSP] 2016-08-12T13:02:50.251-0400
Level: TRACE
Code: com.novell.osp.util.URLUtil.connectToURL() [895] thread=http-bio-8443-exec-4
Message: Response code 200 from connection

Hmm, the URL is /status, when I try that URL via a browser (not a REST tool) I get errors due to missing headers, but it takes me to the URL:
https://myserver.acme.com:8443/sspr/public/reference/rest.jsp?forwardedFromRestServer=true

The Status page of the REST docs suggest that it would read a Users status. Getting back the password policy, the password last changed, expired, etc stuff.

[OIDP] 2016-08-11T20:07:34.818-0400
Level: ERROR
Code: com.novell.oidp.authentication.classes.sspr.SSPRChecksClass.needToCheck() [174] thread=localhost-startStop-1
Message: 
   Level: ERROR
   Code: com.novell.oidp.authentication.classes.sspr.SSPRChecksClass.needToCheck() [172]
   Thread: http-bio-8443-exec-4
   Correlation Id: 89457de9-2a1d-4f72-8a81-9268e969cff9
   Text: Get Status request to SSPR returned an error:
   Error code: 5027
   Error Message: You do not have permission to perform the requested action.
   Error Detail:

However, this check did not work for me, and SSPR is saying my user doing the REST GET request does not have permissions to read this user... Hmmm... This would be interesting to figure out what is going wrong here. I wonder, if the 5027 error, which is what I was getting while this whole issue was going on, is the key here. Perhaps, the REST call is made, as the user itself, since OSP has the password handy at this moment, and since my overall issue is failing authentication, this authentication also fails? Of course, there is a bit of recusion, since I have yet to see my authentication fail, that comes later, and this would imply an earlier authentication attempt whose failure, is itself not logged.

But it seems like it still considers me authenticated? This is probably because you cannot assume SSPR is deployed with IDM, and just when SSPR is configured, and responds to the REST call, and sends back status information aout the user can you then use it to deny access. Otherwise, without SSPR you might always deny access.

Now I wonder if this changes if you use the Legacy Password change provider (The User Application integrated one). It makes a bit of sense, since in the past User Application could tell that your user needed to set Challenge Response questions, change an expired password and so on. It seems like with the change to OSP as the login front end instead of User Application that the task of handling those cases was passed to OSP, which in turn passes them to SSPR. In troubleshooting this, I did switch back to the Legacy Password approach, but I do not have any logs from that time where I could check and see if this was really the case.

[OIDP] 2016-08-12T13:02:50.255-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.MethodProfile.authenticateMethod() [661] thread=http-bio-8443-exec-4
Message: Authenticated authentication class: com.novell.oidp.authentication.classes.sspr.SSPRChecksClass, Status: AUTHENTICATED

As noted above, even though the SSPR check failed it calls me authenticated for it.

That seems like a good stopping point for this article. Lots more trace to go, I know this seems boring at time, but my hope is that someone will be stuck in a similar bind and not understand what they are seeing and that this series will help them figure it out.