Analyzing data for Content Manager for z/OS library server (LS) log file.

Answer

The following is a breakdown of a LS log and how to read each of the common records and fields on those records. Many records are similar. Many have the same order of data, like date, time stamp, time zone.
Where records are very similar, I will provide one example and define the fields and what they mean. I may give a second or third similar example so someone reading the log file can see how things change. The LS log also has records providing what DB2 sql (select, update, delete, etc.) is being evoked. Some records indicate the end of a process and include return codes. I will try to describe each of these in at least one example so you know what you are seeing. I can not cover every single record the LS might generate, but what I provide will let you figure these other out. The first set of records I will describe is for a logon of a user at sysadmin client. After that I will have only examples of given records not a complete action like logon or logoff.


Library server log record layout/definition

ICMPLSLG ICMLOGON &&& 00606 06/08 19:12:10.459 GMT ;08191210458396 ICMADMIN Entry
ICMPLSLG ICMLOGON &&& 00661 06/08 19:12:10.461 GMT ;08191210458396 ICMADMIN Hostname
Hostname <XXX-XXX-XXXXXXX>
API Level <0803000400>
LogID <>

The above is a common record found at the start of a library server log. The library server WLM does not normally start until such time as someone logs onto the library server. As such, the first record is a logon record. The logon process generates a number of records in the LS log when doing a level 15 trace.
I have two records and some data presented by the LS for the second one. I list each field and give it a number for future reference purpose. The line number is the number I will use for future references.

1. ICMPLSLG is the module name being executed.
2. ICMLOGON is the function or stored procedure being invoked.
3. &&& represents a number of blanks in the log that do not show up clearly in this technote.
4. 00606 is the line number of the program being executed.
5. 06/08 is the date.
6. 19:12:10.459 is the time stamp of this record.
7. GMT is the time zone of the time stamp.
8. 08191210458396 is the thread identification.
9. ICMADMIN user id of person causing action being taken.
10. Entry is what ICMLOGON is doing, entry to logon function.

Note the second record is very similar to the first and has many similar fields. Instead of ENTRY, it has
Hostname. This is the type of changes between this very common record type you will see.
In this case.

1. Hostname is the name of the Sysadmin workstation of the user logging into the library server. The actual format may may not be 3 characters with a dash followed by 3 more etc. It is as a given shop defines it.
2. API level is the version, release and ptf level of the API of the sysadmin client calling the library server.
3. LogID was not provided but is the sysadmin log id.

Library server log record example 2

ICMPLSLG ICMLOGON &&& 00672 06/08 19:12:10.461 GMT ;08191210458396 ICMADMIN Library server code built < Dec 19 2006 18:29:58 >

In this record, note that field 10 as indicated above is not present. Also it provides the build date of the library server code. This can be used to determine what level of library server code is being executed. It also helps IBM development know what version and release of a module to use when doing problem analysis.


Library server log record example 3

ICMPLSLG ICMLOGON &&& 00807 06/08 19:12:10.461 GMT ;08191210458396 ICMADMIN Input
UserID <ICMADMIN>
DB2UserID <ICMADMIN>
Language < >
Application <ICM Connector>
LogonOption 0

This record is similar to opSys2, except field 10 has a value of input. This means it is the input data provided by the syadmin client to the LS.

The 5 fields following are those fields and the values for each.
Userid was ICMADMIN. That is what the user logged on with as their user id.
DB2UserID was ICMADMIN. They do not always need to be the same. They can be different is individual users have their own ids that have sysadmin privileges.


Library server log record syscontrol passed data

The next record is identical to the above but has a field 10 value of "SysControl".
This record will include The following syscontrol information.

Current Users 0
Max Users 0
Max User Action 2
Default language <ENU>
MaxLogonRetry 0
PasswordDuration 180
SystemFlag 0
Database Name <ICMMLSDB>
Schema Name <ICM>
MaxResultSetSize 0
Platform 3
AllowTrustedLogon 0

The above information is what is defined for the id and library server.


Library server log record exit invocation example

ICMPLSLG getExitModuleName &&& 01998 06/08 19:12:10.587 GMT ;08191210458396 ICMADMIN
DLL Path: <ICMXLSLG>
ICMPLSLG callUserExit &&& 02031 06/08 19:12:10.587 GMT ;08191210458396 ICMADMIN Entry
ICMPLSLG callUserExit &&& 02099 06/08 19:12:10.611 GMT ;08191210458396 ICMADMIN Return rc=0

Note:

• For the above 3 lines, we are in the same module, but a different set of stored procedures.
• The thread is still the same value.
• This is showning that the library server, as part of logon, needs to get the exit module.
• The exit module name is listed in the DLL Path: data item above.
• The last record shows the return code value returned by the exit. When every you see a return code in a library server trace, you have normally ended a process. The second record showed entry and the Return is the exit with the return code.

Library server log record logon data example

ICMPLSLG ICMLOGON 01627 06/08 19:12:10.615 GMT ;08191210458396 ICMADMIN ICMSTUSERS
UserID <ICMADMIN>
UserName <ICM Super System Administrator>
UserDomainID 1
UserPrivSetCode 1 Name <AllPrivs>
GrantPrivSetCode 6 Name <ClientUserReadOnly>
DfltItemACLCode 3 Name <PublicReadACL>
DfltRMCode 1 Name <ICMRMF>
DfltSMSCollection 1 Name <OAMAF.CLLCT001>
UserInfo <ICMADMIN ;1 ;08191210458396; HOSTNAME=CW4-ITS-77SNP21
;APILEVEL=0803000400;LID=;UNUM=2;ITEMSUPACC=1;>
UserToken < 83630 -1 >

Next the library server displaying the relevant data for the userid from the ICMSTUSERS table.
This shows the attribute in the table and the associated value.


Library server log record end of a process example

ICMPLSLG ICMLOGON &&& 01692 06/08 19:12:10.615 GMT ;08191210458396 ICMADMIN Privcode Only
ICMPLSLG ICMLOGON &&& 01734 06/08 19:12:10.615 GMT ;08191210458396 ICMADMIN Specific Library Server
ICMPLSLG ICMLOGON &&& 01952 06/08 19:12:10.615 GMT ;08191210458396 ICMADMIN 157 msec
ICMPLSLG ICMLOGON &&& 01953 06/08 19:12:10.615 GMT ;08191210458396 ICMADMIN Exit rc=0 reason=0 extrc=0 extreasn=0 LCT =2007/06/08 15:12:10.615

• All 5 records are similar to previous discussed records.
• The first two are different only in that field 10 explains what was done or what was checed. Like privilege code.
• The third record indicates how many mila seconds were processed to do logon. Go first record and it had in its timestamp 459 and this record has 615. Given the DB2 timestamp is being truncated, the difference between the two numbers we have is 156. The actual value rounded up was most likely 157.
• The fourth record shows the return code, reason code and external return and reason code for the logon process. The LCT is the local timestamp instead of the GMT that this process ended.

Library server log record examples of included DB2 statements executed

From this point on, I will be using describing miscellaneous records in the library sever.

ICMPLSGT checkItemTypeViewPriv &&& 01564 06/08 19:12:10.749 GMT ;08191210458396 34710730132205352202 ICMADMIN C_ITEM_TYPES_PIV szSQLstmt <SELECT DISTINCT A.ITEMTYPEVIEWID, A.ITEMTYPEID, C.PRIVS FROM ICM.ICMSTITVIEWDEFS A, ICM.ICMSTCOMPILEDACL C WHERE (((.ACL = A.ACLCODE OR C.ACL = -1) OR (A.ITEMTYPEVIEWID<1000)) AND C.UNUM = 2) ORDER BY A.ITEMTYPEID ASC, A.ITEMTYPEVIEWID ASC > pszSubselect <(SELECT DISTINCT A.ITEMTYPEVIEWID FROM ICM.ICMSTITVIEWDEFS A, ICM.ICMSTCOMPILEDACL C WHERE ((C.ACL = A.ACLCODE ORC.ACL = -1) AND C.UNUM = 2 AND ( (ICM.ICMACLPRIVBITCHECK(C.PRIVS, 122)=1) )) ) UNION (SELECT DISTINCT A.ITEMTYPEVIEWID FROM ICM.IMSTITVIEWDEFS A WHERE A.ITEMTYPEVIEWID<1000 ) >
ICMPLSGT openItemTypesCursor 01797 06/08 19:12:10.792 GMT ;08191210458396 34710730132205352202 ICMADMIN ITEM_TYPES_SEL szSQLstmt <SELECT A.KEYWORDNAME, A.KEYWORDDESCRIPTION, B.ITEMTYPEID,B.ITEMTYPECLASS,B.ITEMLEVELACLFLAG,B.ITEMTYPEACLCODE,B.DFLTRCODE,B.DFLTCOLLCODE,B.DFLTPREFCHCOLLCODE,B.DFLTRETENTIONUNIT,B.DFLTITEMRETENTION,B.DFLTXDOCLASSID,B.AUTOLINKENABLE,B.AUTOLINKSMS,B.EGMENTID,B.SEGMENTTHRESHOLD,B.PARTITIONID,B.PARTITIONTHRESHOLD,B.VERSIONCONTROL,B.VERSIONMAX,B.ITEMEVENTFLAG,B.USERID,B.CHANGED,B.POCESSNAME,B.DFLTPRIORITY,B.ITEMTYPEFLAG FROM ICM.ICMSTNLSKEYWORDS A, ICM.ICMSTITEMTYPEDEFS B WHERE B.ITEMTYPEID > 0 AND B.ITEMTYPID = A.KEYWORDCODE AND A.KEYWORDCLASS = 2 AND A.LANGUAGECODE = 'ENU' ORDER BY ITEMTYPEID ASC WITH UR >

ICMPLSGT openCompntTypesCursor 01989 06/08 19:12:10.829 GMT ;08191210458396 34710730132205352202 ICMADMIN COMP_TYPES_SEL szSQLstmt <SELECT A.KEYWORDNAME, A.KEYWORDDESCRIPTION, B.COMPONENTTYPEID,B.ITEMTYPEID,B.PARENTCOMPTYPEID,B.CARDINALITYMIN,B.CARDNALITYMAX,B.DELETERULE,B.COMPTYPECLASS,B.USERID,B.CHANGED FROM ICM.ICMSTNLSKEYWORDS A, ICM.ICMSTCOMPDEFS B WHERE B.ITEMTYPEID > 0 AND B.COMPONENTTYPEID = A.KEYWORDCODE AND A.KEYWORDCLASS = 5 AND A.LANGUAGECODE = 'ENU' ORDER BY ITEMTYPEID ASC, COMPONENTTYPEID AS WITH UR >

ICMPLSGT openAttrsCursor 02180 06/08 19:12:10.879 GMT ;08191210458396 34710730132205352202 ICMADMIN ATTRS_SEL szSQLstmt <SELECT COMP.ITEMTYPEID, COMPATTR.COMPONENTTYPEID,COMPATTR.ATTRIBUTEID,COMPATTR.ATTRIBUTEGROUP,COMPATTR.SEQUENCENUM,COPATTR.ATTRFLAGS,COMPATTR.DEFAULTTYPE,COMPATTR.MINIMUMVALUE,COMPATTR.MAXIMUMVALUE,COMPATTR.DEFAULTVALUE , VIEWATTR.ATTRIBUTEFLAGS FRM ICM.ICMSTCOMPATTRS COMPATTR, ICM.ICMSTCOMPVIEWATTRS VIEWATTR, ICM.ICMSTCOMPDEFS COMP WHERE COMPATTR.COMPONENTTYPEID = COMP.COMPONNTTYPEID AND COMPATTR.COMPONENTTYPEID = VIEWATTR.COMPONENTVIEWID AND COMPATTR.ATTRIBUTEGROUP = VIEWATTR.ATTRIBUTEGROUP AND COMPATT.ATTRIBUTEID = VIEWATTR.ATTRIBUTEID AND COMP.ITEMTYPEID > 0 ORDER BY COMP.ITEMTYPEID ASC, COMP.COMPONENTTYPEID ASC, COMPATTR.SEQUNCENUM ASC WITH UR >

The above is three examples of records including a select from the library server tables. In some of these selects, writes or updates the data or attribute names and associated criteria is clear and easy to read.In some you will see ??? or other such indicators.

The first one is checking itemtype views as indicated in field 2. The second select is doing an open of component type cursor. The third is doing an open of the attribute cursor. This is toward doing a select of attributes later.

In all cases the results of the select are not show in the record with the select. They may be listed later or be data for other gets or other actions later.


Library server log records example of thread ending an beginning

ICMPLSLF ICMLOGOFF 00116 06/08 19:12:11.898 GMT ;08191210458396 ? ICMADMIN Entry
ICMPLSLF ICMLOGOFF 00132 06/08 19:12:11.899 GMT ;08191210458396 ? ICMADMIN Input
UserID <ICMADMIN>
LastAccess -1
ICMPLSLF ICMLOGOFF 00170 06/08 19:12:11.899 GMT ;08191210458396 ? ICMADMIN User Logged Off
ICMPLSLF ICMLOGOFF 00200 06/08 19:12:11.899 GMT ;08191210458396 ? ICMADMIN 2 msec
ICMPLSLF ICMLOGOFF 00201 06/08 19:12:11.899 GMT ;08191210458396 ? ICMADMIN Exit rc=0 reason=0 extrc=0 extreaon=0 LCT =2007/06/08 15:12:11.899
ICMPLSLG ICMLOGON 00606 06/08 19:12:11.986 GMT ;08191211986332 ICMADMIN Entry
ICMPLSLG ICMLOGON 00661 06/08 19:12:11.986 GMT ;08191211986332 ICMADMIN Hostname

The purpose of these records is to show how field 8, thread identifier changed from one user to the other.
In the logoff, the Userid of the person logging off is also provided.


Library server log record example of selects that have substitutions

ICMPLSLC ICMLISTCOMPILEDACL 00416 06/08 19:12:14.893 GMT ;08191211986332 34751822832205352202 ICMADMIN SqlString SqlString: <SELECT DISTINCT '%s' AS USERID, A.ACLCODE, P.PRIVDEFCODE FROM %s.ICMSTACCESSCODES A, %s.ICMSTPRIVSETS P, %s.ICMSTUS RS U WHERE U.USERID = '%s' AND U.USERPRIVSETCODE = P.PRIVSETCODE >

ICMPLSLC ICMLISTCOMPILEDACL 00579 06/08 19:12:14.893 GMT ;08191211986332 34751822832205352202 ICMADMIN SELECT DISTINC
'ICMADMIN' AS USERID, A.ACLCODE, P.PRIVDEFCODE FROM ICM.ICMSTACCESSCODES A, ICM.ICMSTPRIVSETS P, ICM.ICMSTUSERS U WHERE U.USERID
'ICMADMIN' AND U.USERPRIVSETCODE = P.PRIVSETCODE ORDER BY ACLCODE FOR READ ONLY WITH UR
ICMPLSLC ICMLISTCOMPILEDACL 00625 06/08 19:12:14.955 GMT ;08191211986332 34751822832205352202 ICMADMIN 67 msec
ICMPLSLC ICMLISTCOMPILEDACL 00626 06/08 19:12:14.955 GMT ;08191211986332 34751822832205352202 ICMADMIN Exit rc=0 reason=0 extrc=0 extreason=0 LCT =2007/06/08 15:12:14.955

The above is another example of a select showing both the wild card values provided and then in the second select how they were resolved.


Library server log example of error or failure

ICMPDRGW ICMGETWORK 01121 06/06 13:38:45.600 GMT ;06133645414253 55008955558438196237 REP1IXD Work list selection <SELECT TMP.COMPONENTID, TMP.RTARGETITEMID, TMP.USERID FROM ( SELECT WRKPKG.COMPONENTID,WRKPKG.PRIORITY, RKPKG.LASTACCTIME,WRKPKG.RTARGETITEMID,WRKPKG.RTARGETITEMTYPEID,WNORDER.WORKNODEORDER,C.USERID FROM D154CM.ICMUT00206001 WRKLIST INNER JOIN D154CM.ICMUT00207001 WNORDER ON WRKLIST.ITEMID = ? AND WNORDER.ITEMID = WRKLIST.ITEMID LEFT OUTER JOIN D154CM.ICM UT00204001 WRKPKG ON (WRKPKG.ITEMID=WNORDER.WORKNODEITEMID ) LEFT OUTER JOIN D154CM.ICMSTCHECKEDOUT C ON WRKPKG.RTARGETITEMID = C.ITEMID AND C.USERID <> ? ) TMP WHERE TMP.USERID IS NULL AND ( (1=1) AND TMP.COMPONENTID IS NOT NULL ) ORDER BY TMP.PRIORITY DESC,TMP.WORKNODEORDER ,TMP.LASTACCTIME ASC WITH UR >
ICMPDRGW ICMGETWORK 01232 06/06 13:38:45.631 GMT ;06133645414253 55008955558438196237 REP1IXD Fetch WP
rc 100
Work Package <>
Target Item <>
Checked out by <>
Current user <REP1IXD>
sNullIndicator 29088
sWPCompIDInd 0
sTargetItemIDInd0
psCheckout 1
ICMPDRGW ICMGETWORK 01253 06/06 13:38:45.631 GMT ;06133645414253 55008955558438196237 REP1IXD Exit rc=7503 reason=0 extrc=100 extreason=0 LCT =2009/06/06 09:38:45.631

The above is an example of a trace entry or two showing a retrieve failure.

• rc=7503 is the library server return code or value of ICM7503. This is defined in the Content Manager messages and codes manual.
• reason=0 means there was no associated reason code.
• extrc=100 is in this case, a DB2 return code of 100, which means the selected item was not found.
• extreason=0 says there was no associated external or DB2 reason code for the DB2 return code.

In some cases DB2 will have an external reason code and it will be present in the extreason field. In addition depending on what other product was invoked the extrc and extreason could be from RACF or some other security package, related to access methods services and ASC routines. The key to reading this external return code or reason code, is the action displayed in the previous record. In this case, a call to DB2.


Library server log date miscellaneous information

Note that the library server trace can tell you what privilege code was required for an action and if the user did not have it assigned, you will get an error indicating that. It will also tell you about ACL codes, collection codes and other such values. When the library server references a code, like ACL or Collection, you need to find them in the ICMSTNLSKEYWORDS TABLE. That table has all the definitions for all the attributes, codes, privileges ACLs, itemtypes, and other such items defined to Content Manager. When Content Manager uses a code, there is always a cross reference definition of the code to the actual name of the field in question.