In the previous article in this series, I followed a bunch of Role based events, and in this article I will continue with some more.

I continued goofing around in my test environment doing Role and Resource stuff, and collecting events. As long as I have them collected, it seems like it would be useful to record them for others to see. I have been meaning to do this since IDM 4.0 came out almost four years ago, but what can I say, I got a bit distracted and busy. Better late than never, right? I wish the official documentation covered this area, but so be it. It seems to me that a section in the docs showing what proper trace for a variety of events SHOULD look like would be really helpful.

Here is what I got when I created a role in the User Application interface. That means I created an nrfRole object in the AppConfig container under my User app driver as you can see from the src-dn in the XDS event document.

You can see how it was named:

\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\RoleDefs\Level10\SAP-Portal-ECC-AccountRole

And that my driver is the \TEST_IDM\tstidm\services\driverSet\UserApplication\ object. With a AppConfig container (Interestingly named cn=AppConfig, not an OU object, which is perfectly valid, just uncommon for eDirectory focused folk), then a RoleConfig container, followed by a RoleDefs container (Note: This one is plural, so don't forget the S). Then you have three containers, Level 10, Level 20, and Level 30 available for the corresponding Permission (10) IT (20), and Business (30) role levels.

It is also possible to make sub containers for Roles, so watch out for those as well. In fact the SAP drivers I took this example from will make role sub containers for the many roles it will automatically generate.

[09/03/13 10:34:08.317]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <add cached-time="20130903143408.300Z" class-name="nrfRole" event-id="tstidm01#20130903143408#4#1:a740b4a4-9ba1-4c67-cdbf-a4b440a7a19b" qualified-src-dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole" src-dn="\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\RoleDefs\Level10\SAP-Portal-ECC-AccountRole" src-entry-id="108955" timestamp="1378218848#1"/>
  </input>
</nds>

As you can see, this has no attributes, just the raw event for the nrfRole class, with a src-dn value.

This gets mapped to a command of:

<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <nrf:role dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole" event-id="0" xmlns:nrf="urn:dirxml:nrf"/>
  </input>
</nds>

Which processes as follows:

[09/03/13 10:34:08.340]:roles ST:SubscriptionShim.execute() returned:
[09/03/13 10:34:08.340]:roles ST:
<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>
  <output>
    <status event-id="0" level="success">nrf:role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole</status>
  </output>
</nds>
[09/03/13 10:34:08.342]:roles ST:No input transformation policies.
[09/03/13 10:34:08.342]:roles ST:No schema mapping policies.
[09/03/13 10:34:08.342]:roles ST:Resolving association references.
[09/03/13 10:34:08.343]:roles ST:Processing returned document.
[09/03/13 10:34:08.343]:roles ST:Processing operation <status> for .
[09/03/13 10:34:08.343]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  nrf:role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole

A nice simple output again. Interestingly enough, the Role creation does not go through the various levels of nrfStatus stuff. I guess that is just on the linkage objects (nrfResourceRequest, nrfResourceAssociation, etc) that ask for a link to be made, and the state of making that link gets stored in the nrfStatus attribute. I like the idea in principle, but since eDirectory is limited by a single writer thread, implementing a process that needs multiple writes to complete one task seems less than optimal.

Next up in the process would be to assign the resource to the Role. This was done in the User App interface by hand, as opposed to via a SOAP call or via a driver. This process generates an nrfResourceAssociation object which is used to link the two objects together.

[09/03/13 10:35:47.262]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <add cached-time="20130903143547.232Z" class-name="nrfResourceAssociation" event-id="tstidm01#20130903143547#4#1:5e321e8a-a099-41c9-dd85-8a1e325e99a0" qualified-src-dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003" src-dn="\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\ResourceAssociations\20130903103632-d7885752a01c4a5b9c078a50fb03b003"src-entry-id="108956" timestamp="1378218947#7">
      <add-attr attr-name="nrfRole">
        <value timestamp="1378218947#4" type="dn">\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\RoleDefs\Level10\SAP-Portal-ECC-AccountRole</value>
      </add-attr>
      <add-attr attr-name="nrfResource">
        <value timestamp="1378218947#7" type="dn">\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\ResourceDefs\SAP-ESSPortal-UserAccount</value>
      </add-attr>
      <add-attr attr-name="nrfStatus">
        <value timestamp="1378218947#3" type="int">10</value>
      </add-attr>
    </add>
  </input>
</nds>

This object has some attributes of interest, like the nrfRole, nrfResource being referenced, since this links the nrfResource to the nrfRole, and has an nrfStatus along with it. Thus in the event we see the filter allows the DN's of the objects to make it through. This is useful for following the trace, but as we will see in the next event, the mapping of the class to a command will drop all that data, and I guess look it up again on its own, inside the shims own code.

[09/03/13 10:35:47.284]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <nrf:resourceassociation dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003" event-id="0" xmlns:nrf="urn:dirxml:nrf"/>
  </input>
</nds>
[09/03/13 10:35:47.287]:roles ST:: Retrieving resource association objects based on a role or resource DN. DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
[09/03/13 10:35:47.295]:roles ST:SubscriptionShim.execute() returned:
[09/03/13 10:35:47.295]:roles ST:
<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>
  <output>
    <status event-id="0" level="success">Transitioned request status from 10 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003</status>
    <status event-id="0" level="success">Modified resource association
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003</status>
  </output>
</nds>
[09/03/13 10:35:47.299]:roles ST:No input transformation policies.
[09/03/13 10:35:47.300]:roles ST:No schema mapping policies.
[09/03/13 10:35:47.300]:roles ST:Resolving association references.
[09/03/13 10:35:47.300]:roles ST:Processing returned document.
[09/03/13 10:35:47.300]:roles ST:Processing operation <status> for .
[09/03/13 10:35:47.300]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 10 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003
[09/03/13 10:35:47.302]:roles ST:Processing operation <status> for .
[09/03/13 10:35:47.302]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Modified resource association
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003

In this trace you can see that although the actual event contained the Role and Resource object references, it is lost when converted to a command and the RRSD shim has to go out to request it again, as it logs, when it says:

[09/03/13 10:35:47.287]:roles ST:: Retrieving resource association objects based on a role or resource DN. DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole

Thus it has to go out and re-read data already contained in the event. But since the shim really seems to just respond to events, and then go do work assuming it knows little else about the object, this is at least consistent.

Then we see two status results:

    <status event-id="0" level="success">Transitioned request status from 10 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003</status>
    <status event-id="0" level="success">Modified resource association
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceAssociations\CN=20130903103632-d7885752a01c4a5b9c078a50fb03b003</status>

we see that the request itself, the nrfResourceAssociation object, gets a nrfStatus update change from 10 to 50. Then the event itself is returned as a success.

You can see that the status is upon the nrfResourceAssociation object, which is the glue between the Role and the Resource.

Next up, now that I have a Role created, a Resource created (Though I do not think I got trace of that one happening) and the two object linked, the obvious step is to assign a user to the Role and see what happens:

[09/03/13 10:37:39.239]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <add cached-time="20130903143739.211Z" class-name="nrfRequest" event-id="tstidm01#20130903143739#4#1:02169fee-7ace-4e1d-8e92-ee9f1602ce7a" qualified-src-dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0" src-dn="\TEST_IDM\tstidm\services\driverSet\UserApplication\AppConfig\RoleConfig\Requests\20130903103824-18698fd1250d46c3a2daebb95a368cbf-0" src-entry-id="108957" timestamp="1378219059#14">
      <add-attr attr-name="nrfStatus">
        <value timestamp="1378219059#14" type="int">0</value>
      </add-attr>
    </add>
  </input>
</nds>

So in the User Application GUI when I click on the Role from the Catalog, then the Assignments tab, and Assign a User, I get a nrfRequest object in the AppConfig's RoleConfig's Request container. When created, we start with an nrfStatus of 0, which makes sense.

Mapped through the policies we get this event, sent to the RRSD Shim:

[09/03/13 10:37:39.257]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <nrf:request dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0" xmlns:nrf="urn:dirxml:nrf"/>
  </input>
</nds>
[09/03/13 10:37:39.258]:roles ST:Subscriber processing request for .
[09/03/13 10:37:39.258]:roles ST:Submitting unknown event to subscriber shim.
[09/03/13 10:37:39.259]:roles ST:No command transformation policies.
[09/03/13 10:37:39.259]:roles ST:Filtering out notification-only attributes.
[09/03/13 10:37:39.259]:roles ST:Fixing up association references.
[09/03/13 10:37:39.259]:roles ST:No schema mapping policies.
[09/03/13 10:37:39.260]:roles ST:No output transformation policies.
[09/03/13 10:37:39.260]:roles ST:Submitting document to subscriber shim:
[09/03/13 10:37:39.260]:roles ST:
<nds dtdversion="4.0" ndsversion="8.x">
  <source>
    <product edition="Advanced" version="4.0.1.0">DirXML</product>
    <contact>Novell, Inc.</contact>
  </source>
  <input>
    <nrf:request dn="O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0" event-id="0" xmlns:nrf="urn:dirxml:nrf"/>
  </input>
</nds>
[09/03/13 10:37:39.264]:roles ST:: Processing request
        DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0
[09/03/13 10:37:39.288]:roles ST:: Process Equivalent To Me
                Role: Process Equivalent To Me
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Operation: 5
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith
                Operation: {1}
                Identity: {2}
[09/03/13 10:37:39.327]:roles ST:: Processing request
        DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.348]:roles ST:SubscriptionShim.execute() returned:
[09/03/13 10:37:39.348]:roles ST:
<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>
  <output>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0</status>
    <status event-id="0" level="success">Added assigned role to identity
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith</status>
    <status event-id="0" level="success">Created resource request
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0</status>
    <status event-id="0" level="success">Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0</status>
    <status event-id="0" level="success">Added assigned resource to user
                Resource: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=SAP-ESSPortal-UserAccount
                User: O=tstidm\OU=Users\OU=Empl\CN=jsmith</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0</status>
    <status event-id="0" level="success">Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0</status>
  </output>
</nds>
[09/03/13 10:37:39.354]:roles ST:No input transformation policies.
[09/03/13 10:37:39.354]:roles ST:No schema mapping policies.
[09/03/13 10:37:39.355]:roles ST:Resolving association references.
[09/03/13 10:37:39.355]:roles ST:Processing returned document.
[09/03/13 10:37:39.355]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.355]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130
903103824-18698fd1250d46c3a2daebb95a368cbf-0
[09/03/13 10:37:39.357]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.357]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned role to identity
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith
[09/03/13 10:37:39.358]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.358]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Created resource request
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.360]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.360]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.361]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.361]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0
[09/03/13 10:37:39.357]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.357]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned role to identity
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith
[09/03/13 10:37:39.358]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.358]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Created resource request
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.360]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.360]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.361]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.361]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned resource to user
                Resource: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=SAP-ESSPortal-UserAccount
                User: O=tstidm\OU=Users\OU=Empl\CN=jsmith
[09/03/13 10:37:39.363]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.363]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0
[09/03/13 10:37:39.364]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.364]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0
[09/03/13 10:37:39.366]:roles ST:End transaction.

Man oh man, did that generate a lot of trace. Lets try and break that up a bit to see if we can figure out what just happened. 

We basically get around 11 status events, and lets see if any of them make sense on their own. 

[09/03/13 10:37:39.355]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0

Our first status above is the change from nrfStatus of 0 to 30. This event is a change on the nrfRequest object, not the user itself. This is one of those places, where you wonder if maybe there was a better way? After all, eDirectory is a single writer system, so writes are expensive and it would be nice to minimize them, as opposed to a regular RDBMS where writes are not so expensive.

I think we will see a lot more write events in the processing here for me to complain about as well.

Remember that the initial write of the nrfRequest object is being done by the User Application, writing the request made in the GUI to an object in eDirectory, for the RRSD driver to react to, thus our first status is a change in state of that existing object that triggered this entire flow.

[09/03/13 10:37:39.357]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.357]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned role to identity
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith

Now we see that the Role is assigned to User, which is a write to the User object of the nrfAssignedRole attribute with a DN reference back to the Role object referenced in the message text. The message is nice, since you get the object being written to (the Identity) and the role being referenced.

[09/03/13 10:37:39.358]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.358]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Created resource request
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0

Third event is create a Resource Request, in the AppConfig container, under the RoleConfig and ResourceRequests containers. This is an nrfResourceRequest object. This is because the Role previously assigned included a Resource association. So this means, a request object to track the assignment of the Resource to the user is created. (As a side note, you will be SHOCKED at how large the AppConfig container under your User App driver can get!).

[09/03/13 10:37:39.360]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.360]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0

Now that we have created the Resource Request object, the RRSD driver will process it as our fourth status. This is why a moment ago I called it an object to track the Resource assignment, since I knew the RRSD driver was about to create the request and then process it. This normally would not work in a single driver, because loopback protection would prevent the driver from seeing the event it itself just created. But in this case, the driver is not really acting as a driver in the traditional sense. Rather it is doing a stack of things, directly. I do not think this is doing it via IDM actions, nor via LDAP, so I will assume it is using JClient to directly write to eDirectory. You can tell, since no events show up to indicate LDAP or IDM events anywhere to be seen. I think this whole process is all internal to the code in the RRSD, but I am happy we at least get some hints along the way as to what is being done, since it is not well documented what the process actually should follow. (I.e. How do you know something has gone wrong, if you do not know what it looks like to go right?)

Here we see the status, (nrfStatus attribute) change from 0 to 30, as it moves through the assignment of the Request. Look at the DN presented in the Message, since the actual name is a date stamp of 20130903103739 followed by a GUID like number, to make sure we have a unique object name c6d920b088ea4ef797f09d40385b1589 followed by a digit, 0 in this case probably to further differentiate and ensure uniqueness. So the CN is kind of meaningless, other than to tell you about when it was created. You can see from the DN that it is in the ResourceRequests container, under RoleConfig, which means it is as the name says, a request for a resource, as opposed to being in the Requests container, under the RoleConfig container, which would be a Role request. I think the naming is due to the evolution of the RBPM product. Roles predate the idea of Resources, so of course when the RoleConfig's Requests container was named, at the time it seemed like there would only be Roles in this tree structure. But when the time came to add Resources to the product, in the RBPM 3.7 version, I guess it made sense to add the Resource stuff under the RoleConfig container, instead of some sibling ResourceConfig style container. No real difference to either approach, but it kind of makes sense once you know that. I find understanding a bit of why they made decisions helps me understand the overall product better. But that may just be me.

[09/03/13 10:37:39.361]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.361]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0

For our fifth status event, the Role Request transitions from 0 to 30 again, which is odd, since that was actually our first status event in this list of events. So I am not entirely sure what is going on here, and why we get this message a second time. (I did double check, the DN is identical, the timestamp and the GUID).

[09/03/13 10:37:39.357]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.357]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned role to identity
                Role: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=RoleDefs\CN=Level10\CN=SAP-Portal-ECC-AccountRole
                Identity: O=tstidm\OU=Users\OU=Empl\CN=jsmith

Again we se that the Role has been assigned to the identity. Same as our second status event. Which is our sixth event.

[09/03/13 10:37:39.358]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.358]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Created resource request
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0

For the seventh event we get yet another duplicate from above. This is exactly the same result as earlier in the flow, the third event. Curiouser and curiouser.

[09/03/13 10:37:39.360]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.360]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 0 to 30
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0

Our eighth event is a repeat again, as the Resource Request moves from status of 0 to 30.

[09/03/13 10:37:39.361]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.361]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Added assigned resource to user
                Resource: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceDefs\CN=SAP-ESSPortal-UserAccount
                User: O=tstidm\OU=Users\OU=Empl\CN=jsmith

This ninth event looks like a new one, where it has assigned the resource to the user object. I wonder if the process requires two passes to assign it to the user, perhaps first you modify the Resource, then you modify the User? Maybe that would explain the double events? Not sure I buy that argument but perhaps.

[09/03/13 10:37:39.363]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.363]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=ResourceRequests\CN=20130903103739-c6d920b088ea4ef797f09d40385b1589-0

Now we see the Resource Request move to status from 30 to 50, which I believe is complete. I do know that 80 is one of the error states. It seems like documentation for all the various states would be handy, at least to me. If anyone knows where to find such a list, I would love to see it.

[09/03/13 10:37:39.364]:roles ST:Processing operation <status> for .
[09/03/13 10:37:39.364]:roles ST:
DirXML Log Event -------------------
     Driver:   \TEST_IDM\tstidm\services\driverSet\Role and Resource Service Driver
     Channel:  Subscriber
     Status:   Success
     Message:  Transitioned request status from 30 to 50
                DN: O=tstidm\OU=services\CN=driverSet\CN=UserApplication\CN=AppConfig\CN=RoleConfig\CN=Requests\CN=20130903103824-18698fd1250d46c3a2daebb95a368cbf-0
[09/03/13 10:37:39.366]:roles ST:End transaction.

Now that the resource has transitioned to complete at state 50, we see the Role Request that started this all off moving to state 50 as well.

As you can see the RRSD driver does a fair bit of work, and somewhat interesting work. I worry about the performance of the shim, but it uses Jclient directly, not IDM events to write back to eDirectory, so in theory that should be the faster approach. I would be very interested in approaches to optimize the performance of this shim, as you can see in an Roles Based model, you really require the Roles and Resources Service Driver (RRSD) running well and quickly.

Anyway, that about wraps up part two, stay tuned for the next episode where more Role granting stuff shall follow.