IBM FileNet P8, Version 5.2.1            

Analyzing Trace Logging Output

The contents of a trace log file as it was generated during application run time is described in the following sections and the included example presents log entries that use the format pattern that is 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 alternative 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:

<TZ time> <thread id> <sub-system> - <level> <message>

Where:

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 each double backslash back to a single backslash. For information about how to create and use this script, see Conversion of Output Entries.

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.

  1. 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).
  2. Save the text file as a SED script. For example, ExpandTrace.sed.
  3. 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 log4j Output

You can analyze trace logging output by 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, see the log4j Chainsaw documentation (http://logging.apache.org/chainsaw/).

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)
   


Last updated: October 2015
logging_output.htm

© Copyright IBM Corporation 2015.