Reading through the OSP log file – Part 2

0 Likes
In the first part of this series I noted I would walk through the procedure a user login to OSP for IDMProv might take, and show a specific error I ran into.

In the previous article I showed it rendering the login page, seeing the user is not authenticated, and then deciding to redirect to the login page. The redirect to the login session, considers the session information. Since I have not yet logged in, it creates a session for me to tie the authentication information against.

[OIDP] 2016-08-12T13:02:49.704-0400
Level: DEBUG
Code: com.novell.oidp.cluster.ClusterCookieContext.resolveSession() [154] thread=http-bio-8443-exec-4
Message:
Session cached:
Class: NIDPSession
Id: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6-CX
SubId: 0
Private Id: D1K6X)Me2Qw9Fn-E0q4FM}8k]
Type: PERSISTANT
Created Time: 08-12 13:02:19 0488 (1471021339488) (Elapsed: 30216)
Last Used Time: 08-12 13:02:19 0501 (1471021339501) (Elapsed: 30203)
Main JSP: main
Do Not Set Activity: false
Session Data Key: 1
Class: NIDPSessionData
Id: 1
Create Time: 08-12 13:02:19 0490 (1471021339490)) (Elapsed: 30214)
Target stack:
0: https://myserver.acme.com:8443/osp/a/idm/auth/oauth2/authcodecontinue?privateId=f8847a8a493e6a844d00&client_id=rbpm&irdpkg=1471021339493-1870600049
Class: ContractExecutionProfile
Service: idm(id=auth)
Request: /osp/a/idm/auth/app/login
Reset: false
First Time: true
Passive: false
Force: false
Counter: 0
Return URL: https://myserver.acme.com:8443/osp/a/idm/auth/app/login?acAuthCardId=np-contract-{$default-card}&sid=1
Top: false
Authenticated: false
Credential Update: false
Class: AuthenticationContract
Id: np-contract
Name: User Name/Password Login
URI: idm:login:user:np
Trust Level: 0
Timeout: 0
Check Trust Level: false
Show Pwd Expired UI: true
Remote: false
Default: true
Executable: Name/Password Method(id=np-method)
Executable: SSPR Check Method(id=sspr-checks-method)
Executable: (Auto) IDM Admin Role Mapping Method(id={$auto}-admin-role-mapping-method)
Authentication Card: User Name/Password Login-{$default-card}(id=np-contract-{$default-card})
Logout Flag: 0
Show Logout: false



As noted earlier the time stamps used are JTIME, milliseconds since 1970, stored in a 64 bit integer. You can see this when it shows the age of the session:

Created Time: 08-12 13:02:19 0488 (1471021339488) (Elapsed: 30216)
Last Used Time: 08-12 13:02:19 0501 (1471021339501) (Elapsed: 30203)


The elapsed is in milliseconds, so that is 30 seconds, which is probably how long it took me between rendering the login page and entering my credentials.

Class: AuthenticationContract
Id: np-contract
Name: User Name/Password Login
URI: idm:login:user:np
Trust Level: 0
Timeout: 0
Check Trust Level: false
Show Pwd Expired UI: true
Remote: false
Default: true
Executable: Name/Password Method(id=np-method)
Executable: SSPR Check Method(id=sspr-checks-method)
Executable: (Auto) IDM Admin Role Mapping Method(id={$auto}-admin-role-mapping-method)
Authentication Card: User Name/Password Login-{$default-card}(id=np-contract-{$default-card})


You can see the contract it uses for this session, which is np-contract (as opposed to SAML or Kerberos the other two supported types by the OSP provided with IDM).

But also can see that it will execute a series of login events that are not necessarily chained, but are sequenced.

First up it will use the np-method, the Name/Password method, and then an SSPR Check Method, finally an IDM Admin Role Mapping method.

The SSPR Check makes a REST call for the user to SSPR to get the status, and see if the password is expired, needs to be changed, locked, or even strong enough. I was trying to see if an OSP install without SSPR still tries this, and I think it may so if you have one of those, take a look in your logs and leave a comment and let me know. You will see the REST call later in trace.

Then it does an IDM Admin Role Mapping, which is to say, is this an Admin user, or just a typical log in user, which I am not sure of the use case for quite yet. OSP seems to have Roles, in the same way NAM has Roles, sort of permissions assigned to a Dynamic Group equivalent. Now that we have seen what OSP is planning on doing, we will now see it actually take all these steps.

[OIDP] 2016-08-12T13:02:49.704-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




First up it notices that my session is not Authenticated. I question the validity of this message, since even after authenticating I still occasionally see this message, so I am not sure this means what I think it means! Inconceivable! (Something about a land war in Asia, right?)


[OIDP] 2016-08-12T13:02:49.704-0400
Level: TRACE
Code: com.novell.oidp.servlets.handler.CommonHandler.processRequest() [401] thread=http-bio-8443-exec-4
Message: Handling request command: Login



Decides I need to login, which likely implies it could do other things in OSP I suppose.


[OIDP] 2016-08-12T13:02:49.707-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



Oh look, I am not authenticated (again, no really, they mean it this time). I am uncertain why it keeps checking like this. But I suspect it is an error case or timeout handler, where you keep checking and if so, fork out, authenticate, then come back. Thus if you hit a timeout and it checked it would re authenticate then continue where you left off.


[OIDP] 2016-08-12T13:02:49.707-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: 0
Executable: Name/Password Method(id=np-method)
Type: user-authenticate
Session authenticated: false
Valid on session: false
Method selected for execution.



As we saw at the very beginning we are going to start with Name Password as it executes. It is also nice that it has an Executables count value (3) and a Counter showing which one is being processed. I did not notice that before. It is nice to take a slow stroll through the logs and sniff the daisies. (Don't bees love them, and they sting!)

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

[OIDP] 2016-08-12T13:02:49.708-0400
Level: TRACE
Code: com.novell.oidp.authentication.classes.system.PasswordClassBase.handlePostedData() [729] thread=http-bio-8443-exec-4
Message:
User Id: uaadmin
Password: ********
Secondary resolution: false



Now I had entered my credentials, which was POST'ed to the web page, so the credentials are presented to OSP already, and as you can see the function name is handlePostedData, and it uses my uaadmin username, and nicely masks out the password. Bet you there is some setting that unmasks that, since being able to validate the password is getting through (Say a character in the password is breaking a component) but I imagine they will not want anyone to know that setting if it does exist.

The line secondary resolution set to fault is interesting, I initially thought this was referring to something like two factor authentication where you might need a second thing before logging in succeeds, but that would probably be handled with another executable being chained into the list we have. Instead I think this allows for a different attribute or piece of data to identify the user in the user store. By default, the value you enter into OSP is looked against cn and mail attributes. Perhaps this is a place where OSP in the full version would let you login by say telephone number, or employee ID. (Which by the way, if you needed it you could likely get to work in this version by having an eDirectory LDAP server as your user store, which aliases the workforceID attribute to cn, and then it would probably do the trick.

When it comes to SAML this is a bit of a more common thing. You login to an IDP (Identity Provider) that is central to your enterprise, but you may have a different username there, than in a connected system. Thus the SAML assertion would return with the name of the attribute it asserts identifies you and the value of that attribute so the system receiving the SAML assertion can find the user the IDP is telling it to trust.

[OIDP] 2016-08-12T13:02:49.708-0400
Level: TRACE
Code: com.novell.oidp.authentication.classes.system.PasswordClassBase.handlePostedData() [793] thread=http-bio-8443-exec-4
Message: Attempting to authenticate with userid: uaadmin


This is seemingly a smidgen redundant, but not so much if you consider the Secondary resolution possibility. It might need to look for an object with a different identifying attribute.


[OIDP] 2016-08-12T13:02:49.708-0400
Level: TRACE
Code: com.novell.oidp.authentication.classes.AuthenticationClass.logPrincipalMsg() [523] thread=http-bio-8443-exec-4
Message: Will look for principal in 1 authentication sources. Find all principals: true.

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


As you will see throughout OSP the configuration for eDirectory, that the IDM version uses is known as 'bisadus'. I have to admit, it is killing me trying to figure out what that stands for. I do not know why, but acronyms are like a puzzle to me. I want to know what it stands for so badly. If you happen to know, please be sure to leave comment on this article.

But the key takeaway is that OSP is about to try to login to eDirectory with the user uaadmin.


[OIDP] 2016-08-12T13:02:49.708-0400
Level: TRACE
Code: com.novell.oidp.source.ldap.LDAPAuthenticationSource.searchUser() [1082] thread=http-bio-8443-exec-4
Message: Searching for principal(s) on Data Store idm_idv using filter: (&(objectClass=User)(|(cn=uaadmin)(mail=uaadmin))). Find all principals: true



The setting Find All Principals set to true is interesting, implying it is a settable value, and that there might be cases where you do want to find all principals? I guess the first would suffice in that case?

[OIDP] 2016-08-12T13:02:49.709-0400
Level: TRACE
Code: com.novell.oidp.source.ldap.LDAPAuthenticationSource.searchUser() [1170] thread=http-bio-8443-exec-4
Message: Performing LDAP search (&(objectClass=User)(|(cn=uaadmin)(mail=uaadmin))) in context o=acme

[OIDP] 2016-08-12T13:02:49.709-0400
Level: TRACE
Code: com.novell.identity.common.ldap.jndi.JNDIStore.doAdminSearch() [1112] thread=http-bio-8443-exec-4
Message: Base context: o=acme, Filter: (&(objectClass=User)(|(cn=uaadmin)(mail=uaadmin))), Scope: 2, Attributes: GUID, cn, nrfMemberOf, srvprvPreferredLocale, mail, mail, initials, givenName, mobile, {$dn}, cn, sn, {$dn}, objectClass, loginIntruderAttempts, Request Controls: 0


Now this output is of excellent value! It tells us so many interesting things. First of all, this is how I knew that when you enter a login username to OSP on the login page, it looks for cn and mail. You can see it in the LDAP filter.

The filter is shown as:
(&(objectClass=User)(|(cn=uaadmin)(mail=uaadmin)))


By now you must know how to read an LDAP filter, but in case you do not, the & sign means a logical AND, so the user must be of class User, and then an OR indicated by the pipe (|) sign of either cn=uaadmin or mail=uaadmin.

This also tells me that if you had user objects that were a completely custom object class, say you made an acmeUser structural class and did all your work with those kinds of objects, OSP just is not going to let you login. This is a bigger deal in Sun Directory Server or Open LDAP style implementations. This might be an issue for the full OSP product but not for this stripped down version since it is only allowed to connect to eDirectory as its LDAP source.

The last line is nice, the doAdminSearch call, since it traces out more LDAP information. The base context to search downwards from (o=acme). It would be nice to see if blank, were defined as the RootDSE and down, in other words the top of the tree and down. This would be helpful for cases you have many top level Organization objects as some trees have been designed historically. LDAP is usually not kind to that tree design, and the traditional solution is blank, to imply RootDSE and down. However not every code path supports that, so this is where IDM is useful to synchronize those users into another tree with a more LDAP friendly structure.

You see the scope, 2, which is usually subtree (Entry is usually 0, and Container is usually 1) and finally the list of attributes it will request back.

Attributes: GUID, cn, nrfMemberOf, srvprvPreferredLocale, mail, mail, initials, givenName, mobile, {$dn}, cn, sn, {$dn}, objectClass, loginIntruderAttempts

It gets the GUID, since people can move around and the best way to handle users moving or groups moving is by tracking their GUID. But it also means recreating a user is hard, since you can make everything the same, but rarely can you write to GUID to set it back properly to match.

nrfMemberOf is an indicator of IDM RBPM Roles the user might have assigned, which would be interesting to know why OSP cares.

srvprvPreferredLocale is a language choice, in case you have selected one in User Application so that if you need multi-language support the page can be rendered in the desired language.

mail is there twice which interesting, not sure why.

initials, givenName, sn, and cn are naming attributes.

mobile and loginIntruderAttempts are probably intended at login to see if you need to be blocked and I guess mobile so you could possibly be sent an SMS by SSPR to do some password operation. However, this is OSP not SSPR, so I am not sure why it is being requested. Likely a hold over from the full up OSP product. As it turns out loginIntruderAttempts is probably a bad choice and instead should be also looking at LockedByIntruder to see if the account is actually locked. However as we will see later the SSPR Check will validate this info for us, if you have SSPR installed.

I do not quite know what the {$dn} variable is for. It might be a variable to replace with the local LDAP directories name for the attribute that returns the DN of the object as an attribute, as opposed to the DN of the object. It would be a different code path to select the objects actual name than selecting an attribute value, so there is value in requesting that attribute.

Consider in the XDS and XPATH case. This would be the difference in using the Operation Attribute (DN) token than the Source DN() token. They both work, but if you have a loop of code over Operation Attributes, then it is easier if DN is just another value being looped over.

For eDirectory that attribute turns out to be standards compliant and is known as 'EntryDN'. Not sure why it is there twice.

The objectClass attribute request is probably just for completeness, and perhaps is being checked to see if an Auxiliary class is needed to add the oidpInstanceData to the object. (It is part of the ndsLoginProperties class so almost certainly is there already since that is the one that adds Universal Password support to User objects.)

This seems like a good place to break and continue in the next article.

Labels:

How To-Best Practice
Comment List
Related
Recommended