When last we left off, we had actually started to login, via OSP. Isn't it amazing how much trace it takes to get to an actual login, right? This is part of the reason they ship OSP with much lower levels of logging enabled. As you can imagine, this would not be a good way to run in production. Think of the disk space you would waste, if nothing else.

Previously we saw that there was a list of contracts to execute, the username password for actual logins, then the SSPR check, to make sure you account is not locked, disabled, expired, password expired, on the lam, on the terrorist watch list and so on. This reminds us that OSP is really a nice and mostly fully functional NAM style product, for federation at least and can cascade authenticators or contracts. It is just when shipped with IDM, we get a restricted version with no interface to control the more interesting parts of it.

The next contract to be executed is one for Admin Role mapping, which succeeds and makes me an Admin:

[OIDP] 2016-08-12T13:02:50.256-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: 2
      Executable: (Auto) IDM Admin Role Mapping Method(id={$auto}-admin-role-mapping-method)
         Type: non-user
         Session authenticated: false
         Valid on session: false
         Method selected for execution.

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

[OIDP] 2016-08-12T13:02:50.258-0400
Level: DEBUG
Code: com.novell.oidp.authentication.classes.RoleMapping.doAuthenticate() [214] thread=http-bio-8443-exec-4
Message: 
   Assigning the following role(s) to selected principal 'cn=uaadmin,ou=admins,ou=system,o=acme
      Name: system::IDPAdministrator

[OIDP] 2016-08-12T13:02:50.258-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.RoleMapping, Status: AUTHENTICATED

[OIDP] 2016-08-12T13:02:50.258-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.MethodProfile.authenticateMethod() [682] thread=http-bio-8443-exec-4
Message: Authentication Method (Auto) IDM Admin Role Mapping Method succeeded

I am unsure how it is deciding I am an admin user in this context. Is it looking at my nrfAssignedRoles attribute for one of the system roles, like User App Administrator? But there are 17 such possible system roles, and they can be scoped to only apply to smaller domains, so I wonder what it is looking for. It seems unlikely that it is checking for permissions to the [Root] object of the tree to become a tree admin.

There is no obvious LDAP call made, I did not see ACL's requested in earlier lookups, so maybe it is just literally pulling from the name in the ism-configuration.properties file and what it says is the administrative user.

Or perhaps it is using the container for administrators that can be set in configupdate.sh to select. In that case, a lookup is unnecessary since the DN is already retrieved, and thus just parsing the DN to check if this is a child of a known container should suffice, which is likely what is being done by this contract.

This Admin Role is probably similar to how NAM has Roles, which are of course different than IDM RBPM Roles, since we are short of words in the English language. I think the criteria for assigning this role is simply the subtree the user resides in, but it would be interesting to have a different approach allowed. For example, in SSPR an LDAP filter is used. This allows a flag attribute, or a group membership, or even an IDM Role, (use nrfAssignedRoles=DN value) to define who is an SSPR Admin. Using an IDM Role is actually kind of clever, and we did that a client once. Of course, you could have the IDM Role assign Group Membership in the Identity Vault, and then look for the Group membership, but that is basically the same thing, with or without one layer of indirection.

As it turns out, one of the things that the IDM engine should ship with, is a simple Loopback driver configuration that allows you to assign IDV Group memberships via Roles. It is really quite simple to develop, and I am sure this wheel has been reinvented many times over the years. To simplify things, for when a customer of mine needed this functionality I put together a package to add to a Loopback driver that does it all. Makes an EntitlementConfiguration object so that when User Application queries entitlements the driver supports it gets the configuration. Then entitlement queries just work, and you can see them available when assigning a valued entitlement to a Resource.

This allows you to do some very clever things with the Roles model. You can then have a Role, that grants access to a Workflow. You can grant a specific group eDirectory Browse and Compare permissions to a specific PRD object in the tree (or use the GUI to do it) after blocking the tree based right that normally inherits down.

Thus you can have a Role that controls access to PRD's and you can extend this model to much of the User App and Roles side of the house.

If anyone is interested, that package is available in my public package repository at: https://idmfolder.ciscony.com/repo/cis-idm-repo

Try it and if you have any issues, please let me know since I am always looking for ways to improve it.

So now I think it finally auths me to OSP, or at least so it begins:

[OIDP] 2016-08-12T13:02:50.259-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.UserIDProfile.validateIdentifiedPrincipal() [136] thread=http-bio-8443-exec-4
Message: Session not authenticated. Principal considered valid!.

This message feeds into my notion that the not authenticated messages we keep seeing are related to the difference between 'officially authenticated' per OSP's view of the world, versus each step of authentication. Here we see that the session itself is not authenticated, but it at least acknowledges that the principal (I hope that is me! The principal at school is you PAL, as opposed to the principle of the issue being PLE).

[OIDP] 2016-08-12T13:02:50.259-0400
Level: TRACE
Code: com.novell.oidp.session.authentication.NIDPAuthentication.<init>() [68] thread=http-bio-8443-exec-4
Message: Created new Local Consumed Authentication!

[OIDP] 2016-08-12T13:02:50.259-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.ContractExecutionProfile.authenticateSessionByContract() [770] thread=http-bio-8443-exec-4
Message: Created new NIDPAuthnContext for ContractExecutionProfile with Auth Instant: 1471021370259

Above it seems to be saying at this time stamp, 1471021370259 we are starting the OSP session. Now this in fact, in hindsight, since I found out the answer while I was writing this series, is a big glaring hint at what the issue is. That looks like CTIME, but of course CTIME rolled over to 1.5 billion seconds in the middle of 2016 so I should have noticed it that it is not quite CTIME. Also there are too many digits, this is greater than 2 billion, so must be a 64 bit integer.

When all you have is a hammer, everything looks like a nail, so I went into Designer, and looked at the Convert Time token. There is defines a couple of time syntaxes that are commonly used.

CTIME - Count of seconds since the very beginning of 1970. Thus 1 in CTIME is the first second after midnight, New Years Eve of 1970. The very important thing to remember here is that it is in a 32 bit number space, so 4 billion is the maximum, and if you want to do negative values (Dates before 1970) then you can only use about 2 billion as your maximum value. Two billion seconds, counted from 1970 runs out in the year 2037 (February I think). Thus we will likely have a Y2K37 style scare one of these decades, since this is a super common date format internally for things. One loophole is to throw away negatives, and view the value as unsigned, thus freeing up the second 2 billion values. This extends the issue out to 2108, which I can probably live with. eDirectory, Unix, and lots of other things (Some databases) use this format internally to store dates.

FILETIME - This is a count of 100 nanosecond intervals (nanosecond is a billionth of a second, so 10 million of these intervals a second!!! Now that is high resolution!) and stored in a 64 bit integer. The count interesting starts at midnight of the year 1601. No clue why, no doubt there is a good reason, and half of a 64 bit integer space runs out in the year 2500 or so, thus this format is probably fine for longer than I care to worry about. As far as I know, only Active Directory uses this format, but no doubt other apps will adopt it.

In FILETIME this date is super low, and only a few hours into the year 1601. So clearly not FILETIME either.

JAVATIME - This is a count of milliseconds since 1970 but stored in a 64 bit integer and is in theory the preferred Java time format for internal use.

As I noted, this probably should been a big hint. That looks like a good JAVATIME date value. But we will (eventually) come back to this point.

Now we are back attempting to authenticate, and this looks familiar from before.

[OIDP] 2016-08-12T13:02:50.260-0400
Level: TRACE
Code: com.novell.oidp.session.authentication.NIDPAuthentication.addAuthnContext() [373] thread=http-bio-8443-exec-4
Message: 
   Class: NIDPLocalAuthentication
      Identity Id: df880dc9f1eb6742c7a3df880dc9f1eb
      Display Text: np-contract-{$default-card}
      Consumed: true
      AuthnContext Objects:
            Class: NIDPAuthnContext
               Auth Instant08-12 13:02:50 0259 (1471021370259) (Elapsed: 1)
               LastUsedTime08-12 13:02:50 0259 (1471021370259) (Elapsed: 1)
               Mag Context: 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})

In fact, we can confirm that the values used are JAVATIME, by looking at these lines:

               Auth Instant08-12 13:02:50 0259 (1471021370259) (Elapsed: 1)
               LastUsedTime08-12 13:02:50 0259 (1471021370259) (Elapsed: 1)

And see two examples of human readable date stamps, followed by their JavaTime equivalents.

[OIDP] 2016-08-12T13:02:50.260-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.setAuthPrincipal() [1290] thread=http-bio-8443-exec-4
Message: 
   Setting the Authenticated Principal
   Candidate Principal:
     Type: LDAPPrincipal
     GUID: df880dc9f1eb6742c7a3df880dc9f1eb
     User Identifier: cn=uaadmin,ou=admins,ou=system,o=acme
     Authentication Source: bisadus
     Cached Attribute Count: 12
   No Existing Principal Found! Candidate Principal set in session 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6

[OIDP] 2016-08-12T13:02:50.260-0400
Level: TRACE
Code: com.novell.oidp.attributes.cache.CacheAttributeSource.copyAttributes() [109] thread=http-bio-8443-exec-4
Message: 
   Copying 12 attributes from this cache to the destination cache that has 0 attributes.
   Adding cached attribute: nrfMemberOf
   Adding cached attribute: srvprvPreferredLocale
   Adding cached attribute: mail
   Adding cached attribute: saml2-mapping-attr
   Adding cached attribute: initials
   Adding cached attribute: givenName
   Adding cached attribute: mobile
   Adding cached attribute: dn
   Adding cached attribute: userCN
   Adding cached attribute: Surname
   Adding cached attribute: userDN
   Adding cached attribute: {$authsource.ObjectNameAttr}
   The destination cache now has 12 attributes.

[OIDP] 2016-08-12T13:02:50.260-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.authenticate() [2781] thread=http-bio-8443-exec-4
Message: Authenticating Session 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6-CX with authentication NIDPLocalAuthentication, Session type: PERSISTENT

So although it said it was authenticating, in fact it used the previously cached and authenticated session. Thus we did not have to go back through all that logging yet again to login.

Looks like this all worked, my password is not expired, and it seems happy:

[OIDP] 2016-08-11T20:07:34.818-0400
Level: INFO
Code: com.novell.oidp.session.NIDPSession.authenticate() [1146] thread=localhost-startStop-1
Message: 
   Authenticated user cn=uaadmin,ou=admins,ou=system,o=acme in User Store IDM eDir with roles <Roles(null)>:
      <RoleSet(null)>:
         Role: IDPAdministrator
         Name: system

[OIDP] 2016-08-12T13:02:50.263-0400
Level: TRACE
Code: com.novell.oidp.profile.authentication.ContractExecutionProfile.returnFromAuthnRequest() [722] thread=http-bio-8443-exec-4
Message: No pending request OR going to Password Expired Servlet. Status: AUTHENTICATED

[OIDP] 2016-08-12T13:02:50.263-0400
Level: TRACE
Code: com.novell.oidp.profile.LoginProfile.executeContract() [716] thread=http-bio-8443-exec-4
Message: Contract Execution Profile "execute()" returned status: AUTHENTICATED

[OIDP] 2016-08-12T13:02:50.263-0400
Level: TRACE
Code: com.novell.oidp.profile.LoginProfile.executeContract() [725] thread=http-bio-8443-exec-4
Message: Set Authentication Context NIDPAuthnContext with Auth Instant 1471021370259 from Contract Execution Profile ContractExecutionProfile

Here we have a timestamp again as: Auth Instant 1471021370259

This value is the same as before when we authenticated, so it is keeping track of the same session, which is a good sign. Yet another hint I did not initially recognize.

[OIDP] 2016-08-12T13:02:50.263-0400
Level: INFO
Code: com.novell.oidp.profile.LoginProfile.successfulAuthentication() [169] thread=http-bio-8443-exec-4
Message: nLogin succeeded, redirecting to https://myserver.acme.com:8443/osp/a/idm/auth/oauth2/authcodecontinue?privateId=f8847a8a493e6a844d00&client_id=rbpm&irdpkg=1471021339493-1870600049.

Here we get a redirect to the authcodecontinue page of OSP, after we have authed, and after we have a session. Thus we should get an OAuth ticket from here to proceed

Now we do a GET:

[OSP] 2016-08-12T13:02:50.432-0400
Level: DEBUG
Code: com.novell.osp.OSPRequestContext.logRequest() [1737] thread=http-bio-8443-exec-4
Message: 
   HttpServletRequest (Number 6)
      Method: GET
      Request URL: /osp/a/idm/auth/oauth2/authcodecontinue
      Query String: privateId=f8847a8a493e6a844d00&client_id=rbpm&irdpkg=1471021339493-1870600049
      Scheme: https
      Context Path: /osp
      Servlet Path: /a
      Path Info: /idm/auth/oauth2/authcodecontinue
      Server Name: myserver.acme.com
      Server Port: 8443
      Content Length: -1
      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@2HjrOWyO6DuF3jPV2d3KCd4kLmUAQOjsfk@tuMOkgNmIzv8ONJDnblk77welMRvOsjGuQNAK4W7ejbMgqoVAmioFzNxgul7@9DqSWt7HLZadsqeF/ukYqfFBdbXm/wZAfKhdjupdnGNbRLUs6BtmdDWqB83JGuSDgH3DSIQJhUjgjduH2NAoOWJyBSKWzktm38kfed1jhDSXbw~~
         (3 of 3): x-oidp-session59303d34382c2d310=200-PPNW/I7PKXCVDJGNXOZQQJN XW0V6RVQW8JBL7 I-2E7B88D7-C458!1!C459!120!127!9Ll0wqc9CnDbOIfDBku8M328qiMxBuDGG99Xbn2ruS4~!tUgfSAvPk29esQ4LlF/HCKafkll7NKeupd35JcJjj4iCZif hJtHkgqk0YiMz3F8Y6Kea2QI71jUF7w2l7CYCULLuvNUtVan3p4H/Yqe1WhCfo3oLY UXJ2ZX9PFxTdmbshnwOOECOr3t3P/ rlRjf3xzjW5KZZVrWMo CRn40Eg7wsZxvEr6KMBU/dHjITJKrlR1/RffsSlvH/AfHAaAYngWMgO53V2CjMntr50UGFY/b4UGBfApf2EGaXuUu75u/o/vtPargXXImMhc8fpnxMPjmpTyjUcJ/19vQV03s17TPVePGTEqJxH9rGLMcFfnZ8Rlcz3MXIE77IXrIaXx0hIigOZUe5 5t2QENuz66UynSZzTgwiJwlscdQ/vwiNmZUneL4FtEHy/i6jLtLvweGTRtmW2Ex/BEY4oJX3/Ri4YCdxryzuE0BP62g7FffKcAcGjUfOOodWXLS0Su4Kmuyx/KBeHfbpy2Al8ap58i89ZV2 ryg8m/J9UJkqiEoowLD8KPYBC9BBPWYdNoUVH4iui1QjDfCJ8fmhiETdJ3uFJBKKHdhymbj7ngGF2RMGQYDvKYdkpxgfUyI 3hAogrA0vSXMY37FP xRKqzDA0EA mZ04Cs4CVF2GjrceVbNAUNrgayC68OYAnQSnSLriI54R8XuSaIdw/H wYHUp04ldRcpUjzJhfF41yczW7w5qXSCa6zV2KFe1VnAPPk XVgfZoJaB4G08ZGYIptxQiNnb8HfujJjPMXDhJ79PZfpShyscBnRXrii4cYGnXRHzvDquqQ7xndy1bRjYNVdn39R8gIPN5FTTuoveDKmvo4IxXD5UVqe3hq5oUf1pxQgANHovXc82QnhKB4c6sZAFZqYFLOKNlVNFnjv8pkIoeGEUFj2k9dZlZxRLHSua vYIyIOg 5qIap639k3bjSC51DCJ1rQ3ZD0as2VKTd/vyBWPTglDJdeTKemggLSZwv1qGBbAJxEYKjCEoZkFaP nfhY6Pn42DbmRDZKM06AVDXMQcvWazeEpNqCQdHFir4jSolL32X6qu7nlGyo u0q8Ws~
      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
      Session
         Id: FC02C133431DD08F292D3A69E1FDEF65
         Last Accessed Time: 1471021370266
      Parameters
         privateId
         client_id
         irdpkg
      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

Our initial POST was to /osp/a/idm/auth/app/login after which we logged in and then we get redirected to this one as a GET to /osp/a/idm/auth/oauth2/authcodecontinue

Now we move over to the authcode module, which gets a request for a code:

[OSP] 2016-08-12T13:02:50.433-0400
Level: TRACE
Code: com.novell.osp.servlet.OSPServlet.process() [213] thread=http-bio-8443-exec-4
Message: 
      Class: OSPRequestContext
         HttpServletResponse exists.
         Http request type: GET
         Request number: 6
         Tenant: idm
         Service: idm(id=auth)
         Path element count: 2
            Element: oauth2
            Element: authcodecontinue
         Override locale: en_US

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

Again at the ALL logging level it gets a bit silly. But it tells us we are using the oauth2 handler to process the request.

[OIDP] 2016-08-12T13:02:50.440-0400
Level: TRACE
Code: com.novell.oidp.session.authentication.NIDPAuthentication.getAuthenticatedContext() [352] thread=http-bio-8443-exec-4
Message: 
   There are 0 existing NIDPAuthnContext objects contained inside of this NIDPAuthentication
   No match. Returning null

It needs a user, does not find one included in the GET request, but then it links to the one I just created when I logged in a moment ago.

[OIDP] 2016-08-12T13:02:50.440-0400
Level: TRACE
Code: com.novell.oidp.session.authentication.NIDPAuthentication.addAuthnContext() [373] thread=http-bio-8443-exec-4
Message: 
   Class: NIDPLocalAuthentication
      Identity Id: df880dc9f1eb6742c7a3df880dc9f1eb
      Display Text: np-contract-{$default-card}
      Consumed: true
      AuthnContext Objects:
            Class: NIDPAuthnContext
               Auth Instant08-12 13:02:50 0259 (1471021370259) (Elapsed: 181)
               LastUsedTime08-12 13:02:50 0263 (1471021370263) (Elapsed: 177)
               Mag Context: 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})

[OIDP] 2016-08-12T13:02:50.441-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.setAuthPrincipal() [1290] thread=http-bio-8443-exec-4
Message: 
   Setting the Authenticated Principal
   Candidate Principal:
     Type: LDAPPrincipal
     GUID: df880dc9f1eb6742c7a3df880dc9f1eb
     User Identifier: cn=uaadmin,ou=admins,ou=system,o=acme
     Authentication Source: bisadus
     Cached Attribute Count: 0
   Existing Principal Found:
     Type: LDAPPrincipal
     GUID: df880dc9f1eb6742c7a3df880dc9f1eb
     User Identifier: cn=uaadmin,ou=admins,ou=system,o=acme
     Authentication Source: bisadus
     Cached Attribute Count: 0
   Candidate Principal cached but not added to session 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6

It is unclear what it means that an LDAP Principal is found, cached, but not added to the session. You would think it would be involved in the cached setting somehow.

[OIDP] 2016-08-12T13:02:50.441-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.<init>() [439] thread=http-bio-8443-exec-4
Message: Built Session from XML: id: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6-CX, Type: PERSISTENT

[OIDP] 2016-08-11T20:07:34.818-0400
Level: INFO
Code: com.novell.oidp.session.NIDPSession.logout() [1048] thread=localhost-startStop-1
Message: Session Logged Out

But now suddenly, after all that work, I am logged out. What happened? Why? No obvious warning here.

[OIDP] 2016-08-12T13:02:50.442-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.isAuthenticated() [2520] thread=http-bio-8443-exec-4
Message: 
   Session Id: 0e969fa98e544d28af92096f2ca4ea13-8ee7eae3a3effbfae6
   Initial consumed authentications count: 1
      Removing timed out authentication context: 1471021370259
         Last used: 08-12 13:02:50 0263
         Context timeout: -1294967296
         Elapsed since timeout: 1294967474
      The Local Authentication was authenticated, but it must have timed out!
      Local: false
      Remote: false
   An AuthnContext timed out and was removed such that the session is no longer authenticated! Logging out session!
   Authenticated: false
   Removed system administrator role: system::IDPAdministrator

Ok, so now it tells me I was authenticated but my AuthnContext timed out. How, I literally just finished logging in, what is going on?

The key elements to the answer are in here in the Context timeout and Elapsed Since timeout fields, but I will finish the logging review and then explain.

Now it looks like it is looking for a cookie to tell it what user or session to use.

[OIDP] 2016-08-12T13:02:50.443-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.getData() [604] thread=http-bio-8443-exec-4
Message: Created a new id for a NIDPSessionData object: 2

[OIDP] 2016-08-12T13:02:50.443-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.getSessionData() [630] thread=http-bio-8443-exec-4
Message: Created NIDPSessionData with id: 2

[OIDP] 2016-08-12T13:02:50.443-0400
Level: TRACE
Code: com.novell.oidp.session.NIDPSession.getSessionData() [646] thread=http-bio-8443-exec-4
Message: Retrieved existing NIDPSessionData with id: 2

[OIDP] 2016-08-12T13:02:50.443-0400
Level: TRACE
Code: com.netiq.oidpp.oauth2.handler.InterRequestPackage.<init>() [243] thread=http-bio-8443-exec-4
Message: 
   Inter-request data:
      Package Id: 1471021339493-1870600049
   Searching for cookie named x-oidp-oauth2-1471021339493-1870600049 among 3 cookies in the request.
   Found cookie named x-oidp-oauth2-1471021339493-1870600049. Value has 408 characters.
   Base64 decoded cookie value to 304 encrypted bytes.
   Decrypted decoded cookie value to 288 bytes.
   Plain text cookie value has 288 characters.

[OIDP] 2016-08-12T13:02:50.444-0400
Level: TRACE
Code: com.novell.oidp.authentication.AuthenticationManager.getCard() [331] thread=http-bio-8443-exec-4
Message: Did not search for "null" or "empty string" card id.

[OIDP] 2016-08-12T13:02:50.444-0400
Level: TRACE
Code: com.netiq.oidpp.oauth2.handler.BrowserHandlerBase.handleError() [583] thread=http-bio-8443-exec-4
Message: Redirect error: Missing authenticated principal.

[OIDP] 2016-08-12T13:02:50.444-0400
Level: INFO
Code: com.netiq.oidpp.oauth2.handler.TokenRequestHandlerBase.auditTokenCreation() [280] thread=http-bio-8443-exec-4
Message: IssueOAuthCode

[OIDP] 2016-08-12T13:02:50.445-0400
Level: TRACE
Code: com.netiq.oidpp.oauth2.handler.InterRequestPackage.cleanup() [322] thread=http-bio-8443-exec-4
Message: 
   Deleting OAuth2 Inter-request data package cookie: 1471021339493-1870600049
   Setting cookie named x-oidp-oauth2-1471021339493-1870600049 with a cookie value of 0 characters into the responset.
   Added cookie to request with:
     Cookie Domain: myserver.acme.com
     Path: /
     MaxAge (Seconds): 0
     Secure: true

And then I end at the access_denied:

[OSP] 2016-08-12T13:02:50.447-0400
Level: TRACE
Code: com.novell.osp.UIResponder$Response.setResponse() [1345] thread=http-bio-8443-exec-4
Message: 
      Response: TARGET
      Target: https://10.1.1.2:8443/IDMProv/oauth?error=access_denied&state=020288ae-9ef9-49ac-9a14-940fddb28e6f

So looks like the session has timed out inside OSP in almost 0 time. Do I have a zero timeout somewhere? Here is where I get redirected to the Access Denied page my browser keeps ending at when I test this.

A few elements up I said I found the issue, and it is in these lines:

      Removing timed out authentication context: 1471021370259
         Last used: 08-12 13:02:50 0263
         Context timeout: -1294967296
         Elapsed since timeout: 1294967474
      The Local Authentication was authenticated, but it must have timed out!

The problem was, I was trying to cleanup up my configuration, and make the timeouts for the system sufficiently large, that I would not have timeout issues. From a security perspective, I was not that worried, but some backbend timeouts, I did not want to expire quickly.

There are many available timeouts in User App and OSP together, and I was trying to set them all to the same, and fairly high. For no good or apparent reason I had chosen 30,000,000. It was pretty random. I just added a bunch of zeroes to the default of 300.

Well here is a fun 'bug' that I have been told works as designed. That time field is NOT taking seconds rather it seems like it is taking seconds, converting to JAVATIME, which is milliseconds and then storing it in a 32 bit integer. Well 30,000,000 times 1000 is 30,000,000,000 which is way more than a 32 bit integer can hold (Signed it can hold 2 billion and change, unsigned 4 billion and low change). Thus I overflowed the time value and got myself into a weird case of a negative timeout, where I always timed out, since I had a negative timeout and thus had timed out in the past, before I even logged in.

Now I concede 30,000,000 seconds is stupid, it is 347 days. However it does indicate that the max timeout you can enter is, 2^31, which is 2147483648 and which converts to 24.8 days maximum.

The obvious correct answer is to add a note to the docs and configupdate about this limit at the simplest level or to change to use a 64 bit integer at a more functional fix level.

I thought I would share this error, because it was kind of crazy, you could see it doing crazy stuff, and once you know the answer, all the craziness made sense in hindsight.