Custom logging in a rule/workflow step

[#1]

Oftentimes, it's difficult to figure out which SailPoint class to enable logging on when debugging a rule.

Plus turning on logging for a connector in order to debug a rule, has the added effect of turning on all other logging

statements for the connector as well which can make it difficult to isolate the log statements for your rule.

Here is a trick to do your own per-rule custom logging:

1. Make sure to import the apache log4j Logger object

import org.apache.log4j.Logger;

2. Create a custom logger in your rule or workflow code:

Logger  mylogger = Logger.getLogger("com.yourcompany.projectname.FinanceCorrelationRule ");

3. Use this logger object for all your logging in the rule:

mylogger.debug("This is a debug message");     mylogger.info("This is an info message");

4. Using your log4j.properties file, control logging per rule by enabling or disabling logging:

log4j.logger.com.yourcompany.projectname.FinanceCorrelationRule =<loglevel>

[joseph_hobbs]

In the code snippet to create a custom logger, should the call be "LoggerFactory.getLogger()" versus "Logger.getLogger()"?  Thanks!

[DerekHackbardt]

Chris's info is correct... you just have to remember to have "import org.apache.log4j.Logger;" in the rule and it works great!

[chris_hajdu]

Logger.getLogger() is calling the static method org.apache.log4j.Logger.getLogger(String name) which is defined as:

Retrieve a logger named according to the value of the name parameter.

http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Logger.html

[joseph_hobbs]

That explains it.  I had "org.slf4j.Logger" on the brain for some reason...  Thanks for the clarification!

[#6]

I have a question about logging in the workflow.

When we use this kind of logging mechanism in the workflow, do we need to define Logger log = Logger.getLogger("com.yourcompany.projectname.WorkflowName") object in all the steps of the workflow or there is any specific step to define the Logger object so that it can be used in all the steps of the workflow? The reason I am asking this is because my logging is not working in all the steps of the workflow. It's only working in the step I defined the Logger object.

Here is my workflow. The logging in step "Logging" is working just fine but the logging in step "InactivateIdentity" is not.

NOTE: A call to method inactivateIdentity() inside Step "InactivateIdentity" is defined in a rule which is referenced via RuleLibraries.

<?xml version='1.0' encoding='UTF-8'?>

<!DOCTYPE Workflow PUBLIC "sailpoint.dtd" "sailpoint.dtd">

<Workflow explicitTransitions="true"  libraries="Identity" name="MRO Suspend Subprocess" type="Subprocess">

  <Variable input="true" name="trace"/>

  <Variable input="true" name="debug"/>

  <Variable input="true" name="identityName"/>

  <Variable input="true" name="identityDisplayName"/>

  <Description>This is a subprocess to Suspend the Identity. This subprocess can be triggered from different places like Terminate Identity Quick Link, User Separation Life Cycle Event, etc.</Description>

<RuleLibraries>

  <Reference class="sailpoint.object.Rule" name="MRO RuleLibrary Identity Utils"/>

</RuleLibraries>

  <Step icon="Start" name="Start" posX="50" posY="50">

    <Description>Start of the workflow</Description>

    <Transition to="Logging"/>

  </Step>

  <Step icon="Task" name="Logging" posX="179" posY="212">

    <Description>Print some debug information</Description>

    <Script>

      <Source>

        import sailpoint.object.*;

        import org.apache.log4j.Logger;

        Logger log = Logger.getLogger("mro.workflow.MROSuspendSubprocess");

        log.debug("MRO Suspend Subprocess Workflow: IdentityName=" + identityName);

        log.debug("MRO Suspend Subprocess Workflow: IdentityFullName=" + identityDisplayName);

        log.debug("MRO Suspend Subprocess Workflow: Launcher=" + launcher);

      </Source>

    </Script>

    <Transition to="InactivateIdentity"/>

  </Step>

  <Step icon="Task" name="InactivateIdentity" posX="328" posY="52">

    <Description>Inactivate the Identity</Description>

    <Script>

      <Source>

        log.debug("MRO Suspend Subprocess Workflow: Inactivating Identity with IdentityName=" + identityName);

        inactivateIdentity(identityName);

        log.debug("MRO Suspend Subprocess Workflow: Identity with IdentityName=" + identityName + " inactivated successfully.");

      </Source>

    </Script>

    <Transition to="Finish"/>

  </Step>

  <Step icon="Stop" name="Finish" posX="1299" posY="53">

    <Description>End of the workflow</Description>

  </Step>

</Workflow>

[gaurav_jain]

I guess it has to be workflow variable and not a local variable.

Thanks,

Gaurav

[chris_hajdu]

Correct:

Ideally create a workflow variable called mylogger for example.

In the definition for that variable do it like so:

<Variable initializer="script:   import org.apache.log4j.Logger; return Logger.getLogger(&quot;mytest.mytest&quot;);" name="mylogger"/>

To use it later in a step:

<Step condition="ref:debug" icon="Message" name="DebugStep" posX="150" posY="50">

    <Description>This step will output debug information regarding the workflow.</Description>

    <Script>

      <Source>

mylogger.debug("This is debug!!!!!"); </Source>

    </Script>

    <Transition to="UserForm"/>

  </Step>

[joseph_hobbs]

As a general rule of thumb, I use different custom loggers for each step in the workflow.  This allows me to identify which step actually generated the message.  You can just toss an additional level on the logger name, using 'com.yourcompany.projectname.WorkflowName.StepName'.  That allows you to focus your logging on a specific step (if necessary), but also lets you enable logging across the board at the workflow level as well...

[#10]

Joseph,

That's what I end up doing as well and I'm liking it.

-Amit

[#11]

Joseph,

I fall into a different issue by using additional level on the logger. If you see my workflow example above I am referencing a "MRO RuleLibrary Identity Utils" library to call inactivateIdentity() method. I also have logger defined inside that Rule Library. It was working just fine before I added additional level logging but now it has stopped logging. Could you tell what possibly be the issue? I am pasting the Rule library code below.

<RuleLibraries>

  <Reference class="sailpoint.object.Rule" name="MRO RuleLibrary Identity Utils"/>

</RuleLibraries>

<?xml version='1.0' encoding='UTF-8'?>

<!DOCTYPE Rule PUBLIC "sailpoint.dtd" "sailpoint.dtd">

<Rule language="beanshell" name="MRO RuleLibrary Identity Utils">

  <Source>

    <![CDATA[

import java.util.HashMap;

import java.util.Iterator;

import java.util.Map;

import org.apache.commons.lang.ObjectUtils;

import org.apache.commons.lang.RandomStringUtils;

import org.apache.log4j.Logger;

import sailpoint.api.IdentityService;

import sailpoint.api.SailPointContext;

import sailpoint.object.Custom;

import sailpoint.object.Application;

import sailpoint.object.Filter;

import sailpoint.object.Identity;

import sailpoint.object.Link;

import sailpoint.object.QueryOptions;

import sailpoint.object.Attributes;

import sailpoint.tools.GeneralException;

import java.util.Iterator;

  Logger log = Logger.getLogger("mro.ruleLibrary.IdentityUtils");

  static String SUSPENDED = "Suspended";

  static String IMMEDIATE_TERMINATION_KEY = "immediateTermination";

  static String PERSONNEL_STATUS_KEY = "personnelStatus";

  public static void inactivateIdentity(String identityName) {

    log.debug("inactivateIdentity() called for Identity [" + identityName + "]");

    try {

      Identity identity = context.getObjectByName(Identity.class, identityName);

      if (identity != null) {

        log.debug("Identity found. Name [" + identity.getDisplayName() + "]");

        identity.setInactive(true);

        context.saveObject(identity);

        context.commitTransaction();

      } else {

        log.debug("Identity with name [" + identityName + "] not found in the system.");

      }

      log.debug("inactivateIdentity() call for Identity [" + identityName + "] completed successfully!");

    } catch (GeneralException e) {

      log.error("Exception during inactivateIdentity() call for identity [" + identityName + "]", e);

    }

  }

  public static void markIdentityAsSuspended(String identityName) {

    log.debug("markIdentityAsSuspended() called for Identity [" + identityName + "]");

    try {

      Identity identity = context.getObjectByName(Identity.class, identityName);

      if (identity != null) {

        log.debug("Identity found. Name [" + identity.getDisplayName() + "]");

        identity.setAttribute(IMMEDIATE_TERMINATION_KEY, true);

        identity.setAttribute(PERSONNEL_STATUS_KEY, SUSPENDED);

        context.saveObject(identity);

        context.commitTransaction();

      } else {

        log.debug("Identity with name [" + identityName + "] not found in the system.");

      }

    log.debug("markIdentityAsSuspended() call for Identity [" + identityName + "] completed successfully!");

    } catch (GeneralException e) {

      log.error("Exception during markIdentityAsSuspended() call for identity [" + identityName + "]", e);

    }

  }

    ]]>

  </Source>

</Rule>