The format of logging information in event log and logs for Shareplex processes (4326101)

Knowing the format of the entries in the logs can help one decipher the logs faster. It also helps configure any monitoring script (supplied by Quest or created by customer) that is looking for a certain pattern. Starting with Shareplex 6.0, the format of information logged in event log and process specific logs for Shareplex processes have materially changed. The new format (especially for event_log) is more conducive to extracting information as explained below.

N.A.

A. Changes in event log:

In Shareplex versions prior to 6.0, the event log displays information in the following format, which shows three fields, namely date, time and a narration. It is possible to sift through it for signs of error exit codes or specific error strings in the narration field. A Shareplex monitoring script is deployed to do this at times.

Sample event log entry for Pre 6.0 Shareplex:

02/01/08 13:13 Logging user command: oracle start post
02/01/08 13:13 Process launched: sp_opst (for o.SID1-o.SID2 queue pear) [pid = 33926]
02/01/08 13:13 Notice: sp_opst(pdb) (for o.SID1-o.SID2 queue pear) Oracle env - SID2:/u730/app/oracle/product/8.1.7.2.32
02/01/08 13:13 Notice: sp_opst(osp) (for o.SID1-o.SID2 queue pear) Oracle version 81
02/01/08 13:14 Notice: sp_opst (for o.SID1-o.SID2 queue pear) Post will not open more than 490 cursors (OPEN_CURSORS - 10).
02/01/08 13:15 Notice: sp_opst (for o.SID1-o.SID2 queue pear) Block on "owner"."table" lifted
02/01/08 13:15 Process exited sp_opst  (for o.SID1-o.SID2 queue pear) [pid = 33926] - exit(20)
02/01/08 13:15 Process launched: qview (for 0xac1e270d+PP+pear+sp_opst+o.SID1-o.SID2 queue *) [pid = 33928]
02/01/08 13:15 Logging user command: oracle rrls rollbacks post queue
02/01/08 13:15 Notice: qview(que) (for qview queue qview) qview -p did not read release any rollbacks
02/01/08 13:15 Process exited qview  (for 0xac1e270d+PP+pear+sp_opst+o.SID1-o.SID2 queue *) [pid = 33928] - exit(1)
02/01/08 13:16 Notice: sp_cop Failed to break current operation for session 17, blocked by session 9

The event log in Shareplex 6.0 or up has an entirely different format as shown below. More fields are introduced, some of which may be useful for the end user to analyze the event log better. Other fields may be of significance to Development for troubleshooting. The first field tells if the entry is an informational message, notice, a warning or an error condition. The second field is for date, the third one is for time, the fourth and fifth fields have significance for Development or Support, the sixth field is for the module (Capture, Activation, etc) and the seventh field contains the narration of the event.

Sample event log entry for Shareplex 6.0 or higher:

ora_cleansp was carried out on Thu Oct 30 22:07:57 EDT 2008 by joe.plumber for SID1
Notice   2008-10-31 23:25:43.657182 13566618 1 SPO, Demo license key will expire on Midnight of Dec 05, 2008
Info     2008-10-31 23:25:43.759802 13566618 1 SharePlex was started on cpu IBM,0102B0D8F using port 2100 version 6.1.0.21
Info     2008-10-31 23:25:59.933237 5337538 1 Command server launched, pid = 5337538  (connecting from s1892cdc.cdc.abc.com)
Notice   2008-10-31 23:28:50.199158 5337538 1 User command: oracle activate config config_Abc.file (from s1892cdc.cdc.abc.com)
Info     2008-10-31 23:28:50.209593 933956 1 Activation launched, pid = 933956  (activating sid SID1)
Notice   2008-10-31 23:28:55.356046 933956 1 Activation: Oracle compatible parameter='9.2.0'.  (activating sid SID1) [module ocf]
Warning  2008-10-31 23:29:24.471558 933956 1 Activation: 13007 - NO_UNIQUE_KEY_WITH_LOB found on object id: 897186  (activating sid SID1) [module osp]
Error    2008-11-03 17:49:05.075308 9962028 1 Process: Can't assign requested address bind: fd 3  [module rmp]

Another major difference is the manner in which the errors are reported by exit codes. Earlier the abnormal termination was denoted by exit(1) but now it is denoted with "exited with code=1" as shown below:

Info     2008-10-16 15:57:30.967137 27222 1 Export exited with code=1, pid = 28005  (exporting to yxhis queue yxora1)
Warning  2008-10-16 15:57:30.965584 28005 1 Export cannot connect to import on yxhis: unable to identify peer
Info     2008-10-16 15:57:30.962104 28005 1 Export connected to host on yxhis
Info     2008-10-16 15:57:30.853497 28005 1 Export launched, pid = 28005  (exporting to yxhis queue yxora1)

B. Changes in process logs (taking the *ord* log for Read process as example):
There is a slight change in the logs for specific processes, which includes the *ord log (for Read), *ocap log (for Capture), *opo log (for Post) and trace_log (for other processes like sp_cop, Export, Import, etc).

Sample ord log entry for Pre 6.0 Shareplex:

As shown below, the first field is for date, the second one is for time, the third and fourth fields have significance for Development or Support, the fifth field contains the narration of the event:

06-06-05 19:09:37.521508 17981 1 INFO:ord_GetKeyFromOracle: Got Snapshot error (rc=1555) trying to use next RCM (rowid=AAAvHwACLAAA8DxAAn) on Mon Jun  5 19:09:37 2006
06-06-05 19:09:37.535616 17981 1 INFO:ord_GetKeyFromOracle: Exhausted all RCM's with rc=1555, generated new RCM (rowid=AAAvHwACLAAA8DxAAn)
06-06-05 19:09:37.535971 17981 1 qpos getting stoSeqno1 70

Sample ord log entry for Shareplex 6.0 or higher:

The only difference in the ord log is the inclusion of an additional field for module at the start of each entry. Typically the module would be the one for which the log is created, the ord module (acronym for Read module) in this case:

ord      2008-11-02 19:25:15.043722 1258028 1INFO:ord_GetKeyFromOracle: Exhausted all RCM's with rc=1555, generated new RCM (rowid=AADbCVAAKAAA516AAH)
ord      2008-11-02 19:25:15.043847 1258028 1 qpos getting stoSeqno1 10
ord      2008-11-02 19:25:15.071198 1258028 1 q_seeking to 45622893435
ord      2008-11-02 20:20:03.108786 1258028 1INFO:ord_GetKeyFromOracle:Exhausted all RCM's with rc=1555, generated new RCM (rowid=AADb8lAB9AACX++AAa)
ord      2008-11-02 20:20:03.119580 1258028 1 qpos getting stoSeqno1 10
ord      2008-11-02 20:20:03.149790 1258028 1 q_seeking to 45632018452

This change has a significant impact on monitoring scripts as legacy scripts designed for pre 6.x logging struction will need to be updated to account for the new format.