How to enable DEBUG logging to show SQL queries generated by RSA Identity Governance & Lifecycle

[#1]

Article Number

000039901

Applies To

RSA Product Set: RSA Identity Governance & Lifecycle
RSA Version/Condition: 7.2.1, 7.5.0
 

Issue

When troubleshooting performance issues RSA Customer Support may request detailed information on SQL queries that are executed when a certain activity is done.   This article describes a technique to capture SQL queries related to those activities in the aveksaServer.log file.

Resolution

WARNING:

• DEBUG level logging can produce a large volume of log data in a short time and may have an adverse effect on performance and may cause disk space issues.
• Use the following precautions when enabling DEBUG level logging:
  • If possible use TEST systems instead of PROD.
  • Ensure that DEBUG level logging is disabled at the end of the test session.
  • Enable DEBUG level logging only for the specific time of the test session and limit DEBUB level logging to the shortest interval possible.
  • Enable only the specific DEBUG facilities needed for the test case.

In order to ensure you can quickly enable and disable DEBUG level logging, it is recommended that the user log into RSA Identity Governance & Lifecycle in two separate browser instances, one to conduct the test, and the other to enable/disable the logging.  In order to ensure that the browser sessions are unique you can use separate machines, or different types of browsers on the same machine.

In the first browser:

• Navigate to Admin > Diagnostics > Logs tab 
• Disable Auto Refresh
• Click the Settings button
• Choose the Category org.hibernate.SQL
• Click the +Add button
• Select the logging level DEBUG.  
• Do NOT press OK

In the second browser:

• Prepare to run the test.  If the page is on a nested menu navigate to the page or tab before the page that you want to demonstrate the issue but do not display the actual page that has the issue.  Doing so may invalidate the test results. 

In the first browser:

• Click OK to apply the logging settings.

In the second browser:

• Execute the feature that has a performance issue.  
• Take a full-screen capture of the entire desktop showing the problem page with the request URL in the browser and the windows date and time of the request in the lower right corner. 

In the first browser, immediately:

• Click the Settings button.
• Click Reset to Defaults.
• Click OK.

Provide the following artifacts to RSA Customer Support for analysis:

• The screen capture showing the test with the time of the test.
• The log artifacts containing the aveksaServer.log for the time of the test.
• A 1 hour (or a 1/2 hour if it is available) AWR report that covers the time of the test.

Sample output from aveksaServer.log showing the type of information output at the DEBUG log level:

10/12/2021 16:05:06.336 DEBUG (default task-13633) [org.hibernate.SQL] select this_."ID" as ID1_12_0_, this_.NAME as NAME2_12_0_, this_.DESCRIPTION as DESCRIPTION3_12_0_, this_.NAMEDESCRIPTION as NAMEDESCRIPTION4_12_0_, this_.REQUESTOR_ID as REQUESTOR_ID5_12_0_, this_.REQUESTORNAME as REQUESTORNAME6_12_0_, this_.DELEGATE_ID as DELEGATE_ID7_12_0_, this_.DELEGATENAME as DELEGATENAME8_12_0_, this_.REQUEST_DATE as REQUEST_DATE9_12_0_, this_.COMPLETED_DATE as COMPLETED_DATE10_12_0_, this_.DELAY_DATE as DELAY_DATE11_12_0_, this_.NOTES as NOTES12_12_0_, this_.CURRENT_STATE as CURRENT_STATE13_12_0_, this_.TYPE as TYPE14_12_0_, this_.SESSION_ID as SESSION_ID15_12_0_, this_.SESSION_TIME as SESSION_TIME16_12_0_, this_.SOURCE_TYPE as SOURCE_TYPE17_12_0_, this_.SOURCE_OBJECT as SOURCE_OBJECT18_12_0_, this_.WORKFLOW_ID as WORKFLOW_ID19_12_0_, this_.UNDOWORKFLOW_ID as UNDOWORKFLOW_ID20_12_0_, this_.IS_UNDONE as IS_UNDONE21_12_0_, this_.IS_ALLDIRECTEVENT as IS_ALLDIRECTEVENT22_12_0_, this_."VISIBLE_TO_TARGET" as VISIBLE_TO_TARGET23_12_0_, this_.VERSION as VERSION24_12_0_, this_."CAS1" as CAS25_12_0_, this_."CAS2" as CAS26_12_0_, this_."CAS3" as CAS27_12_0_, this_."CAS4" as CAS28_12_0_, this_."CAS5" as CAS29_12_0_, this_."CAS6" as CAS30_12_0_, this_."CAS7" as CAS31_12_0_, this_."CAS8" as CAS32_12_0_, this_."CAS9" as CAS33_12_0_, this_."CAS10" as CAS34_12_0_, this_."CAI1" as CAI35_12_0_, this_."CAI2" as CAI36_12_0_, this_."CAI3" as CAI37_12_0_, this_."CAI4" as CAI38_12_0_, this_."CAI5" as CAI39_12_0_, this_."CAD1" as CAD40_12_0_, this_."CAD2" as CAD41_12_0_, this_."CAD3" as CAD42_12_0_, this_."CAD4" as CAD43_12_0_, this_."CAD5" as CAD44_12_0_, this_."CAU1" as CAU45_12_0_, this_."CAU2" as CAU46_12_0_, this_."CAU3" as CAU47_12_0_, this_."CAU4" as CAU48_12_0_, this_."CAU5" as CAU49_12_0_, this_."CAU1_NAME" as CAU50_12_0_, this_."CAU2_NAME" as CAU51_12_0_, this_."CAU3_NAME" as CAU52_12_0_, this_."CAU4_NAME" as CAU53_12_0_, this_."CAU5_NAME" as CAU54_12_0_, this_."ESCALATIONS" as ESCALATIONS55_12_0_, this_."ERRORS" as ERRORS56_12_0_, this_."EDITABLE" as EDITABLE57_12_0_, this_."CANCELLABLE" as CANCELLABLE58_12_0_, this_."FULFILLCANCEL" as FULFILLCANCEL59_12_0_, this_.FORM_ID as FORM_ID60_12_0_, this_.REQUESTFORMNAME as REQUESTFORMNAME61_12_0_, this_.ATTACHMENT_SET_ID as ATTACHMENT_SET_ID62_12_0_, this_.HASATTACHMENTS as HASATTACHMENTS63_12_0_, this_.REVIEW_DEF_ID as REVIEW_DEF_ID64_12_0_, this_.REVIEW_DATE as REVIEW_DATE65_12_0_, this_."REQUESTOR_ID" as REQUESTOR_ID66_12_0_, this_."DELEGATE_ID" as DELEGATE_ID67_12_0_ from HB_CHANGE_REQUESTS this_ where (this_.CURRENT_STATE<>? and (lower(this_.NAMEDESCRIPTION) like ? or lower(this_.REQUESTORNAME) like ?)) order by this_.REQUEST_DATE desc fetch first ? rows only
10/12/2021 16:05:06.339 DEBUG (default task-13633) [org.hibernate.SQL] select masterente0_."ID" as ID1_319_0_, masterente0_."USER_ID" as USER_ID2_319_0_, masterente0_."IDC_ID" as IDC_ID3_319_0_, masterente0_."IDC_GROUP_ID" as IDC_GROUP_ID4_319_0_, masterente0_."CREATION_DATE" as CREATION_DATE5_319_0_, masterente0_."DELETION_DATE" as DELETION_DATE6_319_0_, masterente0_."TERMINATION_DATE" as TERMINATION_DATE7_319_0_, masterente0_."EMAIL_ADDRESS" as EMAIL_ADDRESS8_319_0_, masterente0_."NAME" as NAME9_319_0_, masterente0_."FIRST_NAME" as FIRST_NAME10_319_0_, masterente0_."LAST_NAME" as LAST_NAME11_319_0_, masterente0_."SUPERVISOR_ID" as SUPERVISOR_ID12_319_0_, masterente0_."DEPARTMENT" as DEPARTMENT13_319_0_, masterente0_."TITLE" as TITLE14_319_0_, masterente0_."IS_TERMINATED" as IS_TERMINATED15_319_0_, masterente0_."IS_DELETED" as IS_DELETED16_319_0_, masterente0_."JOB_STATUS" as JOB_STATUS17_319_0_, masterente0_."BUSINESS_UNIT_ID" as BUSINESS_UNIT_ID18_319_0_, masterente0_."SUPERVISOR_NAME" as SUPERVISOR_NAME19_319_0_, masterente0_."VIOLATION_COUNT" as VIOLATION_COUNT20_319_0_, masterente0_."EXCEPTION_COUNT" as EXCEPTION_COUNT21_319_0_, masterente0_."AVAILABILITY_STATUS" as AVAILABILITY_STAT22_319_0_, masterente0_."JML_STATUS" as JML_STATUS23_319_0_, masterente0_."BACKUP_SUPERVISOR" as BACKUP_SUPERVISOR24_319_0_, masterente0_."BACKUP_SUPERVISOR_NAME" as BACKUP_SUPERVISOR25_319_0_, masterente0_."CUS_ATTR_USER_CAS_1" as CUS_ATTR_USER_CAS26_319_0_, masterente0_."CUS_ATTR_USER_CAS_2" as CUS_ATTR_USER_CAS27_319_0_, masterente0_."CUS_ATTR_USER_CAS_3" as CUS_ATTR_USER_CAS28_319_0_, masterente0_."CUS_ATTR_USER_CAS_4" as CUS_ATTR_USER_CAS29_319_0_, masterente0_."CUS_ATTR_USER_CAS_4_NAME" as CUS_ATTR_USER_CAS30_319_0_, masterente0_."CUS_ATTR_USER_CAS_5" as CUS_ATTR_USER_CAS31_319_0_, masterente0_."CUS_ATTR_USER_CAS_5_NAME" as CUS_ATTR_USER_CAS32_319_0_, masterente0_."CUS_ATTR_USER_CAS_6" as CUS_ATTR_USER_CAS33_319_0_, masterente0_."CUS_ATTR_USER_CAS_6_NAME" as CUS_ATTR_USER_CAS34_319_0_, masterente0_."UNIQUE_ID" as UNIQUE_ID35_319_0_ from V_MASTER_ENTERPRISE_USERS masterente0_ where masterente0_."ID"=?

Notes

The following additional DEBUG logging class can be added to the debug output to log pagination data associated with the SQL request.  It is not required for capturing the SQL.

com.aveksa.server.db.persistence.PersistenceServiceProvider