Get more out of maximo logs - log correlation in 7.5

Body

Many of us have found that it is not a simple task to identify from a maximo log file which user operation is contributing to a long running SQL, or what are all the SQL queries or events triggered by a particular user action. Many different user threads and system threads are writing out to the same log file at the same time. Except for the user ID printed out in the log, the log entries are really not correlated in any way.

In version 7.5, a new feature, log correlation, is introduced to provide correlations among log entries. Once enabled, each UI request, crontask action, or REST call will be given a unique ID. The log entries printed out by the execution of this UI request, crontask action or REST call will all bear this correlation ID.

Only the UI request, crontask action, and REST calls are correlated in 7.5. There are log entries that are not correlated, such as log entries produced by system monitoring threads.

Correlation IDs are in the format of [CID-TYPE-NUMBER]. TYPE can be ‘CRON’ or ‘UI’ to differentiate the UI request vs. crontask action. NUMBER is to ensure uniqueness.

Correlation has properties. Additional log entries marking the beginning and the end of the correlation will be logged at the beginning and end of the correlation respectively. Each correlation has its property values, and they are printed at the end of the correlation.

• UI request correlation prints out app name, UI session id, UI event identifier, client IP, elapse time etc.
• Crontask action correlation prints out crontask name, instance name and elapse time.

A crontask correlation example:

[INFO] [MXSERVER4] [CID-CRON-0] Correlation started.

[INFO] [MXSERVER4] [CID-CRON-0] BMXAA6719I - USER = (MAXADMIN) SPID = (136) app (null) object (MAXUSER) : select * from maxuser  where

userid =  'MAXADMIN'  and status in (select value from synonymdomain where domainid = 'MAXUSERSTATUS' and maxvalue = 'ACTIVE')

[INFO] [MXSERVER4] [CID-CRON-0] BMXAA6719I - USER = (MA

XADMIN) SPID = (150) app (null) object (PERSON) : select * from person  where personid =  'MAXADMIN'

...

[INFO] [MXSERVER4] [CID-CRON-0] Correlated data: BEGIN

InstanceName:AsyncImmediate TaskName:AsyncImmediateJobCron ElapsedTime:109 ms  END

A UI correlation example:

[INFO] [MXSERVER4] [CID-UI-60] Correlation started.

[INFO] [MXSERVER4] [CID-UI-60] BMXAA6719I - USER = (WIL

SON) SPID = (145) app (null) object (MAXPROPVALUE) : select * from maxpropvaluewhere ((upper(servername) like '%COMMON%')) and (propname ='mxe.adminPasswd')

[INFO] [MXSERVER4] [CID-UI-60] BMXAA6719I - USER = (WIL

SON) SPID = (152) app (null) object (DMCOLLAPPTOOLBAR) : select * from dmcollapp

toolbar  where (appname = 'PROPMAINT') order by toolbarsequence

[INFO] [MXSERVER4] [CID-UI-60] Correlated data: BEGIN

uIClientIP:127.0.0.1 UserId:wilson Event:click- AppName:propmaint UISessionId:1216911858516 ElapsedTime:812 ms  END

Once a correlation is identified, searching the logs by the correlation ID, you will find all the logs produced by this UI, cron or REST event. From the other direction, if you need to find out what produced a particular log entry, the correlation property will point you to the right direction.

How to enable it? There are a couple of properties you need to set.

• Master correlation property

–        mxe.logging.CorrelationEnabled (default value 1)

–        When set, the crontask and REST correlation will be enabled.

–        The property is self-refreshable.

• Additional property to enable UI request correlation (disabled OOB)

–        mxe.webclient.logging.CorrelationEnabled (default value “false”)

–        Only take effect when mxe.logging.CorrelationEnabled=1.

–        The property is not self-refreshable, require server restart.

You also need the Logger pattern strings in place in order to display the correlation id, though it is in place out of box for 7.5. [%q] is to print out the correlation ID. Without it, the log entry will not include the correlation ID even if correlation is enabled.

As all good things come with a price, there will be a slight overhead on the correlation, mainly the cost of having a light weight filter for the UI events.