If you have been following the evolution of Identity Manager at NetIQ/Micro Focus you will have noticed how logins have changed with the latest versions of IDM 4.02 (Home and Provisioning Dashboard add on) and IDM 4.5 and higher.

Previously the login to User Application was direct, and if you wanted to do Single Sign On, that happened as a component of User Application that knew over the years how to do SAML, Kerberos, and SAP Logon Tickets. Some of those got deprecated in later User Application versions, and doing the SAML approach was a lot of work. (In fact it was just WAY easier to form fill with NAM (NetIQ Access Manager) than to get SAML working).

With the later IDM releases, an new intermediary was added to make this easier. When NetIQ released the xAccess products (Social Access, Mobile Access, and Cloud Access) they needed a lighter weight SSO engine than NAM. After all if you have deployed NAM, you kind of should have 3-6 machines at a minimum to properly deploy it. But the xAccess products were intended to be an appliance, running as a single box. Already they had a hefty load of having the IDM engine, some of the Roles engine, before adding in the entirety of NAM.

Thus they created OSP, (One SSO Provider) which is a stripped down version of NAM, sharing much code, but simplifying a great deal. The biggest simplification was stripping out form fill, identity injection and most things that are not federation based. Then the administrative interface was modified to remove the need for the Admin Consoles.

An even more stripped down version of OSP is now included with IDM. This supports username/password, SAML, and Kerberos authentication modes. Thus OSP is the front end for your logon experience with IDM. This is smart as it moves the code out of being an IDM problem, and not requiring the purchase of NAM, but using an internally supported product. Thus as xAccess gets better, we get a better OSP out of it. Things we need fixed for IDM feed back into the xAccess line as well.

Also since OSP is designed to work with MANY federation partners, it does actually work with those federation partners and is tested with them. Just in the context of its use in IDM land it is not specifically tested, but it means we can almost certainly get it to work. I showed this with an example of getting it working to SAML federate with Shibboleth v2 in this article:
Configuring IDM 4.5s OSP to talk to a Shibboleth IDP

I showed some troubleshooting examples in a bunch of articles afterwards that you may find helpful as you work through any issues with OSP.

• Troubleshooting OSP in IDM 4.5 – Part 1

• Troubleshooting OSP in IDM 4.5 – Part 2

• Troubleshooting OSP and SSPR – Part 3

• Troubleshooting SSO in User Application 4.02

One of the confusing things, that should really be better explained is the cascading trusts involved. If you have SAML configured to an IDP (say NAM or Shibboleth) then the following could be true:

User logs in to Shibboleth IDP (Identity Provider), which might be pointed back at your main IDV LDAP or some other system. OSP trusts the Shibboleth system (since you exchanged metadata which includes a certificate to sign everything with). Now User App asks OSP for an OAuth ticket, and since User App trusts OSP it trusts the OAuth ticket that identifies your user. Then User App does a SAML federated authentication to eDirectory as your user.

That is a lot of federation going on there in the background. It is pretty amazing how well it works in the field. Do be aware that each step of the way has a timeout value for it's session and you might run into an issue if they do not match and you hit the first earliest timeout it may not be recoverable.

Having said all that, I recently ran into an issue with OSP at a client. I had a working IDM 4.5.2 system and then suddenly I could no longer log in to the Identity Apps.

I would log in and I would get redirected to this error URL, with no rendered page, just blank.

https://myid.acem.com:8443/IDMProv/oauth?error=access_denied&state=f56cc008-b92a-44dc-98d7-1287c936532e

When I looked in catalina.out (I run on Tomcat. This would be the server.log on JBoss and the SystemOut.log on Websphere) I see:

2016-08-11 11:31:03,127 [http-bio-8443-exec-2] ERROR com.netiq.idm.auth.oauth.OAuthServlet- [RBPM] OAuth server login failed. Error code returned was
access_denied.

Well gee, Access Denied, no kidding, I figured that out from the URL. Why? Is my admin account intruder locked? Password expired? Account Expired? Am I failing login? I dunno. The log is not telling me why or what. I should note at the outset, that there is a hint here, I see now, having gone through troubleshooting that had I seen earlier, would have let me jump to the reasonable conclusion earlier. However the process is useful, so I think will proceed regardless. The hint is that the module that is throwing the error is: com.netiq.idm.auth.oauth.OAuthServlet

Note that this is an OAuth error. Not an OSP error, not a login error. Rather it hints that my login to LDAP worked properly but when I tried to get an OAuth ticket it denied me. This probably means something past the login event. As I started writing this, I do not actually know the solution to the issue (i have an SR open and in progress), but I thought going through the log would perhaps give me a hint to track down, or help someone else who has an analagous issue (but perhaps not the identical one).

You would think, based on User Appplication experience that you should just go to the Logging page in the Administration tab, and up the trace level for the com.netiq.idm.auth.oauth.OAuthServlet class. Except that this is not part of User Application, this is part of OSP that is throwing the error into Tomcat's shared output log file.

So where do you trace OSP stuff? Where is the GUI to go enable logging? Where is the config file you edit to specify which class to log?

Well it turns out, OSP logging is not as granular as User Application logging, and it is configured in the setenv.sh file in the Tomcat bin directory. On Linux that full path would be:
/opt/netiq/idm/apps/tomcat/bin/setenv.sh

In that file, near the end you will see:

JAVA_OPTS="-Xms1024m -Xmx1024m -XX:MaxPermSize=512m "
export JAVA_OPTS
export CATALINA_OPTS="-Dcom.netiq.ism.config=/opt/netiq/idm/apps/tomcat/conf/ism-configuration.properties -Dcom.netiq.osp.ext-context-file=/opt/netiq/idm/apps/osp_sspr/osp/osp-conf.jar -Dcom.netiq.idm.osp.logging.level=INFO -Dcom.netiq.idm.osp.client.host=myserver.acme.com -Dcom.netiq.idm.osp.tenant.logging.naudit.enabled=false -Dcom.netiq.idm.osp.logging.file.dir=${CATALINA_BASE}/logs -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Dsun.jnu.encoding=UTF-8 -Djavax.xml.transform.TransformerFactory=org.apache.xalan.processor.TransformerFactoryImpl -Didmuserapp.logging.config.dir=/opt/netiq/idm/apps/tomcat/conf/ -Dextend.local.config.dir=/opt/netiq/idm/apps/tomcat/conf/"

In the CATALINA_OPTS section there is a setting:
-Dcom.netiq.idm.osp.logging.level=ALL

This is the one that controls how much OSP logs. If you look at the Apache definition of trace levels for log4j, (https://logging.apache.org/log4j/2.x/manual/customloglevels.html) you will see that the order is basically:

OFF
FATAL
ERROR
WARN
INFO
DEBUG
TRACE
ALL

OSP ships with it set to INFO, which is pretty high and is sometimes useful. ALL is such crazy logging it is unbelievable. But at times it is helpful. It will enumerate every single certificate in the known keystores it uses (and the JVM comes with 90 or more certificates) which seems like a waste of space, until you are troubleshooting whether it was able to find the certificate you included or not. In which case, it is very helpful indeed.

Once you do that, and restart the Identity apps (by restarting Tomcat with the script idmapps_tomcat_init in /etc/init.d) the osp.log.2016-08-15.log (where the current date will be in todays log file). What I did was rename that days log, (as well as catalina.out) and restarted the IDM Apps, which gave me a clean pair of log files and I copied them off to the side.

Then I went to the https://myserver.acme.com:8443/IDMProv and logged in. Then I got the access denied error, and copied that file to the side.

I looked at the first OSP log, found the end timestamp, then I looked at the second OSP log and found where my login event began, after everything started up.

The first thing I saw was rendering the OSP Login page did not log into this file, which makes sense, that is more of a Tomcat thing, serving up a simple web page. It was only when I actually entered a username and password that events got logged, because at that point I did an HTTP POST by clicking on Login.

[OSP] 2016-08-12T13:02:49.647-0400
Level: DEBUG
Code: com.novell.osp.OSPRequestContext.logRequest() [1737] thread=http-bio-8443-exec-4
Message: 
   HttpServletRequest (Number 5)
      Method: POST
      Request URL: /osp/a/idm/auth/app/login
      Query String: acAuthCardId=np-contract-{$default-card}&sid=1
      Scheme: https
      Context Path: /osp
      Servlet Path: /a
      Path Info: /idm/auth/app/login
      Server Name: myserver.acme.com
      Server Port: 8443
      Content Length: 248
      Content Type: application/x-www-form-urlencoded
      Locale: en_US
      Host IP Address: 10.1.1.2
      Remote Client IP Address: 10.4.4.222
      Cookies
         (1 of 3): JSESSIONID=FC02C133431DD08F292D3A69E1FDEF65
         (2 of 3): x-oidp-oauth2-1471021339493-1870600049=B5BNmMPd8oj45QxF2CvOVh33b6pBsbTT3zSY1BAtZ3Xbt2uwFj2Mqf5@EPCC1NryQIdk7JCLE6oicz8V28SwumOIOrJTPQxrNM42E4M5qV/D@LBkAn6pS9BeHFiRPzW00qC4l2FnJH/h0Vb7zRadh967S8CW8yFBKSYeU5Azb1HkdvWPgFWY3g2gBpqqh45sgGaliDi@2HjrOWyO6DuF
3jPV2d3KCd4kLmUAQOjsfk@tuMOkgNmIzv8ONJDnblk77welMRvOsjGuQNAK4W7ejbMgqoVAmioFzNxgul7@9DqSWt7HLZadsqeF/ukYqfFBdbXm/wZAfKhdjupdnGNbRLUs6BtmdDWqB83JGuSDgH3DSIQJhUjgjduH2NAoOWJyBSKWzktm38kfed1jhDSXbw~~
         (3 of 3): x-oidp-session59303d34382c2d310=200-JOBNIOFPQXB1WMCJ9JXAEQXPVZRSDW5B3DBE6Y7X-2E7B88D7-4C2E!1!4C2E!120!127!Hx7MrTzxNobmRj8mp5/Aos9Qd28 VPGxTTWH7umaxbY~!DI7l8LQFEkDBbi P8tr7r5CuVFWZokfGcKju8bBx9Ex4uzyhCcUobfZW0qhaJ8PB31OHMXyaYswY2ccRxo6St0QMTNNaJui76MXJ
XYhz EIEgIP L lAciIjPG8IjS3xJG/sIcXjP2whtl/0vrwHq18dqUYxySSxlSwC3A4o0ZYa9UviHe23uUmnb8eB5csSqtu81t3FZXNxd8eBiu2BshHIv/vg67Vbf4Q0kFJmDPRkPV ol9uuvUZgJdMYqfSbyunbwbGTryJKCFqyXNJfUkH4Ieea6lhbb9fa0BhrfMxLN9vrKPEZkD htCyOQ58uUX1ENNIbJ4Juf4T9HuFiH zAFbDS6OWxn5j1eMiMuvhj9KBHYY
cyWXvCK6rdNNL6djUf01pmuEXWCyo fa8IZb2SLKG/LNov5ZV2HiSLmFKPs1173kAXU0qrhFELpuz 8IGPhhb1jyKkEeofJK6F50FUmCSxCqfJS/ta1zvxNPG6qMn4s6cV33bSn0VQp6Ro7KFoSspI9cBx78doGYRKZlmaGph9 9l4LdDCGVItwWR6F8lRR8  fwMqWp5aG1ADg5ftw2DMC5sPSZB7 wfYQg~~
      Headers
         host=myserver.acme.com:8443
         user-agent=Mozilla/5.0 (Windows NT 6.1; WOW64; rv:48.0) Gecko/20100101 Firefox/48.0
         accept=text/html,application/xhtml xml,application/xml;q=0.9,*/*;q=0.8
         accept-language=en-US,en;q=0.5
         accept-encoding=gzip, deflate, br
         referer=https://myserver.acme.com:8443/osp/a/idm/auth/oauth2/grant?response_type=code&client_id=rbpm&state=020288ae-9ef9-49ac-9a14-940fddb28e6f&redirect_uri=https://10.1.1.2:8443/IDMProv/oauth
         cookie=(see above)
         connection=keep-alive
         upgrade-insecure-requests=1
         content-type=application/x-www-form-urlencoded
         content-length=248
      Session
         Id: FC02C133431DD08F292D3A69E1FDEF65
         Last Accessed Time: 1471021340784
      Parameters
         acAuthCardId
         sid
         option
         excludeParameterNames
         secondaryNamingAttrState
         Ecom_User_ID
         Ecom_Password
      Attributes
         javax.servlet.request.ssl_session
         javax.servlet.request.key_size
         javax.servlet.request.ssl_session_mgr
         javax.servlet.request.cipher_suite
         javax.servlet.request.ssl_session_id
         OSPRequestContext

An item that is worthy of notice is that my request was to:
Request URL: /osp/a/idm/auth/app/login

That is, I was posting to the login URL. Which makes sense, but of course it is important since it shows where OSP is going with this.

One thing that initially confused me was this line:
Last Accessed Time: 1471021340784

That looks to the first glance like a CTIME time stamp, though I should have noted that we rolled passed 1.5 billion in CTIME mid 2016, so this could not be CTIME). But when I converted it on a web based Unixtime conversion page, it rendered out as in the year 64000 or so, so it is too large for a 32 bit CTIME timestamp. (CTIME is a count of seconds since the year 1970, Jan 1, midnight. This has limitation since when signed, 2 billion seconds run out around 2036. Unsigned, 4 billion seconds run out in 2108 but then you cannot address dates before 1970.) I tried FILETIME which is what Active Directory uses, which is a count of 100 nanosecond intervals since Jan 1, 1601 at midnight, but this renders out to a few days into 1601, so too small a number. (Being a 64 bit integer, FILETIME runs out in the year 2600 or somesuch).

Finally I was out of ideas, and since I was offline writing this (In the subway, underground, no Internet) I decided to use Designer, and Simulator to try to test ideas. I took a test policy, added a Set Local Variable, and for the value, I used the Convert Time time token on the value. That is when I noticed a time system I almost never use, but is the second choice of the Source/Destination formats for this token. JTIME which is a count of milliseconds since the year 1970.

When I added commas to make it easier for me to read I see the number is in the trillion range as 1,471,021,340,784 so this is clearly not a 32 bit integer, and in JTIME it converts to Aug 12, 2016 when I generated the test case.

I am not showing every line in the log since there seems to be a lot of modules, where the same message bubbles up through the layers multiple times and it is a bit verbose.

Next Tries to find my session, isn't one, but since it is a request for an OAuth grant, with code as the type (OAuth can have a couple of different methods in OSP for granting access, a code is one which IDM uses), it sets a cookie, sees I am unauthenticated:

[OIDP] 2016-08-12T13:02:19.487-0400
Level: TRACE
Code: com.novell.oidp.servlets.handler.AuthenticationServiceRequestHandler.resolveHandler() [181] thread=http-bio-8443-exec-3
Message: IDP oauth2 handler to process request received for grant

[OIDP] 2016-08-12T13:02:19.488-0400
Level: TRACE
Code: com.netiq.oidpp.oauth2.handler.Grant.getCommand() [153] thread=http-bio-8443-exec-3
Message: Response type is "code". Transferring execution to the Auth Code Profile.

[OIDP] 2016-08-12T13:02:19.488-0400
Level: TRACE
Code: com.netiq.oidpp.oauth2.handler.Grant.getCommand() [163] thread=http-bio-8443-exec-3
Message: Response type is unrecognized. Looking at Grant Type: "null".

[OIDP] 2016-08-12T13:02:19.488-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.() [293] thread=http-bio-8443-exec-3
Message: Created new Session: id: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6-CX, Type: PERSISTENT

[OIDP] 2016-08-12T13:02:19.489-0400
Level: DEBUG
Code: com.novell.oidp.cluster.ClusterCookieContext.resolveSession() [154] thread=http-bio-8443-exec-3
Message: 
   Session was created for this user request because no cookie accompanied the request: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6
   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: 1)
         Last Used Time: 08-12 13:02:19 0488 (1471021339488) (Elapsed: 1)
         Main JSP: main
         Do Not Set Activity: false
         Logout Flag: 0
         Show Logout: false

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

Now that OSP has decided I need to login it is time to get started on that by logging out how it is going to do that.

[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

There are a couple of very interesting things in this log snippet. The Authentication Contract is shows as Name/Password Login which is "Id'ed" as np-contract, as opposed to SAML or Kerberos. This is one of those places where some of OSP's pre-configuration shows. In NAM you would have to set some of this up each time, but OSP comes with a preset bundle of options when delivered with IDM.

I firmly believe that most of the items in the contract, and many of the settings here are controllable with OSP, if we had full access to the configuration interface. Thus most of it is buried inside the JAR in configuration files. I know that an issue I raised regarding Shibboleth intergration and the POST URL's in the SAML metadata being wrong, I got a comment that explained which config file held that setting and how to unpack the JAR, change it, repack to change the setting.

I think this is a good stopping point, and I will continue in the next article to walk through the log.