Enabling duration logging of Aggregation and Provisioning events on a VA Host

Version 4

    Introduction

     

    IdentityNow virtual appliance (VA) hosts have the ability to log how long individual provisioning events take to process.  This information is useful to organizations who are trying to track down issues related to the speed of provisioning processing.  This logging feature allows us to quantify how long provisioning to the "last mile" over the wire takes.  It also provides transparency for when a VA hosts's Cloud Connector Gateway (CCG) process receives a provisioning request from the IdentityNow service.

     

    This change needs to be applied separately to each VA host in a cluster.  If you have 3 VA hosts in your cluster then you will need to SSH into all three of them and apply these changes separately.  These changes can be applied as the 'sailpoint' user; they do not require special support from SailPoint to enable access.

     

    This document is an extension of examples shown in the following Compass document:

     

         https://community.sailpoint.com/docs/DOC-9816

     

    It would be entirely reasonable for this content to end up as a section in that document.

     

    Technical Overview

     

    The configuration settings for IdentityNow's CCG process are stored in the following text file on the VA host:

     

    /home/sailpoint/ccg/log4j.properties

     

    The contents of that file should resemble the following screen capture:

     

    Screen Shot 2018-10-10 at 1.22.01 PM.png

     

    You may need to change the ownership of the /home/sailpoint/ccg directory before proceeding, as noted in DOC-9816 above:

     

    sudo chown -R sailpoint /home/sailpoint/ccg  

     

    The following lines should be added to the bottom of the log4j.properties file, using your text editor of choice:

     

    # Enable progress and timing benchmark information to support Services.
    log4j.logger.sailpoint.gateway.accessiq.AggregateHandler=info
    log4j.logger.sailpoint.gateway.accessiq.ProvisionHandler=info
    log4j.logger.sailpoint.gateway.accessiq.StreamingAggregationHandler=info

     

    Once these lines are added the CCG service needs to be restarted to apply the configuration change:

     

    sudo systemctl restart ccg 

     

    Quick Configuration Snippet

    The following snippet of commands will carry out all of these actions in copy/paste friendly format:

     

    cd /home/sailpoint
    sudo chown -R sailpoint /home/sailpoint/ccg  
    cp /home/sailpoint/ccg/log4j.properties /home/sailpoint/log4j.properties
    echo "# Enable progress and timing benchmark information to support Services."  >> log4j.properties
    echo "log4j.logger.sailpoint.gateway.accessiq.AggregateHandler=info"            >> log4j.properties
    echo "log4j.logger.sailpoint.gateway.accessiq.ProvisionHandler=info"            >> log4j.properties
    echo "log4j.logger.sailpoint.gateway.accessiq.StreamingAggregationHandler=info" >> log4j.properties
    cp /home/sailpoint/log4j.properties /home/sailpoint/ccg/log4j.properties  
    sudo systemctl restart ccg 
    cd -

     

     

    Watching Live Provisioning Events

     

    Once the changes have been applied you can "tail" or follow the CCG log file with the following command to watch provisioning events as they come through a VA host.  Note: it is random which VA host in a cluster will process any given provisioning event because the load-share processing of requests.  You will need a shell open to all of your VA hosts if you want to watch for a specific provisioning event "live".

     

    tail -f /home/sailpoint/log/ccg.log | grep -e Provisioning -e "Aggregation progress" | jq -r .message

     

    This will produce output like the following for provisioning events:

     

    Provisioning [Modify] for account [235548] processed for 73 msecs.
    Provisioning [Create,password] for account [232585] starting.
    Provisioning [Create,password] for account [232585] processed for 81 msecs.
    Provisioning [Modify] for account [235548] processed for 182 msecs.

     

    Provisioning operations include Create, Modify, Delete, Lock, and Unlock. Lines that include ",password" means a password was initially set or modified on the account during the operation.

     

    This will produce output like the following for Aggregation processing:

     

    Aggregation progress 'Acme Oracle eDirectory [source-4551]': 50 accounts submitted after 254 msecs, 4800 total
    Aggregation progress 'Acme Oracle eDirectory [source-4551]': 50 accounts submitted after 174 msecs, 4850 total
    Aggregation progress 'Acme Oracle eDirectory [source-4551]': 6 accounts submitted after 2 msecs, 4856 total
    Aggregation progress 'Acme Oracle eDirectory [source-4551]': 0 accounts submitted after 0 msecs, 4856 total

     

    IdentityNow posts accounts up to the service in blocks or pages of 50 accounts in size.  The amount of time taken to process each each page is logged, which allows you to determine the rate of processing of the aggregation.  The last page often has fewer than 50 accounts and the last log at the end of an aggregation reports 0 accounts when the aggregation is complete.