How to Analyze JVM logs (SystemOut.log, SystemErr.log & startServer.log)

Websphere writes formatted text log messages to SystemOut.log,SystemErr.log & startServer.log files.

Sample SystemOut.log

[14/08/11 07:06:54:204 BST] 0000000a ManagerAdmin  I   TRAS0017I: The startup trace state is *=info.
[14/08/11 07:06:54:683 BST] 0000000a ManagerAdmin  I   TRAS0111I: The message IDs that are in use are deprecated

[14/08/11 07:06:55:606 BST] 0000000a FileRepositor A   ADMR0010I: Document cells/server1_Cell/nodes/server1_Manager/node-metadata.properties is modified.

[14/08/11 07:06:57:823 BST] 0000000a ThreadPoolMgr W   WSVR0626W: The ThreadPool setting on the ObjectRequestBroker service is deprecated.

[21/05/10 10:02:56:240 BST] 00000012 TCPPort       E   TCPC0003E: TCP Channel TCP_5 initialization failed.  The socket bind failed for host * and port 9352.  The port may already be in use.
[21/05/10 10:02:56:244 BST] 00000012 TCPPort       E   TCPC0003E: TCP Channel TCP_5 initialization failed.  The socket bind failed for host * and port 9352.  The port may already be in use.

[15/08/11 03:49:59:333 BST] 0000003c SystemOut     O Debug options: file:/opt/IBM/WebSphere/AppServer/profiles/Profile01/dmgr/.options not found
[15/08/11 03:49:59:512 BST] 0000003c SystemOut     O Need to load org.eclipse.osgi.framework.internal.protocol.reference.Handler
[15/08/11 03:49:59:585 BST] 0000003c SystemOut     O Time to load bundles: 76

# Time Stamp: The first part of the log message in sample code is  [15/08/11 03:49:59:585 BST]. It is the time stamp when the message was written. The time stamp is formatted using the locale of the process and it is 24 hour time stamp with milli-second precision

# Thread ID : The next part in the log message is 00000012 /0000003c , which represents the thread id. The thread ID is an eight-character hexadecimal value that is generated from the hash code of the thread that issued the message

# Short name : The short name is the abbreviated name of the component that issued the message. This name is typically the class name of a WAS component and would be some other identifier for the application. here ThreadPoolMgr , FileRepositor , TCPPort etc

# Event Type: The event type is a one character field that indicates the type of the message. The possible values are
* F- Fatal message
* E- Error message
* W- Warning message
* A- Audit message
* I- Informational message
* C- Configuration message
* D- detail message
* O- Messages that are written directly to System.out by an application or server component
* R- Messages that are written directly to System.err by the user application or internal component.
* Z- Place holder to indicate type was not recognized

# Message identifier (TCPC0003E/WSVR0626W/ADMR0010I): The message identifier is a string that is nine characters in length and is in the form CCCC1234X. The first four characters indicate the WAS component that issues the message. The next four characters indicate the specific message that component is issuing. The last character indicates the severity of the message. Its value is either I- informational, W- Warning or E error.

# Message: The message is the data that is logged to the SystemOut.log by the component

Sample SystemErr.log

[21/05/10 10:06:22:772 BST] 0000002b SystemErr     R Warning: unable to load “pr3native” library (using path: /opt/IBM/WebSphere/AppServer/java/jre/bin:/opt/IBM/WebSphere/AppServer/bin::/usr/lib:/opt/IBM/WebSphere/AppServer/lib/WMQ/java/lib) Root cause: pr3native (Not found in java.library.path)
[21/05/10 10:07:43:844 BST] 00000036 SystemErr     R 21-May-2010 10:07:43 com.pega.pegarules.ra.priv
INFO: Attempting to connect to JMS queue for asynchronous task execution

Sample startServer.log

************* End Display Current Environment *************
[21/05/10 10:02:41:607 BST] 0000000a ManagerAdmin  I   TRAS0017I: The startup trace state is *=info.
[21/05/10 10:02:41:671 BST] 0000000a AdminTool     A   ADMU0128I: Starting tool with the dmgr profile
[21/05/10 10:02:41:673 BST] 0000000a AdminTool     A   ADMU3100I: Reading configuration for server: dmgr
[21/05/10 10:02:43:570 BST] 0000000a AdminTool     A   ADMU3200I: Server launched. Waiting for initialization status.
[21/05/10 10:03:04:866 BST] 0000000a AdminTool     A   ADMU3000I: Server dmgr open for e-business; process id is 902