In the first part of this article I discussed I would be reading through and explaining what I see in an example of the Integration Activity trace in User Application. The SOAP function I am trying to call is createRole, so that when a Business Unit code is sent in via our HR driver we create a new Role for it, so that all users in that Business Unit (per HR data) will get assigned to the Role by a second policy we have. (Of course we hope that the timing of the objects is correct, but this is HR, so you never know!)

In the previous article, we got through much of the Start activity, which you would think is pretty simple, but it turns out can do some interesting things.

2016-06-28 15:37:36,312 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] persistStatus() activity=Start[Start], newStatus=Departing
2016-06-28 15:37:36,313 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] notifyDepart(), activity=Start[Start]
2016-06-28 15:37:36,313 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] applyChanges() activity=Start[Start]
2016-06-28 15:37:36,313 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] persistStatus() activity=Start[Start], newStatus=Idle

It is interesting to watch the many steps it takes to move from one activity to another. (A reason why it is hard to document what the trace should look like. So much stuff that is functionally noise. Of course, that is, until it actually goes wrong.)

2016-06-28 15:37:36,314 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] persistStatus() activity=Call CreateRole[Activity], newStatus=Arriving

My workflow here had literally three steps. Start, Call CreateRole, and Finish. So much noise.

2016-06-28 15:37:36,315 [pool-4-thread-10] INFO  com.novell.soa.af.impl.LogEvent- [RBPM] [Workflow_Forwarded] Initiated by System, Process ID: 316b78aa667942459f5691b05eb16ad0, Process Name: cn=Create Role,cn=RequestDefs,cn=AppConfig,cn=UserApplication,cn=dset,ou=idm
,ou=system,o=acme:25, Activity: Start, Recipient: cn=uaadmin,ou=admins,ou=system,o=acme

It is worth noting that the previous items were showing that they are at the TRACE level. The above item is at the INFO level. This is good, since it means, most classes log at the INFO level, so everyone, no extra logging enabled will see this message which is helpful. (My personal favorite log level is ALL, but the noise boss, the noise!!)

2016-06-28 15:37:36,317 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.ProcessImpl- [RBPM] startActivity() activity=Call CreateRole[Activity], newThread=false, pooled = false
2016-06-28 15:37:36,317 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] notifyArrive(), activity=Call CreateRole[Activity]
2016-06-28 15:37:36,317 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] process(), activity=Call CreateRole[Activity]
2016-06-28 15:37:36,317 [pool-4-thread-10] TRACE com.novell.soa.af.impl.activity.ActivityNode- [RBPM] persistStatus() activity=Call CreateRole[Activity], newStatus=Running
2016-06-28 15:37:36,318 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.activity.IntegrationActivity- [RBPM] (pool-4-thread-10), processing count = 0

To this point, it all makes sense, the various steps it takes to start an activity going.

2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerNrfRequest - Started
2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerNrfRequest - Done
2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerNrfResourceRequest - Started
2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerNrfResourceRequest - Done
2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerAttestation - Started
2016-06-28 15:37:36,326 [pool-4-thread-10] TRACE com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] registerAttestation - Done

But here it gets a bit odd, since I cannot find these values in my PRD. The WSDL does not use these names, my flowdata mapping does not use these names, and in fact the next item in the log is the first item in my Pre Activity mapping (Using a named password from a GCV value). I wonder if this is detritus from something else happening in the User Application that got interlaced with my work, but it is hard to know. The pool and thread values look like they should be related. I checked the Properties of the action (Just a display name, WSDL file, and some time out values), I checked the Data Item Mapping pre and post activity and no sign of this stuff. If anyone has a clue why these might be here, please leave a comment.

2016-06-28 15:37:36,338 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: GCV.getValueForNamedPassword('service-account-pwd')

This is useful to know. In principle, in the engine, when you use a GCV value, there are multiple tokens and places you can use it. There is a GCV type called password-ref, which really holds the name of a Named Password which has the encrypted password stored. However in Policy, if you just use the GCV name, it knows to resolve the GCV to the Named Password name and return the actual value you want. Of course, you could just use a Named Password token, and for the name of the password, use the GCV.

In User Application you can use GCV's through a simple GCV.get() function which is great. However, it is not as smart as the engine side, and if the GCV is of the type password-ref then you have to use a different function GCV.getValueForNamedPassword('name-of-named-password'). Of course this should be a GCV and Named Password on the User Application driver itself. In theory this is supposed to work with driver set values but I am doubtful of how well that inheritance works in this location. It works perfect in the engine, but my experience has not been quite so good in the User Application.

2016-06-28 15:37:36,339 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] Calling extended operation (GetDriverGCVResponse) lCtx.extendedOperation(new GetDriverGCVRequest(cn=UserApplication,cn=dset,ou=idm,ou=system,o=acme, service-account-pwd
));
2016-06-28 15:37:36,368 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] GCV definition is: null
2016-06-28 15:37:36,368 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: null

You can see it tried to request the value and it was not returned, instead it was null. In fact, I think when I first testing this for this log, in fact I was relying on the fact it was a Driver Set level GCV and Named Password. Who wants to maintain this all over the place and the inheritance works great in the engine. Alas.

As a side note, in order for Named Passwords to be retrievable from within workflows, there is a GCV on the User Application, with a specific name you need to enable/add. It must be named "allow-fetch-named-passwords" and the value must be "true". The later User Application packaged drivers seem to ship with the value defined but not enabled. Alas, in order for it to take affect, you not only need to restart the User Application driver, you also should restart the User Application web app, which can take some time. This is also true when you make changes. I cannot quite figure out the specifics of when the web app MUST be restarted vs when it must not, but it is just easier to restart it than waste time fighting the issue.

2016-06-28 15:37:36,368 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: GCV.get('UAProvURL')   '/role/service'

My next item in the Pre-Activity is to get the URL for the SOAP endpoint. I hate hard coding strings like this, especially URL's which invariably change. Thus I used a GCV for the basic User App URL and appended the text string to get to the SOAP endpoint for Role operations. (There is a resource/service and other endpoints. If you go those URL's and append ?WSDL you should be able to see and download the WSDL XML file. Open that in SOAP UI a free tool for doing SOAP work, and you can read what the various functions are available.

2016-06-28 15:37:36,368 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] Calling extended operation (GetDriverGCVResponse) lCtx.extendedOperation(new GetDriverGCVRequest(cn=UserApplication,cn=dset,ou=idm,ou=system,o=acme, UAProvURL));

This looks like the same function call from the password one, but you will note it specifies the object DN of the User App driver, and the name of the GCV. This leads me to think it may not inherit properly, unless this specific function in the engine knows how do the inheritance check, and always report back a single value. I.e. Leave the hard work in the engine. But I am not certain.

2016-06-28 15:37:36,393 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] GCV definition is: <?xml version="1.0" encoding="UTF-8"?><nds dtdversion="4.0" ndsversion="8.x">
        <source>
                <product edition="Advanced" version="4.5.3.0">DirXML</product>
                <contact>NetIQ Corporation</contact>
        </source>
        <output>
                <status level="success">Global Configuration Values<configuration-values>
                                <definitions>
                                        <definition display-name="User Application Provisioning Services URL" name="UAProvURL" type="string">
                                                <value xml:space="preserve">https://corp-idmadm101.acme.org:8443/IDMProv</value>
                                        </definition>
                                </definitions>
                        </configuration-values>
                </status>
        </output>
</nds>
2016-06-28 15:37:36,396 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: https://corp-idmadm101.acme.org:8443/IDMProv/role/service

We see that the User Application made a call to the Engine, and got back some XDS. I never tracked down what the query looked like, but that might be fun one day when I have time. But you can see that a special Status event came back with the <configuration-values> node and ours listed there. Notice it did not pull back ALL the GCV values, only the one we requested in XML format. If you think about that, it makes sense and is clever, since there are many types of GCVs not all of whom's value is a simple string. (List, Structured, etc). It seems like this approach potentially offers more flexibility.

Then in the next line you see it appended my text string, and has a full and complete result value. All is good so far, though we will note the password seems to be missing.

2016-06-28 15:37:36,396 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: GCV.get('service-account-dn')
2016-06-28 15:37:36,396 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] Calling extended operation (GetDriverGCVResponse) lCtx.extendedOperation(new GetDriverGCVRequest(cn=UserApplication,cn=dset,ou=idm,ou=system,o=acme, service-account-dn)
);
2016-06-28 15:37:36,422 [pool-4-thread-10] TRACE com.novell.soa.af.impl.scripting.GCVScript- [RBPM] GCV definition is: <?xml version="1.0" encoding="UTF-8"?><nds dtdversion="4.0" ndsversion="8.x">
        <source>
                <product edition="Advanced" version="4.5.3.0">DirXML</product>
                <contact>NetIQ Corporation</contact>
        </source>
        <output>
                <status level="success">Global Configuration Values<configuration-values>
                                <definitions>
                                        <definition display-name="User Application Provisioning Service Account DN" dn-space="dirxml" dn-type="ldap" name="service-account-dn" type="dn">
                                                <description>If a Role or Resource provisioning request is initiated by this service account, then any approvals or provisioning workflows associated with this role or resource are bypassed.</description>
                                                <value>CN=uaadmin,OU=admins,OU=services,O=acme</value>
                                        </definition>
                                </definitions>
                        </configuration-values>
                </status>
        </output>
</nds>
2016-06-28 15:37:36,424 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: CN=uaadmin,OU=admins,OU=services,O=acme

Again, a GCV call that just works. Lovely.

2016-06-28 15:37:36,424 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: flowdata.get('Start/request_form/roleContainer')
2016-06-28 15:37:36,425 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: 

Here we try to do a mapping of data from the Flowdata XML structure that has the Form data. In the Start activity's Data Item Mapping view, in the Post-Activity page, we should have done a Map All so that each form field is mapped to a node in the XML Flowdata object. In this sample, you can see I forgot to do that, since the result is empty. When you do that mapping, it creates the node if it is missing implicitly.

Personally, I think an example of what the Flowdata XML looks like in its entirety after an example PRD would be really helpful in the documentation in terms of visualizing the issue. I know I do it wrong but I work on XML by imaging what it looks like in text, not in the DOM model.

2016-06-28 15:37:36,425 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: flowdata.get('Start/request_form/roleDescription')
2016-06-28 15:37:36,426 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: 
2016-06-28 15:37:36,426 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: flowdata.get('Start/request_form/roleName')
2016-06-28 15:37:36,427 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: 
2016-06-28 15:37:36,427 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: flowdata.get('Start/request_form/roleCategory')
2016-06-28 15:37:36,428 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: 
2016-06-28 15:37:36,428 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: flowdata.get('Start/request_form/roleLevel')
2016-06-28 15:37:36,429 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: 
2016-06-28 15:37:36,429 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating source expression: 'false'
2016-06-28 15:37:36,429 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: false

Our target column is labeled Web Services Input Field, and is meant to define, via XPATH, where we wish to copy this piece of data. That looks like this for the roleDescription example above.

Envelope/Body/createRoleRequest/role/description

You can see in the trace that my Source Expression was:

flowdata.get('Start/request_form/roleDescription')

Thus I use ECMA to get the value (which allows me access to all the tools User App provides) but I then use XPATH to paste it, which is confusing at first if you are not expecting it.

Now why did the last one work, with a value of false? Well my source expression was as it notes in the trace, 'false', that is, a literal string to be evaluated, not read from anywhere so that worked.

Now that it has built up all the data from the Source Expressions into memory, it will proceed to copy that by evaluating the Target Expressions.

2016-06-28 15:37:36,429 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/@_serverUrl_').setValue("https://corp-idmadm101.acme.org:8443/IDMProv/role/service")

I noted that in this case, the target is XPATH, so we see it uses an ECMA function, that I did not have to define, it is implied, and builds the proper ECMA to do the work needed.

2016-06-28 15:37:36,431 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6

As I noted earlier about results being undefined, they look like an error, but I think are really just saying they are being stored in some kind of object that has no real visual, text representation, so this is how you trace it to text. Thus this undefined, while error looking, is not in fact, an error. This by itself would be great to have in the documentation I think. A list on error looking non-errors.

One thing to note, in its absence, which is tricky to catch, is that while the first line in the map was to get the Password from a Named Password, and it came back null on the Source Expression side, it is not even evaluated on the Target Expression side. Yet below we will see that some of the blank values returned are evaluated. I suspect this has to do with the difference between empty and null. If you look at the password example, the result is: null. In the empty cases it is just result: and then blank.

This is a subtle point you can easily miss, and I think this has some interesting consequences in how you design your workflows.

2016-06-28 15:37:36,431 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/@_userid_').setValue("CN=uaadmin,OU=admins,OU=services,O=acme")

Here you a value being written to an XML attribute (_userid_) of the Envelope node. This is delivered by the Integration Activity. There is buried deeper inside it, some ECMA that reads this, and copies it into the proper field to set the proper settings that are needed. The three examples of this are userid and password, which get Base 64 encoded and set as an Authentication header inside the Integration Activity and in the URL setting, ECMA is used to retrieve the URL from the Envelope data we pass in.

The entire User Application seems like a conglomeration of widgets that pass data from one to another, through copying it around. Once you wrap your head around that it becomes more understandable.

2016-06-28 15:37:36,431 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,431 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/container').setValue("")

Just above we saw what happens when you have a value. Here we have a value of "" which is empty. We still get the same Undefined result, and it is still not really an error per se. It is effectively an error, since I meant to pass in data, but it is not an error since it is not required by this field to have a value.

2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/description').setValue("")
2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/name').setValue("")
2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,432 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/roleCategoryKeys/categorykey/categoryKey').setValue("")
2016-06-28 15:37:36,434 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,434 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/roleLevel').setValue("")
2016-06-28 15:37:36,435 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6
2016-06-28 15:37:36,435 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] evaluating target expression: Input.createXPath('Envelope/Body/createRoleRequest/role/systemRole').setValue("false")
2016-06-28 15:37:36,435 [pool-4-thread-10] DEBUG com.novell.soa.af.impl.core.DataItemEvaluator- [RBPM] result: com.novell.soa.script.mozilla.javascript.Undefined@1b36f5f6

This goes on through all the values in my mapping, one by one. Some have values (The literal string example) others do not (the ones I forgot to map from the form in the post activity of the Start action. When it is done, it will build the final SOAP document to send, which is great to have trace out since you can copy and paste it into SOAP UI to test with. However this is a good stopping point for this article. Stay tuned for part 3 where we continue down this intensely boring path, which is only of interest when you have an issue and do not know what success looks like vs a failure.