This section describes the contents of a trace log file as it was generated during application runtime. The example included in this section presents log entries using the format pattern defined in the custom FileNet® Layout class, com.filenet.apiimpl.util.TraceLayout. This layout class is used when the server automatically configures log4J based on the TraceLoggingConfiguration object.
NOTE It is possible to instruct the system to bypass the server implementation of trace logging and to use an alternate layout scheme for formatting log output. For more information, see Choose the Custom Layout Class or a ConversionPattern and PatternLayout.
Using the custom Layout class, all messages are written to the trace log in the following format:
<UTC time> <thread id> <sub-system> - <level> <message>
where:
UTC time —
The UTC time associated with the log entry using a fixed ISO8601 format for GMT time, as YYYY-MM-DDTHH:MM:SS:NNSZ. For example: 2006-09-06T23:22:45.241Z
. thread id —
The hash code of the Java™ thread that is logging the trace entry using an eight character hexadecimal format, padded with leading zeros if necessary. For example: 802284C6
. sub-system —
A maximum four character abbreviation that identifies the affected sub-system, padded with spaces if necessary. For a list of sub-system abbreviations, see Supported FileNet P8 Subsystems.level —
When an error, warning, or other informational message is written to the trace log, the level
name is prepended to the text of the message. For example: "2006-11-30T17:36:12.791Z 01EDFAB8 ENG - WARN RemoteCommand - Unable to find ObjectStore task...
". However, the level
name is never specified in the body of a trace logging message, as all trace logging messages are understood to be at the DEBUG
level. For a list of possible logging levels, see Select the Error Logging Level.message —
The text of the log message, including the following conversions which are written
directly into the trace log file:
\n
" escape sequence.\\
".\n
" escape sequence separators. This causes each
successive trace log entry to appear on a new line.NOTE You can create a SED script to expand the entries in the log file (at every line break, create a new line) and to convert the double-backslashes back to single backslashes. For information about how to create and use this script, see Conversion of Output Entries.
To expand the entries in the log file (at every line break, create a new line) and to convert double-backslashes into single backslashes, you can create and run a SED script.
s/\\\\/\\b/g
s/\\n/\
/g
s/\\b/\\/g
\n
). Depending on the version of SED that you are using, you may need to specify this marker in a different manner in order to have the new lines appear correctly in the expanded text. For example, some systems may require the end-of-line (newline) marker to be represented as (\r\n
).sed -f ExpandTrace.sed p8_server_trace.log > expanded_trace.log
You can analyze trace logging output using tools such as Chainsaw (which is part of the log4j package). This real-time GUI viewer and filter of log4j output requires the input to be in XML format. For more information, refer to the log4j Chainsaw documentation (http://logging.apache.org/log4j/docs/chainsaw.html).
You can also use appropriate third-party tools or common text file analysis tools, such as grep, tail, awk, or diff, or Windows® equivalents, such as Windows Grep, Wordpad, Notepad, and so on.
The entries below represent some sample generated trace and error logging output. Note that the exact format of information logged is subject to change from release to release and is not guaranteed to be representative of any particular environment.
NOTE In the following example, actual line breaks have been inserted after the "\n
" escape sequence separators in the text of the ERROR
level message (the last long entry in this example). This was done to improve the readability of the example in an online setting. Under normal circumstances, the text of the ERROR
level message would be displayed as one continuous line wrapping across several lines.
2006-11-30T17:36:12.273Z 00373E38 CSTG - INFO TTLStreamReaper task has started. 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin Details: Connect: expect:<0> userId:<administrator> password:<b***> batch:<false> appId:<tegwar> URL:<http://tegwar:8008/ApplicationEngine/requestx> URLd:<http://tegwar:8008/ApplicationEngine/download> URLu:<http://tegwar:8008/ApplicationEngine/dupload> 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin Details: Connect: session:<b64435> remote:<37fb1e> token:<clear:locale:ZW5fVVM=:password:YnV6eg==:userid:YWRtaW5pc3RyYXRvcg==:datetime:MTEwMzMzMzc3OQ==:appid:dGVnd2Fy> caller:<at org.carpenter.bill.CreTe.testVersionSeriesOrder(CreTe.java:319)> 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin Details: Parameter: 0: name:<objRef> type:<BaseObjectImpl> value:<Object Reference [DOCUMENT:1] ID "{BF6FD73B-CFF2-43DD-99B3-375A0EF25EAD}" in ObjectStore "Bag Of Fun"> 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin Details: Parameter: 1: name:<AutoClassify> type:<Boolean> value:<false> 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin Details: Parameter: 2: name:<minorVersion> type:<Boolean> value:<false> 2006-11-30T17:36:12.791Z 01F09B88 ENG - Document/Checkin ConnectionWrapper.send send.before 2006-11-30T17:36:12.801Z 01F09B88 ENG - WARN Document/Checkin ConnectionWrapper.send send.after 2006-11-30T17:36:12.801Z 01F09B88 ENG - Document/Checkin Details: Return: name:<return> type:<Vector> value:<> 2006-11-30T17:36:12.801Z 01F09B88 ENG - Document/Checkin Details: Return: Vector: 0: item:<true> 2006-11-30T17:36:12.801Z 01F09B88 ENG - WARN Document/Checkin RemoteCommand.execute stamps beg/i.b/i.a/end/conv,1103333772273,1103333772273,1103333772289,1103333772289,1103333772289 2006-11-30T17:36:12.801Z 01F09B88 ENG - WARN Document/Checkin RemoteCommand.execute deltas beg/i.b/i.a/end/conv/tot,0,0,16,0,0,16 2006-11-30T17:36:12.801Z 01EDFAB8 ENG - WARN Unable to find ObjectStore task {5A00382B-E6F4-4E0A-AF99-6C07C741B5E4} for class com.filenet.engine.queueitem.QueueDispatcher 2006-11-30T17:36:12.806Z 01EDFAB8 ENG - WARN Unable to find ObjectStore task {5A00382B-E6F4-4E0A-AF99-6C07C741B5E4} for class com.filenet.engine.queueitem.ContentQueueDispatcher 2006-11-30T17:36:12.806Z 01EDFAB8 CSTG - WARN No ContentQueue dispatcher for ObjectStore {5A00382B-E6F4-4E0A-AF99-6C07C741B5E4} 2006-11-30T17:36:12.806Z 01EDFAB8 ENG - WARN Unable to find ObjectStore task {5A00382B-E6F4-4E0A-AF99-6C07C741B5E4} for class com.filenet.engine.cbr.CBRDispatcher 2006-11-30T17:36:12.806Z 01507ECC ASYN - INFO Starting queue dispatching for DaphneStore Queue: com.filenet.engine.queueitem.QueueItemDispatcher 2006-11-30T17:36:12.822Z 015C9B61 CSTG - INFO ContentQueueDispatcher starting : {5A00382B-E6F4-4E0A-AF99-6C07C741B5E4} DaphneStore 2006-11-30T17:36:12.822Z 015C9B61 CSTG - INFO ContentQueueDispatcher [DaphneStore] Session Id={DB006624-C49D-4E13-90E8-6C6EECC51F90} 2006-11-30T17:36:12.853Z 00F07933 PUBL - INFO Starting queue dispatching for DaphneStore Queue: com.filenet.engine.publish.PublishRequestDispatcher 2006-11-30T17:36:12.900Z 00850CEC CBR - INFO Starting CBR queue dispatching for DaphneStore 2006-11-30T17:50:04.806Z 00B1BE82 ENG - INFO Starting server shutdown 2006-11-30T17:50:04.806Z 01507ECC ASYN - INFO Stopping queue dispatching for DaphneStore Queue: com.filenet.engine.queueitem.QueueItemDispatcher 2006-11-30T17:50:04.806Z 01DB65AD CFSD - INFO ImportAgentDispatcher terminating, Import Agents have been terminated(ShouldStop returned true), 2006-11-30T17:50:04.853Z 00F07933 PUBL - INFO Stopping queue dispatching for DaphneStore Queue: com.filenet.engine.publish.PublishRequestDispatcher 2006-11-30T17:50:04.869Z 00BABB11 CSTG - INFO TTLStreamReaper: Shutting down any active streams 2006-11-30T17:50:04.869Z 00B1BE82 ENG - INFO Server shutdown completed 2006-11-30T17:50:04.902Z 00BB6B37 ENG - ERROR method name: close principal name: Global Transaction: null User Transaction: null Exception Info: com.filenet.api.exception.EngineRuntimeException: E_TRANSACTION_FAILURE: A transaction problem has occurred. Internal error; an unfinished distributed transaction was rolled back.\n at com.filenet.engine.context.ServerCallContext.close(ServerCallContext.java:272)\n at com.filenet.engine.jca.impl.RequestBrokerImpl.executeChanges(RequestBrokerImpl.java:1046)\n at com.filenet.engine.ejb.EngineCoreBean._executeChanges(EngineCoreBean.java:570)\n at com.filenet.engine.ejb.EngineCoreBean.executeChanges(EngineCoreBean.java:538)\n at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)\n at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)\n at java.lang.reflect.Method.invoke(Method.java:324)\n at org.jboss.invocation.Invocation.performCall(Invocation.java:345)\n at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)\n at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185)\n at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:130)\n at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:51)\n at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)\n at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)\n at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:389)\n at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)\n at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:139)\n at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)\n at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)\n at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)\n at org.jboss.ejb.Container.invoke(Container.java:873)\n at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:413)\n at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:88)\n at $Proxy66.executeChanges(Unknown Source)\n at com.filenet.engine.ejb.EngineBean.executeChanges(EngineBean.java:599)\n at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)\n at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)\n at java.lang.reflect.Method.invoke(Method.java:324)\n at org.jboss.invocation.Invocation.performCall(Invocation.java:345)\n at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)\n at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185)\n at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:130)\n at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:51)\n at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)\n at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)\n at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:363)\n at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)\n at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:139)\n at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)\n at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)\n at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)\n at org.jboss.ejb.Container.invoke(Container.java:873)\n at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)\n at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)\n at java.lang.reflect.Method.invoke(Method.java:324)\n at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)\n at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)\n at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)\n at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:249)\n at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)\n at org.jboss.invocation.jrmp.server.JRMPInvoker$MBeanServerAction.invoke(JRMPInvoker.java:805)\n at org.jboss.invocation.jrmp.server.JRMPInvoker.invoke(JRMPInvoker.java:406)\n at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)\n at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)\n at java.lang.reflect.Method.invoke(Method.java:324)\n at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:261)\n at sun.rmi.transport.Transport$1.run(Transport.java:148)\n at java.security.AccessController.doPrivileged(Native Method)\n at sun.rmi.transport.Transport.serviceCall(Transport.java:144)\n at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)\n at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)\n at java.lang.Thread.run(Thread.java:534)