vRealize Orchestrator: Standardised Logger Action

I have updated this page on 22nd Jan 2019 to introduce enhancements over the original logging action. I have converted the original function calls to an object based approach. This allows a logger object to be used, which looks cleaner and is initialised once. I have also introduced JSDoc documentation styles into my code.

One bugbear that I have with vRO is the limitation around system (console) logging. There is currently no way to dynamically output the name of an action or sub-workflow (see end of the post). I like to see exactly which action or workflow is executing code. This makes it easier for me to troubleshoot a defect, when I am looking at the output logs.

It is possible to use ‘workflow.name’ or ‘this.name’ inside an action, but this will always be set to the name of the initial workflow that was executed. This is because the workflow object is implicitly passed to the action that is called. The result, is that it will look like all the code is executing from the workflow (which is technically true, but I needed more granularity).

I therefore created a standardised way that workflow and action logging should be handled. This is achieved by using an action that will actually handle all the logging for me. The idea is, that an action or workflow will call the ‘logger‘ action, providing some parameters, that allow for a consistent and useful logging experience.

All code that I have provided or talked about in this post can be downloaded as a vRO package for your consumption here.

Here is some example output of the logger action in use:

[I] [Action: startDataCollectionOnComputeResource]: The inventory data collection process on compute resource: 78e8377a-c6d8-4c95-acf9-857123e627eb has started.
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: The inventory data collection task is not running.
[I] [Action: getDataCollectionResultStatus]: Retrieving the inventory data collection result status.
[I] [Action: getDataCollectionResultStatus]: Data collection succeeded at: Sat Feb 17 2018 18:15:32 GMT-0000 (UTC)
[I] [Action: getComputeResourceEntityByName]: Retrieving vCAC Compute Resource entity with name: CLS-TenantA-001
[I] [Action: getComputeResourceEntityByName]: Found vCAC Compute Resource entity: CLS-TenantA-001 with ID: 78e8377a-c6d8-4c95-acf9-857123e627eb
[I] [Action: getHostIDFromComputeResourceEntity]: Retrieving Host ID for Compute Resource Entity: CLS-TenantA-001
[I] [Action: getHostIDFromComputeResourceEntity]: Found Host ID for Compute Resource Entity:78e8377a-c6d8-4c95-acf9-857123e627eb
[I] [Action: getDataCollectionEnabledStatus]: Checking if the inventory data collection collector is enabled.
[I] [Action: getDataCollectionEnabledStatus]: Data collection collector is enabled for: inventory
[I] [Action: getDataCollectionRunningStatus]: The inventory data collection task is not running.
[I] [Action: startDataCollectionOnComputeResource]: Starting inventory data collection on compute resource: 78e8377a-c6d8-4c95-acf9-857123e627eb
[I] [Action: startDataCollectionOnComputeResource]: The inventory data collection process on compute resource: 78e8377a-c6d8-4c95-acf9-857123e627eb has started.
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: There is currently a inventory data collection task running...
[I] [Action: getDataCollectionRunningStatus]: The inventory data collection task is not running.
[I] [Action: getDataCollectionResultStatus]: Retrieving the inventory data collection result status.
[I] [Action: getDataCollectionResultStatus]: Data collection succeeded at: Sat Feb 17 2018 18:15:32 GMT-0000 (UTC)

You can clearly see that the outputs are from an ‘Action‘ followed by the name of the action and then the actual log message.

Below is the logger action that I am using (this is the only action I have that does not conform to my template).

/**
 * This action creates a Logger object that can be used to standardise the log output in workflows.
 * This provides greater visibility into what code is executing and where, which makes troubleshooting easier.
 * @author Gavin Stephens <gavin.stephens@simplygeek.co.uk>
 * @version 1.1.0
 * @function logger
 * @param {string} logType - The component type i.e. Action or Workflow.
 * @param {string} logName - The Action or Workflow name.
 * @returns {*} The Logger object.
 */

function Logger(logType, logName) {
    this.type = logType;
    this.name = logName;
    this.log = function (logMsg) {
        System.log("[" + this.type + ": " + this.name + "] " + logMsg);
    };
    this.warn = function (warnMsg) {
        System.warn("[" + this.type + ": " + this.name + "] " + warnMsg);
    };
    this.error = function (errMsg, exception) {
        System.error("[" + this.type + ": " + this.name + "] " + errMsg);
        if (exception) {
            throw "[" + this.type + ": " + this.name + "] " + errMsg + " " + exception;
        } else {
            throw errMsg;
        }
    };
    this.debug = function (debugMsg) {
        System.debug("[" + this.type + ": " + this.name + "] " + debugMsg);
    };

}

return Logger;

The action takes 2 parameters:

• logType – Should be set to ‘Action‘ or ‘Workflow‘.
• logName – Should be set to the ‘Action‘ or ‘Workflow‘ name.

To use this Logger object in any of my other actions, I place the following lines of code inside the variable block.

var logType = "Action"; // The callee type.
var logName = "actionName"; // This must be set to the name of the action.
var Logger = System.getModule("com.simplygeek.library.util").logger(logType, logName);
var log = new Logger(logType, logName);

And simply use any of the following lines anywhere that you want to perform some form of logging output.

log.log("log message");
log.warn("warning message");
log.error("error message"); // without exception
log.error("error message", exception); // with exception
log.debug("debug message");

You can see that I am passing 2 parameters to the ‘logger‘ function, which matches the inputs for the logger action that is being called.

The ‘log.error‘ method can also include an optional exception, which will log the error and also throw an exception. I use this approach to enforce standardisation in situations where developers would often throw an exception without the error (which would hide the error messages if the exception was being handled).

There is one overhead that you are probably thinking about and that is, yes, you need to manually set the variable ‘logName‘ to match the name of the action itself. This seems a bit dull at first, but in my experience, action names very rarely change.

Identifying the action name from the underlying Rhino function

I mentioned at the start of this post that there is no way to dynamically set the name of the action. There is, however, a way in which this can be achieved using the following:

var logName = arguments.callee.name.substr(6);

All vRO actions are just functions implemented in Rhino, with a prefix applied. The above code retrieves the function name and extracts the action name from it.

However, it is highly recommended that you do not use this as it has been restricted in future releases of ECMAScript, could potentially be removed from vRO and is very costly to execute, which is going to slow your workflows down considerably.

I hope this is useful and as always, any suggestions or comments then please let me know.