Correlation of related events in logs

Log correlation is the process of analyzing a set of related events. The analysis is based on rules that are used to interpret the event data. When log correlation is enabled, you can use the correlation ID to identify the UI request, cron task action, MXSCRIPT object, or REST call that produced a log entry.

When the correlation ID is enabled, descriptive data is added to the beginning of the log file. The field is also available to automate the monitoring on long-running cron tasks and allows filtering of cron task history for faster analysis.

Correlation ID

When log correlation is enabled, identify the user interface (UI) request, cron task action, MXSCRIPT, or REST call that produced a log entry by using the correlation ID. All log entries for a single UI request or cron task action have the same correlation ID. The unique correlation ID applies to any group of log entries such as SQL logs or application logs.

The correlation ID is in the format of [CID-TYPE-NUMBER]. The type can be CRON, UI, MXSCRIPT, or REST. The number ensures uniqueness. The server name is also included when log correlation is enabled. For log entries that are not yet correlated, the correlation ID field in the log is empty. The server name field is empty for logs that are generated before the server name is available.

To enable log correlation, in the System Properties application, add the mxe.logging.CorrelationEnabled property.

To enable UI request correlation, in the System Properties application, add the mxe.webclient.logging.CorrelationEnabled property.

Example

The following example shows the correlation log for the UI requests that are associated with an SQL statement that is being debugged:

Interpret the log file

06 Jun 2012 16:12:38:360 [INFO] [MXServer] [CID-UI-993] Correlation started.
06 Jun 2012 16:12:38:534 [INFO] [MXServer] [CID-UI-993] BMXAA6719I - USER = (WILSON) SPID = 
(137) app (WOTRACK) object (WORKORDER) : select * from workorder  where (woclass in (select 
value from synonymdomain where domainid = 'WOCLASS' and maxvalue in ('WORKORDER','WOACTIVITY'))  
and historyflag = 0 and istask = 0 and siteid = 'BEDFORD')
06 Jun 2012 16:12:38:546 [INFO] [MXServer] [CID-UI-993] BMXAA6719I - USER = (WILSON) SPID = 
(149) app (WOTRACK) object (WORKORDER) : select * from workorder  where (workorderid = 202)
06 Jun 2012 16:12:38:582 [INFO] [MXServer] [CID-UI-993] BMXAA6719I - USER = (WILSON) SPID = 
(27) app (WOTRACK) object (WORKORDER) : select * from workorder  where (workorderid = 202)
06 Jun 2012 16:12:38:717 [INFO] [MXServer] [CID-UI-993] BMXAA6719I - USER = (WILSON) SPID = 
(20) app (WOTRACK) object (WORKORDER) : select count(*) from workorder  where 
(woclass in (select value from synonymdomain where domainid = 'WOCLASS
' and maxvalue in ('WORKORDER','WOACTIVITY'))  and historyflag = 0 and istask = 0 and siteid 
= 'BEDFORD')
06 Jun 2012 16:12:38:998 [INFO] [MXServer] [CID-UI-993] Correlated data: BEGIN UISessionId:3 
Event:loadapp AppName:autoscript UserId:wilson UIClientIP:127:0:0:1 ElapsedTime:638 ms  END

06 Jun 2012 16:12:44:589 [INFO] [MXServer] [CID-UI-994] Correlation started.
06 Jun 2012 16:12:44:597 [INFO] [MXServer] [CID-UIASYNC-995] Correlation started.
06 Jun 2012 16:12:44:634 [INFO] [MXServer] [CID-UIASYNC-995] BMXAA6719I - USER = (WILSON) 
SPID = (149) app (WOTRACK) object (WORKORDER) : select * from workorder  where ((woclass in 
(select value from synonymdomain where domainid = 'WOCLASS' and maxvalue in ('WORKORDER',
'WOACTIVITY'))  and historyflag = 0 and istask = 0 and siteid = 'BEDFORD')) and ((status like 
'%WAPPR%'))
06 Jun 2012 16:12:44:641 [INFO] [MXServer] [CID-UIASYNC-995] Correlated data: 
BEGIN UISessionId:3 AppName:wotrack UserId:wilson UIClientIP:127:0:0:1 ElapsedTime:44 ms  END
  • The first log statement in the fragment displays a field [CID-UI-993] that is the component that is correlated in this example.
  • CID is the correlation ID, followed by the component that is being correlated, and the numeric value that is applied to all the correlated statements output for the particular correlation.
  • The [CID-UI-993] field groups a set of correlated log statements that are started by a UI request.
  • A correlated set of log statements is marked by the Correlation started and Correlation data statements. The first set of correlated log statements begins with [CID-UI-993]correlation started and ends with [CID-UI-993]Correlated data:BEGIN the specific component information END.
  • The second set of correlate log statements indicate that the next set of correlated log statements is being output.
  • When a UI request is correlated, sql commands that run in response to user interaction are placed in the same group of correlated log statements as the UI request.
  • In the second correlated statement for correlation [CID-UI-993], the sql command is associated with the WORKORDER table.
  • If multiple sql statements run in response to the UI request the statements are output to the same group of correlated log statements.
  • The final log statement for correlation [CID-UI-993] begins with Correlation data and provides information about the user session that started the output of correlated log statement.
  • The additional information includes:
    1. The UI session Identifier 3.
    2. The UI event loadapp.
    3. The application that started the UI event autoscript.
    4. The user that started the event wilson.
    5. The IP address from where the UI request was received UIClientIP.
  • In the final log statement for correlation [CID-UI-993], the ElapsedTime information specifies the time that is spent by the application server to process the UI request.