アプリケーションモニタリングを使用したサーバー側 Web ページエラーの診断 - Application Real-Time Monitoring Service

サーバー側のエラー、特に 5xx レスポンスは、根本原因がビジネスロジックの奥深くに隠れていることが多いため、トラブルシューティングが最も困難な問題の 1 つです。従来のログベースのデバッグでは、SSH アクセス、手動でのログ検索、分散型サービス全体での推測が必要になります。

次の例は、Java アプリケーションの一般的なエラーログです。

2018-03-19 20:34:22,890 ERROR [io.undertow.request] (default task-84) UT005023: Exception handling request to /plan-manage.htm:
java.lang.IllegalStateException: UT000010: Session not found wFcTlKtkzPiwMyNtBTFv48jU
	at io.undertow.server.session.InMemorySessionManager$SessionImpl.getAttribute(InMemorySessionManager.java:353) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.spec.HttpSessionImpl.getAttribute(HttpSessionImpl.java:121) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper.saveContext(HttpSessionSecurityContextRepository.java:323) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.security.web.context.HttpSessionSecurityContextRepository.saveContext(HttpSessionSecurityContextRepository.java:117) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:93) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160) [spring-security-web-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:344) [spring-web-4.0.6.RELEASE.jar:4.0.6.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:261) [spring-web-4.0.6.RELEASE.jar:4.0.6.RELEASE]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) [spring-web-4.0.6.RELEASE.jar:4.0.6.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.0.6.RELEASE.jar:4.0.6.RELEASE]
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:85) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:56) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:63) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:58) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:261) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:247) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:76) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:166) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:197) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:759) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_45]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_45]
	at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_45]

Application Real-Time Monitoring Service (ARMS) は、バイトコードインストルメンテーションを通じてこのオーバーヘッドを排除します。ARMS エージェントをインストールすると、コードを変更することなく、例外が自動的にキャプチャ、集約、追跡されます。単一のコンソールから、例外が最初にいつ発生したか、どのくらいの頻度で再発するか、どのメソッド呼び出しがそれをトリガーしたかを特定できます。

このアプローチは、特に次のような場合に役立ちます。

分散クラスター全体で特定の例外が発生した時間と頻度を特定する。
今日の例外を昨日の例外と比較したり、リリース後の例外をリリース前のベースラインと比較したりする。
特定の例外について、パラメーター、アップストリーム呼び出し、ダウンストリーム呼び出しなどの完全なリクエストコンテキストを取得する。
サポートチケットで参照されている失敗したトランザクションを根本原因までトレースする。

仕組み

診断ワークフローは 3 つのステージで構成されます。

アプリケーションに ARMS エージェントをインストール し、例外データの自動収集を開始します。
例外統計を確認 し、傾向、急増、最も頻繁に発生するエラーの種類を特定します。
コールスナップショットとメソッドスタックをドリルダウンして、例外を根本原因までトレース します。

前提条件

アプリケーションに ARMS エージェントをインストールします。デプロイに合った方法を選択してください。

Java アプリケーション：ARMS エージェントの手動インストール
Container Service for Kubernetes (ACK) 内の Java アプリケーション：ACKへのARMS エージェントの自動インストール
オープンソースの Kubernetes クラスター内の Java アプリケーション：Kubernetes環境へのARMS エージェントの自動インストール

インストール後、エージェントは前日比および前週比の比較とともに、メトリクスの自動収集を開始します。追跡されるメトリクスには、平均応答時間、リクエスト数、エラー、リアルタイムインスタンス、フル GC イベント、低速 SQL クエリ、例外、低速呼び出しが含まれます。

例外統計の確認

ARMS コンソールを使用して、最も頻繁に発生する例外と、傾向の経時変化を特定します。

ARMS コンソールにログインします。
左側メニューで、[アプリケーションモニタリング] > [Applications] を選択します。
上部メニューで、アプリケーションがデプロイされているリージョンを選択します。
[Applications] ページで、お使いのアプリケーションの名前をクリックします。
[Application Overview] ページで、[Overview] タブをクリックします。下部のセクションには、例外の総数と、前日比および前週比の変化が表示されます。
[Statistics Analysis] セクションまでスクロールし、[Exception Type] を見つけます。この内訳には、各例外タイプが発生した回数が表示されます。
左側メニューで [Application Details] をクリックします。[Application Details] ページで、[Exception Analysis] タブをクリックして、例外統計グラフ、エラー数、および例外スタックを表示します。

例外の根本原因のトレース

例外統計は、何が失敗しているかは示しますが、その理由は示しません。ログファイル内のスタックトレースは、どの行が例外をスローしたかを示しますが、完全なアップストリームおよびダウンストリームの呼び出しコンテキストとリクエストパラメーターが欠けています。

ARMS は、バイトコードインストルメンテーションによってこのギャップに対処します。最小限のパフォーマンスオーバーヘッドで、すべての例外についてアップストリームおよびダウンストリームの完全なコールスナップショットをキャプチャします。これにより、根本原因を特定するために必要な、パラメーター、コールチェーン、メソッドスタックなどの完全なリクエストコンテキストが得られます。

[Exception Analysis] タブで、診断する例外タイプを見つけ、[Actions] 列の [Interface Snapshot] をクリックします。[Interface Snapshot] タブには、この例外タイプに関連付けられたコールトレースが表示されます。
特定の呼び出しの [TraceId] をクリックして、その完全なトレースを開きます。
説明
高度なトレースフィルタリングについては、「トレースクエリ」をご参照ください。
トレース詳細ページで、完全なコールチェーンを確認します。[Method Stack] 列で虫眼鏡アイコンをクリックしてメソッドスタックを検査し、失敗した呼び出しの完全な実行コンテキストを把握します。
メソッドスタック には、合計トレース期間が 58947 ms と表示されています。主要な呼び出しは次のとおりです。
- Tomcat Servlet Process (58947 ms)
- sun.net.www.protocol.http.HttpURLConnection.getInputStream() (1476行、21 ms、例外メッセージ：java.io.IOException: Server)
- org.apache.http.impl.client.CloseableHttpClient.execute(...) (81行、104 ms)
- org.apache.http.protocol.HttpRequestExecutor.execute(...) (118行、93 ms)
- com.alibaba.arms.console.service.impl.ArmsContextServiceImpl.clear() (79行、0 ms)

根本原因を特定したら、基になるコードを修正します。追加の例外を解決するには、[Exception Analysis] タブに戻り、他の失敗した呼び出しを確認します。

プロアクティブなアラートの設定

例外が発生した瞬間にチームに通知され、発見が遅れることがないように、アラートルールを設定します。アプリケーション内の特定の API またはすべての API に対してアラートルールを作成できます。詳細については、「アプリケーションモニタリングのアラートルール」をご参照ください。