Analyzing trace logging output

The trace log generated by Content Cortex provides information about possible problems. Each entry in the log includes information about the source and category of each message.

The trace log has the following format:

<date> <thread id> <sub-system> <category> - <severity> <message>

Where:

date: The local time of the machine where the trace log is generated. Note that the log also includes the time zone offset from the Coordinated Universal Time, for example:
All times are local; the time zone is Pacific Standard Time(UTC -08:00)
thread id: The hash code of the Java™ thread that is logging the trace entry by using an eight character hexadecimal format, padded with leading zeros if necessary. For example: 802284C6.
category: Distinct code assigned to the message. Use the codes that are included in the error messages to identify problems and find their solutions. You can also search within the information center for message or code numbers to find the information that you need.
sub-system: A maximum four character abbreviation that identifies the affected subsystem, padded with spaces if necessary. For a list of subsystem abbreviations, see Supported Content Cortex Subsystems.

severity: When an error, warning, or other informational message is written to the trace log, the severity name is prefixed to the text of the message. For example: "

2023-02-22T14:17:14.550 00000031 ENG FNRCE0000D - DEBUG Starting task class
'com.filenet.engine.tasks.TaskManager$GCDMonitor'....

The following table lists the possible severities and their meaning.

Severity	Description
`WARN`	Requests logging for potentially harmful situations. Provides sufficient information for debugging (specific RPC names, frequencies, and durations) but no detail.
`DEBUG`	Requests logging for fine grained informational events that are most useful to debug an application. `DEBUG` logs the same information as `WARN` but with additional detail. You can also limit the amount of detail. For example, if you specify a RemoteCommand-only logger to log at the `DEBUG` level, you get specific RPC names, frequencies, durations, parameters, and return values. However, if you specify logging detail for all Content Java API activity, you get the most detail but the additional information logged might not be helpful for resolving problems. Keep in mind that the more detail you collect, the more severe the performance impact.
`ERROR`	Requests logging exceptions thrown from within the API (internally caught exceptions are logged at `DEBUG` level).
`FATAL`	Requests logging for only severe error events that might cause the application to stop.
`INFO`	Requests informational messages that describe the progress of the application at a coarse grained level.

message: The text of the log message, including the following conversions that are written directly into the trace log file:
- All stack trace logging entries are always compressed into one, single line with line break markers between each statement.
- Any line breaks in the original text of the message, including carriage-returns, line-feeds, or combinations of carriage-return/line-feed, are converted to the "\n" escape sequence.
- Any occurrences of a single backslash character in the original text of the message are converted into double backslash "\\".

Conversion of Output Entries

To expand the entries in the log file (at every line break, create a new line) and to convert each double backslash into a single backslash, you can create and run a SED script.

Create a text file and enter the following lines:
```
s/\\\\/\\b/g
s/\\n/\
/g
s/\\b/\\/g
```
Note: In this example, the end of line (newline) marker is directly specified in the script file as backslash "n" (\n). Depending on the version of SED that you are using, you might need to specify this marker in a different manner to have the new lines appear correctly in the expanded text. For example, some systems can require the end of line (newline) marker to be represented as (\r\n).
Save the text file as a SED script. For example, ExpandTrace.sed.
Run your new SED script on your trace log file, and redirect the output to another file:
```
sed -f ExpandTrace.sed p8_server_trace.log > 
expanded_trace.log
```

Analyzing log output

You can also use appropriate third-party tools or common text file analysis tools, such as grep, tail, awk, or diff. Or, you can use Windows equivalents, such as Windows Grep, WordPad, Notepad, and so on.

Sample Output

The following entries represent some sample generated trace and error logging output. Note that the exact format of information that is 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, line breaks are inserted after the "\n" escape sequence separators in the text of the ERROR level message (the last long entry in this example). These line breaks are inserted to improve the readability of the example in an online setting. Under normal circumstances, the text of the ERROR level message is displayed as one continuous line that wraps across several lines.

 
All times are local; the time zone is Mountain Standard Time(UTC -07:00)
VirtualServer: IBM-CA679C103F5Node01 ServerInstance: server1
Date (UTC -07:00)       Thread   Sub  Category     Sev  Message
2013-05-23T12:46:05.218 2E465F1E CSTG FNRCE0000I - INFO TTLStreamReaper task has started.
2013-05-23T12:46:05.343 30A0DC36 CFSI FNRCE0000I - INFO CFSImportAgent:domain1 serial=4 is enabled
2013-05-23T12:46:05.343 D7584661 CBR  FNRCE0000I - INFO CSSIndexRebalancingTask:domain1 serial=8 is enabled
2013-05-23T12:46:05.468 44CCEFCD CBR  FNRCE0000I - INFO Using temp directory for CSS:C:\\Program Files\\IBM\\WebSphere\\AppServer\\profiles\\AppSrv01\\FileNet\\server1\\CSSTemp
2013-05-23T12:46:05.812 44CCEFCD CBR  FNRCE0000I - INFO INSO filter deployed: binary path = 'C:\\Program Files\\IBM\\WebSphere\\AppServer\\profiles\\AppSrv01\\FileNet\\server1\\INSO\\bin\\sx-8-3-7-win-x86-64'
2013-05-23T12:46:05.828 44CCEFCD CBR  FNRCE0000I - INFO sx.cfg located at C:\\Program Files\\IBM\\WebSphere\\AppServer\\profiles\\AppSrv01\\FileNet\\server1\\INSO\\bin\\sx-8-3-7-win-x86-64
2013-05-23T12:46:05.984 44CCEFCD CBR  FNRCE0000I - INFO CSEStellentConfig.properties located at C:\\Program Files\\IBM\\WebSphere\\AppServer\\profiles\\AppSrv01\\FileNet\\server1\\INSO\\bin\\sx-8-3-7-win-x86-64
2013-05-23T12:46:05.984 44CCEFCD CBR  FNRCE0000I - INFO INSO batch text conversion is enabled
2013-05-23T12:46:06.046 44CCEFCD CBR  FNRCE0000I - INFO INSO filter exporter path: C:\\Program Files\\IBM\\WebSphere\\AppServer\\profiles\\AppSrv01\\FileNet\\server1\\INSO\\bin\\sx-8-3-7-win-x86-64\\exporter.exe
2013-05-23T12:46:07.609 2E465F1E SEC  FNRCE0000I - INFO Max connection attempts for ActiveDirectoryProvider is set to 2
2013-05-23T12:46:07.609 2E465F1E SEC  FNRCE0000I - INFO Start resolving LDAP URL for host=[192.168.71.130], port=[389]
2013-05-23T12:46:07.718 2E465F1E SEC  FNRCE0000I - INFO Final LDAP URL for host [192.168.71.130] is: ldap://192.168.71.130:389, whose IP is: 192.168.71.130.
2013-05-23T12:46:07.843 2E465F1E SEC  FNRCE0000I - INFO Succeeded connecting to ldap://192.168.71.130:389
2013-05-23T12:46:07.843 2E465F1E SEC  FNRCE0000I - INFO Start resolving LDAP URL for host=[192.168.71.130], port=[3268]
2013-05-23T12:46:07.843 2E465F1E SEC  FNRCE0000I - INFO Final LDAP URL for host [192.168.71.130] is: ldap://192.168.71.130:3268, whose IP is: 192.168.71.130.
2013-05-23T12:46:07.859 2E465F1E SEC  FNRCE0000I - INFO Succeeded connecting to ldap://192.168.71.130:3268
2013-05-23T12:46:07.859 2E465F1E SEC  FNRCE0000I - INFO Connected to GC on current host: 192.168.71.130
2013-05-23T12:46:09.359 44CCEFCD CBR  FNRCE0000I - INFO binary_recognizer_config.xml located in the default location
2013-05-23T12:46:10.671 44CCEFCD CBR  FNRCE0000I - INFO css_mime_actions_config.xml located in the default location
2013-05-23T12:46:11.031 2E465F1E ENG  FNRCE0000I - INFO Pre-load inuse memory = 130153K
2013-05-23T12:46:21.062 2E465F1E ENG  FNRCE0000I - INFO After loading metadata for object store #1: 'GraniteOaks' inuse memory = 146299K  without explicit GC
2013-05-23T12:46:21.265 2E465F1E CSTG FNRCE0000I - INFO ContentQueueDispatcher starting : 
2013-05-23T12:46:21.281 2E465F1E REPL FNRCE0000I - INFO InboundReplicationDispatcher starting : 
2013-05-23T12:46:21.281 2E465F1E REPL FNRCE0000I - INFO OutboundReplicationDispatcher starting : 
2013-05-23T12:46:21.750 44CCEFCD CSTG FNRCE0000I - INFO ContentQueueDispatcher:GraniteOaks serial=10 is enabled
2013-05-23T12:46:21.750 0848E9F8 ASYN FNRCE0000I - INFO QueueItemDispatcher:GraniteOaks serial=11 is enabled
2013-05-23T12:46:21.750 0848E9F8 ASYN FNRCE0000I - INFO QueueItemDispatcher: GraniteOaks: Starting queue dispatching.
2013-05-23T12:46:21.765 6B4A524A REPL FNRCE0000I - INFO OutboundReplicationDispatcher:GraniteOaks serial=15 is enabled
2013-05-23T12:46:21.765 71D9EA65 SWP  FNRCE0000I - INFO SweepDispatcher:GraniteOaks serial=17 is enabled
2013-05-23T12:46:21.750 D7584661 PUBL FNRCE0000I - INFO PublishRequestDispatcher:GraniteOaks serial=12 is enabled
2013-05-23T12:46:21.765 D7584661 PUBL FNRCE0000I - INFO PublishRequestDispatcher: GraniteOaks: Starting queue dispatching.
2013-05-23T12:46:21.750 30A0DC36 REPL FNRCE0000I - INFO InboundReplicationDispatcher:GraniteOaks serial=14 is enabled
2013-05-23T12:46:21.859 44CCEFCD CSTG FNRCE0000I - INFO ContentQueueDispatcher [{064E034B-CFA2-4A78-BC1B-2297F997076F}] Session Id={F7475D64-054A-4686-84D2-07208C6AD617}
2013-05-23T12:46:49.468 766A43F6 SEC  FNRCE0000I - INFO NonceCache initialized: initial capacity = 50, max capacity = 0, time to live (seconds) = 60
2013-05-23T12:49:07.140 A7EE2594 ENG  FNRCS0001E - ERROR method name: <init> principal name:  Global Transaction: null User Transaction: null Exception Info: Access to Content Engine was not allowed because the request was made anonymously instead of by an authenticated user. The application server reported that the user was anonymous.\n
   com.filenet.api.exception.EngineRuntimeException: FNRCS0001E: SECURITY_ANONYMOUS_DISALLOWED: Access to Content Engine was not allowed because the request was made anonymously instead of by an authenticated user. The application server reported that the user was anonymous.\n	
   at com.filenet.engine.context.SecurityContext.<init>(SecurityContext.java:87)\n	
   at com.filenet.engine.context.ServerCallContext.<init>(ServerCallContext.java:136)\n	
   at com.filenet.engine.context.ServerCallContext.newInstance(ServerCallContext.java:1156)\n
   at com.filenet.engine.jca.impl.RequestBrokerImpl.getRequestForwardingURI(RequestBrokerImpl.java:466)\n	
   at com.filenet.engine.ejb.EngineCoreBean._getRequestForwardingURI(EngineCoreBean.java:715)\n	
   at com.filenet.engine.ejb.EngineCoreBean.getRequestForwardingURI(EngineCoreBean.java:697)\n	
   at com.filenet.engine.ejb.EJSLocalStatelessEngineCore_22877cb1.getRequestForwardingURI(Unknown Source)\n	
   at com.filenet.engine.ejb.EngineBean.methodInit(EngineBean.java:200)\n	
   at com.filenet.engine.ejb.EngineBean.getObjects(EngineBean.java:365)\n	
   at com.filenet.apiimpl.transport.ejbstubs.EJSRemoteStatelessEngine_2e64c374.getObjects(Unknown Source)\n	
   at com.filenet.apiimpl.transport.ejbstubs._Engine_Stub.getObjects(_Engine_Stub.java:515)\n	
   at com.filenet.apiimpl.transport.ejb.EJBSession$EJBImpl._getObjects(EJBSession.java:621)\n	
   at com.filenet.apiimpl.transport.ejb.EJBSession$EJBImpl.run(EJBSession.java:525)\n	
   at java.security.AccessController.doPrivileged(AccessController.java:314)\n	
   at javax.security.auth.Subject.doAs(Subject.java:573)\n	
   at com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:195)\n	
   at com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:152)\n	
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n	
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)\n	
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)\n	
   at java.lang.reflect.Method.invoke(Method.java:611)\n	
   at com.filenet.apiimpl.util.J2EEUtilWS.doAs(J2EEUtilWS.java:220)\n	
   at com.filenet.apiimpl.transport.ejb.EJBSession$EJBImpl.getObjects(EJBSession.java:554)\n	
   at com.filenet.apiimpl.transport.ejb.EJBSession.getObjects(EJBSession.java:456)\n	
   at com.filenet.apiimpl.util.SessionHandle.getObjects(SessionHandle.java:381)\n	
   at com.filenet.apiimpl.core.Session.callGetObjects(Session.java:92)\n	
   at com.filenet.apiimpl.core.Session.executeGetObject(Session.java:297)\n	
   at com.filenet.apiimpl.core.Session.getObject(Session.java:311)\n	
   at com.filenet.apiimpl.core.IndependentObjectImpl.getObject(IndependentObjectImpl.java:149)\n	
   at com.filenet.apiimpl.core.IndependentObjectImpl.refresh(IndependentObjectImpl.java:157)\n	
   at com.filenet.api.core.Factory$Domain.fetchInstance(Factory.java:2219)\n	
   at com.filenet.acce.mediator.P8BaseMediator.getDomain(P8BaseMediator.java:91)\n	
   at com.filenet.acce.mediator.P8InstanceMediator.executeGet(P8InstanceMediator.java:154)\n
   at com.filenet.acce.mediator.P8InstanceMediator.execute(P8InstanceMediator.java:118)\n	
   at com.filenet.acce.AccePluginService$1.run(AccePluginService.java:115)\n
   at java.security.AccessController.doPrivileged(AccessController.java:314)\n
   at javax.security.auth.Subject.doAs(Subject.java:573)\n
   at com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:195)\n
   at com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:152)\n
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)\n
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)\n
   at java.lang.reflect.Method.invoke(Method.java:611)\n
   at com.filenet.apiimpl.util.J2EEUtilWS.doAs(J2EEUtilWS.java:220)\n
   at com.filenet.api.util.UserContext.doAs(UserContext.java:143)\n
   at com.filenet.acce.AccePluginService.doPrivileged(AccePluginService.java:134)\n
   at com.filenet.acce.AccePluginService.execute(AccePluginService.java:92)\n
   at com.ibm.ecm.util.PluginUtil.invokeService(PluginUtil.java:595)\n
   at com.ibm.ecm.struts.actions.PluginAction.executeBaseAction(PluginAction.java:109)\n
   at com.ibm.ecm.struts.actions.BaseAction.execute(BaseAction.java:166)\n
   at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)\n
   at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)\n
   at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)\n
   at com.ibm.ecm.struts.controller.ControllerServlet.process(ControllerServlet.java:238)\n
   at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:525)\n
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:595)\n
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)\n
   at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1224)\n
   at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:774)\n
   at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:456)\n
   at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:178)\n
   at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:136)\n
   at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:79)\n
   at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:928)\n
   at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1025)\n
   at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:87)\n
   at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:895)\n
   at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1662)\n
   at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:195)\n
   at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:452)\n
   at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:511)\n
   at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:305)\n
   at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:83)\n
   at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)\n
   at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)\n
   at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)\n
   at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)\n
   at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)\n
   at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)\n
   at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)\n
   at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1690)