トレース・ロギング出力の分析
このセクションでは、アプリケーションの実行時に生成されたトレース・ログ・ファイルの内容について説明します。このセクションに含まれている例では、FileNet® のカスタム・レイアウト・クラスである com.filenet.apiimpl.util.TraceLayout に定義されたフォーマット・パターンを使用するログ項目を示します。 このレイアウト・クラスは、サーバーが TraceLoggingConfiguration オブジェクトに基づいて log4j を自動的に構成する場合に使用されます。
カスタム・レイアウト・クラスを使用すると、すべてのメッセージは以下のフォーマットでトレース・ログに書き込まれます。
<TZ time> <thread id> <sub-system> - <level> <message>
ここで
- TZ time: レース・ログが生成されているマシンのローカル時間。ログには、次の例のような協定世界時からのタイム・ゾーン・オフセットも含まれています。
All times are local; the time zone is Pacific Standard Time(UTC -08:00)
- thread id : 8 文字の 16 進形式を使用して、トレース項目をログに記録する Java™ スレッドのハッシュ・コード。必要な場合は先頭にゼロが付加されます。例: 802284C6。
- sub-system : 影響を受けるサブシステムを示す最大 4 文字の省略語。必要な場合はスペースが付加されます。サブシステムの省略語のリストは、「サポートされる FileNet P8 サブシステム」を参照してください。
- level: エラー、警告、またはその他の通知メッセージがトレース・ログに書き込まれる場合、メッセージ・テキストの接頭部に level 名が付加されます。 例:「2013-09-19T11:59:52.341 4B56AA71 WSI FNRCE0000D - DEBUG Using Principal<gcd_admin> from UserContext」。 サポートされるロギング・レベルのリストは、「エラー・ロギング・レベルの選択」を参照してください。
- message : トレース・ログ・ファイルに直接書き込まれる、以下の変換を含むログ・メッセージのテキスト。
- すべてのスタック・トレース・ロギング項目は常に単一行に圧縮され、各ステートメントの間に改行マーカーが入ります。
- メッセージのオリジナル・テキスト内にあるすべての改行 (復帰、改行、復帰と改行の組み合わせを含む) は、エスケープ・シーケンス「¥n」に変換されます。
- メッセージのオリジナル・テキスト内に単一の円記号文字がある場合は、すべて 2 つの円記号「¥¥」に変換されます。
- エラー・メッセージが Throwable と共にログに記録された場合、Throwable 情報 (クラス名と複数のスタック・トレース行) が「¥n」エスケープ・シーケンス区切り文字を使用してメッセージ・テキストに付加されます。これにより、連続するトレース・ログ項目がそれぞれ新規行に表示されます。
出力項目の変換
ログ・ファイル内の項目を拡張 (改行ごとに新規行を作成) したり、2 つの円記号を 1 つの円記号に変換したりするには、SED スクリプトを作成して実行します。
- テキスト・ファイルを作成し、次の行を入力します。
s/¥¥¥¥/¥¥b/g s/¥¥n/¥ /g s/¥¥b/¥¥/g
注: この例では、行末 (改行) マーカーが、円記号「n」(¥n) としてスクリプト・ファイル内に直接指定されています。ご使用の SED のバージョンによっては、拡張されたテキストに新規行を正しく表示するために、このマーカーを別の方法で指定する必要がある場合があります。 例えば、一部のシステムでは、行末 (改行) マーカーを (¥r¥n) と表す必要があります。 - テキスト・ファイルを SED スクリプトとして保存します。例えば、ExpandTrace.sed のようにします。
- 次のようにして、ご使用のトレース・ログ・ファイルで新規の SED スクリプトを実行し、出力を別のファイルにリダイレクトします。
sed -f ExpandTrace.sed p8_server_trace.log > expanded_trace.log
log4j 出力の分析
トレース・ロギング出力は、Chainsaw (log4j パッケージに含まれます) などのツールを使用して分析できます。この log4j 出力のリアルタイム GUI ビューアーおよびフィルターでは、入力を XML 形式にする必要があります。詳細については、log4j Chainsaw の資料 (http://logging.apache.org/chainsaw/) を参照してください。
また、適切なサード・パーティー・ツール、共通テキスト・ファイル分析ツール (grep、tail、awk、diff など) を使用することもできます。 または Windows の同等製品 (Windows Grep、ワードパッド、メモ帳など) を使用することもできます。
サンプル出力
以下の項目は、生成されたトレース・ロギングおよびエラー・ロギングの出力例を示しています。 ログに記録された情報の正確なフォーマットはリリースごとに変更される可能性があり、特定の環境を表すという保証はありません。
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)