In the first three parts of this series I discussed the various events I have seen go through the Roles and Resources Service Driver (RRSD henceforth).

I noted that really there seem to be 4 classes of events that go through (even stole that list from a mapping table in the driver configuration).

• User events

• nrfRequest for Role

• nrfRequest for Resource

• Role to Resource association.

This driver is different than others, since it uses JClient to talk to the directory straight through Java over NCP. That is, modifications to eDirectory do not happen as XDS event documents sent back to the engine to be processed as most every other driver normally works. Nor is it via an LDAP connection to write data back to the directory, as the User App itself (but not necessarily the driver) works. Nor is it injecting events into other driver queues to query or write data, as the User App driver does for CODE MAP Refresh events or as the Managed System Driver does for checking state of objects.

Thus this driver cannot run in a remote loader instance, it needs to be localhost to an eDirectory instance (ergo, run in an engine instance, since the engine requires eDirectory locally to event out of, using dxevent).

All along I was sure this was most of the story. But I have since learned two new interesting tidbits through experimenting and seeing what comes out of the driver log trace. You have seen in the past three articles how interesting reading the trace can be, in terms of understanding the underlying processes.

On a side note, my actual degree from university is in Biology, Ecological Genetics, (no comment how I ended here, other than to say I focused on the field of cladistics, the study of evolutionary family trees. Cladistics is all about building the most parsimonious (optimum) tree structure that describes all the descendants based on the data we have. Well what do you think eDirectory tree design is all about.)

In molecular biology they often attempt to break biological processes, since you can get interesting hints about things work properly, by seeing what happens when you break pieces of it. Imagine that the intermediate product of a biological process is generated and consumed very quickly, such that enough never builds up to be detectable. Well if you break the process that consumes this product, you then can see a build up of its precursor.

Same thing in IDM operations. Sometimes, seeing failures indicates better what was trying to be done by its failure than watching a successful operation.

I am too lazy to go cull out all the examples of this I have written about in the past, but specifically in the case of Java applications, since the error shows the class calling it, and normal programmers like to name classes usefully, the error is often informative. I concede the case of Null Pointer Exception is immensely annoyingly unhelpful, but the class that was called that returned the null pointer exception can be helpful.

This is all to say, I thought I had understood everything that was going on in the RRSD driver for a User being assigned a Role via the creation (By User App via LDAP) of an nrfRequest object in the directory, and how the RRSD stepped through processing it.

Then this error showed up (Since we have seen the process before, I will show a stripped down trace sample):

Triggering event, a create of an nrfRequest object, converted to an nrf:request command.

[08/26/14 05:44:32.958]:Role_test ST:Submitting document to subscriber shim:
[08/26/14 05:44:32.958]:Role_test ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.1">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <nrf:request dn="O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1" event-id="0" xmlns:nrf="urn:dirxml:nrf"/>
  </input>
</nds>

Returns what looks familiar, but look at the very end! (I will call it out again to make it easier to see)

[08/26/14 05:44:32.959]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1
[08/26/14 05:44:32.969]:Role_test ST:: Process Equivalent To Me
                Role: Process Equivalent To Me
                Role: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level20\CN=External Services\CN=OBIEE External
                Operation: 5
                Identity: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004
                Operation: {1}
                Identity: {2}
[08/26/14 05:44:32.983]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-1e556b0adee242c497ef2cade269a563-0
[08/26/14 05:44:33.003]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-a90d04f46d2940aca2f0a47787f946cb-0
[08/26/14 05:44:33.027]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-dc37886cc8394660835a8c729012b19a-0
[08/26/14 05:44:33.112]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-4e74c908610f4e1fad74c7754863040b-0
[08/26/14 05:44:33.158]:Role_test ST:: Processing request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-487b840d550441f9aff8b15967937fc7-0
[08/26/14 05:44:33.235]:Role_test ST:SubscriptionShim.execute() returned:
[08/26/14 05:44:33.236]:Role_test ST:
<nds dtdversion="3.6.1">
  <source>
    <product instance="RoleService" version="4.0.0.5730">Novell Role Service Driver</product>
    <contact>Novell, Inc.</contact>
  </source>
  <output>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1</status>
    <status event-id="0" level="success">Added assigned role to identity
                Role: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level20\CN=External Services\CN=OBIEE External
                Identity: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Created resource request
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-1e556b0adee242c497ef2cade269a563-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-1e556b0adee242c497ef2cade269a563-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=WAS Service - OBIEE
                User: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-1e556b0adee242c497ef2cade269a563-0</status>
    <status event-id="0" level="success">Created resource request
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-a90d04f46d2940aca2f0a47787f946cb-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-a90d04f46d2940aca2f0a47787f946cb-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=WAS Application - Siebel
                User: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054432-a90d04f46d2940aca2f0a47787f946cb-0</status>
    <status event-id="0" level="success">Created resource request
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-dc37886cc8394660835a8c729012b19a-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-dc37886cc8394660835a8c729012b19a-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=WASAccount
                User: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-dc37886cc8394660835a8c729012b19a-0</status>
    <status event-id="0" level="success">Created resource request
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-4e74c908610f4e1fad74c7754863040b-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-4e74c908610f4e1fad74c7754863040b-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=OBIEE External Authorization group
                User: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-4e74c908610f4e1fad74c7754863040b-0</status>
    <status event-id="0" level="success">Created resource request
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-487b840d550441f9aff8b15967937fc7-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-487b840d550441f9aff8b15967937fc7-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=OBIEE Account
                User: O=acme\OU=Users\OU=Partners\CN=ddgaikwad_004</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-487b840d550441f9aff8b15967937fc7-0</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1</status>
    <status event-id="0" level="error">Failed to send nrf status update for request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1
        to workflow process: WF:62f544057f4747a78f60b653e6d6cf73
                Reason: java.lang.RuntimeException: javax.net.ssl.SSLHandshakeException: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target</status>
  </output>
</nds>

After the final transition from status level 30 to 50, we get the following error, once again, but this time in slightly nicer format.

DirXML Log Event -------------------
     Driver:   \acme-QA\acme\Services\IDM\acme-DriverSet\RoleService
     Channel:  Subscriber
     Status:   Error
     Message:  Failed to send nrf status update for request
        DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1
        to workflow process: WF:62f544057f4747a78f60b653e6d6cf73
                Reason: java.lang.RuntimeException: javax.net.ssl.SSLHandshakeException: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target

Stripped of headers, that error is:

Reason: java.lang.RuntimeException: javax.net.ssl.SSLHandshakeException: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target</status>

Before we go on, I got this example from a forum poster, and as I looked at it I thought, oh, wait, maybe this has a different issue, since the header of the XDS document starts as:

<nds dtdversion="3.6.1">
  <source>
    <product instance="Role and Resource Service Driver" version="4.0.0.5730">Novell Role Service Driver</product>
    <contact>Novell, Inc.</contact>
  </source>     

Compare that to the engines header, as it sends an event down the Subscriber channel:

<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.1">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>

Note that the dtdversion is 3.6.1 not 4.0. The missing ndsversion makes sense since a shim does not have an eDirectory version, but the engine does.

But the product node was saying it was the Role Service Driver but version 4.0.0.5730 which is confusing since the named changed to add in Resources in User App 3.7 release. You can also see that the instance XML attribute has the Resource word in it.

Basically this is all a shim issue, and barely worth opening a bug, just worth noting it is cause for confusion, if you thought you were IDM 4.02 across the board, and seeing a shim return 3.6.1 and possibly Roles Service Driver (a pre-3.7 UA driver version) could confuse. Thankfully this is all cosmetic, but worth calling out to save on false alarms. (Gave me a fright for a moment there).

Now back to the real error at hand... As I said earlier, the Java class reporting the error is often informative as to what was being attempted when it failed.

The first class, java.lang.RuntimeException is mostly telling us we had a problem.

The next javax.net.ssl.SSLHandshakeException: exception is helpful, since now we know we have an SSL issue, and probably a handshake issue.

The next error is helpful as well, sun.security.validator.ValidatorException:, we see this is now really a Sun class, so basically core Java (pre-Oracle) security classes. Nicely it provides an actual error message:

PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target

What this is saying is that PKI (Private Key Infrastructure) components are having an issue finding a Certificate Authority that is trusted, that signs the SSL certificate exposed by a SSL connection.

SSL works by starting the conversation using RSA encryption using the SSL Private Key and Public Key pair. But you have to trust that key pair at least a little bit, by having declared you trust the signing authority that signed the SSL certificate used by the web service. (This is usually done in Java with a JKS (Java KeyStore) certificate store entry, imported with the flag -trustcacerts set.)

Once you get that going SSL switches over to using symmetric encryption (Like AES-256, DES, whatever) that is MUCH faster and simpler, but requires that you both agree on a value used to encrypt decrypt the data. The Private Key stuff is used only to get that shared secret for use in symmetrical encryption.

Ok, that is all interesting, and meant as a lesson in reading Java stack traces, and how SSL works, and whatnot. However there is still something interesting going on here.

We know that the RRSD shim uses JClient for its operations. I would have thought ALL its operations, and I have seen no real hints in the trace that it did anything else. But here by looking at an error we see that in fact something is being done over SSL.

Operationally in context here, I would expect only two kinds of SSL to be relevant. First, an LDAP connection over SSL (LDAPS over 636 or using Start TLS on 389) is the most obvious example. But since we know JClient is in use for almost everything it seems almost inconceivable to do LDAP operations suddenly for one final step. I can contrive an example where it might be helpful, like a query for any other nrfRequest objects with a timestamp attribute that you want to do a time based compare on. LDAP can do a query on timestamp fields for nrfStartDate >=201410031111Z which is kind of useful, but NCP (as far as I know) cannot in such a simple fashion. But that seems fairly unlikely to me.

The second obvious example is some kind of operation done over HTTPS, which sort of defines it as a Web Service, which could be SOAP or REST, and in the context of Roles Based Provisioning Modules, User Application, and whatnot, that is most likely SOAP. (Though trending towards REST for more and more things as version progress).

Thus my guess is that what we are seeing is the RRSD driver make a SOAP call to the User App. It also helps that as background to this specific case, I know that the user who reported the problem had just changed the SSL certificate on his User Application. In that process he changed from one signing authority to another. Almost certainly one, not contained in Java 1.7's cacerts file that RRSD was using on the engine server.

Now here is where it helps if you have played with the User Application SOAP endpoints to catch the next nuance.

If you are interested in reading more about ways to use the User Application SOAP endpoints, consider reading these articles:

• User App, SOAP Integration activity interesting error

• Using SOAP to terminate a running workflow – Part 1

• Using SOAP to terminate a running workflow – Part 2

Yes, I like citing myself. Get used to it. These are meant to be helpful references, and some folk may not know these articles exist and find them helpful. For the rest of you, glaze over your eyes, and avert them for a few lines.

This is relevant, since when we look at the error message in detail again, we see the beginning, looks a tiny bit different than the rest of the events. Our error looks like this (I chopped off the Java stack error, since it is irrelevant here and just adds noise and confusion, assume this ended with a proper </status> node to close the XML).

<status event-id="0" level="error">Failed to send nrf status update for request
	DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20140826054432-2742e2485be34e95a5829f422eb1c4c4-1
	to workflow process: WF:62f544057f4747a78f60b653e6d6cf73

However a normal success looks like this:

<status event-id="0" level="success">Transitioned request status from 30 to 50
	DN: O=acme\OU=Services\OU=IDM\CN=acme-DriverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20140826054433-487b840d550441f9aff8b15967937fc7-0</status>

Now maybe it is because it is an error, or maybe because I never noticed it before, but there is an extra line in the error case:

to workflow process: WF:62f544057f4747a78f60b653e6d6cf73

The key takeaway here, that ties all my meanderings together, is that when you make SOAP calls into User App about workflows, you need to specify the workflow ID (Looks like that WF: GUID like value) in the call.

Notice none of the other status change functions have that WF: part, which makes me think they are all pure JClient.

Now if I had to guess, I would suspect they are calling the following SOAP function:

<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:ser="http://www.novell.com/provisioning/service">
   <soapenv:Header/>
   <soapenv:Body>
      <ser:setRoleRequestStatusRequest>
         <!--Optional:-->
         <ser:arg0>?</ser:arg0>
         <ser:arg1>?</ser:arg1>
         <!--Optional:-->
         <ser:arg2>?</ser:arg2>
      </ser:setRoleRequestStatusRequest>
   </soapenv:Body>
</soapenv:Envelope>

I guess this function for two reasons. First is that the error message begins with "Failed to send nrf status update for request..." and second it is the only Set Role Request Status Request function I can find in the Provisioning Web Service WSDL file.

This does actually answer a question that has long been discussed in the forums. Can you manipulate the Role assignments purely in eDirectory objects (ergo via a driver, that is not RRSD nor UA driver). We often get a cryptic incomplete answer that it is not supported, which is fair enough. But that was never really the question. The question is, what needs to be done in UA to make this all work. Right here we have a concrete example of one place where more than just object manipulation will suffice.

It reads to me that you should then reach back into the User App and update the Workflow that made the nrfRequest object to update its status as complete.

I find that a very interesting find.

I suspect that the RRSD driver also can probably send back error messages to the UA and the originating workflow. Or put another way, it almost certainly changes the state in this case, as a success, you can bet your bottom dollar they send error states as well, should the Workflow request have failed.

Now the more I think about this, I wonder if this only occurs when a Workflow is involved in the nrfRequest generation, I will assume it is the nrfCorrelationId attribute having a value that indicates this.

Thus if you are NOT using workflows, this would seem to be an example of the opposite then, that the Web services call is just about 'closing out' the workflow as a successful Role grant, vs the raw act of granting a Role.

While this error is VERY informative, it is not that enlightening at the end of it, but boy does it give you food for thought.

(If you happen to have any informative errors like this, please send them to me. I find this stuff a ton of fun!)