AWS X-Rayを使ってAPIをトレースしよう！！

GX推進グループ AWS Java

マネックス証券 システム開発推進部のHです。

はじめに

今回はCDKではなく、普通のAWSネタです。
例えばアプリケーションで時間がかかっている処理がある場合にどうやって調査しますか？
1台のサーバーに全部の業務アプリケーションが入っているようであれば、そのサーバーのログを追っていけばわかることが多いと思います。(もちろんわからないことも多いと思います) もしくはDBで時間がかかっているクエリを見つけるとか。 一方でマイクロサービスの場合は複数のサーバーがあり、ネットワークがありということでどこがボトルネックになっているかわからないこともあるかと思います。
今回はAWS上にAPI Gateway＋AWS Fargate＋Amazon Auroraの構成を作り、AWS X-Rayを使って一連の流れをトレースしてみます。

  • AWS X-Rayは、API GatewayやEC2、ECS、Fargateなどが送信するトレース情報を画面上で確認できます。

docs.aws.amazon.com

構成のイメージ

AWS環境の構成としては下図のようにシンプルに作ります。ただしFargateでは2つのコンテナを実行します。その理由としては以下の通りです。

  • X-Rayにトレース情報送信する仕組みが必要で、AWSからX-Rayデーモンとして提供されています。これをサイドカーコンテナとして起動します。
    AWS X-Ray デーモン

  • 業務アプリケーションコンテナとしては、X-Rayに送信するトレース情報をデーモンプロセスに送信します。

環境を作ってみる

■REST APIの作成

以下のREST APIを作成します。ちょうど最近東京オリンピックがあったので、日本のメダル数を返すようなものを作ります。

  • [API-1]ランダムで任意の競技のメダル数(金、銀、銅)を返します。
  • [API-2]日本が取った全部の競技のメダル数を返します。
  • [API-3]異常系(例外を発生させます。X-Rayで異常系の確認をするため)

AWSリソース(API GatewayやFargate)の構築については、前回書いているので、今回は割愛しますが、X-Rayを使用する上でいくつかポイントがあるので、そこを記載します。

■Aurora

下記のデータを持つDB、テーブルを作成します。AuroraにはX-Rayの設定はありません。

■Fargate

□業務アプリケーションについて

アプリはJavaで作成し、フレームワークはSpring Bootを使用します。X-Rayに関する定義がいくつかありますが、今回業務ロジックは特に修正しません。(X-Ray SDKを使用した処理を追加することで、より細かいトレース情報を得ることはできます)

〇build.gradle

X-Ray SDKのライブラリを追加します。

dependencyManagement {
  imports {
    mavenBom('com.amazonaws:aws-xray-recorder-sdk-bom:2.9.1')
  }
}

dependencies {
  …
  implementation 'com.amazonaws:aws-xray-recorder-sdk-core'
  implementation 'com.amazonaws:aws-xray-recorder-sdk-aws-sdk'
  implementation 'com.amazonaws:aws-xray-recorder-sdk-aws-sdk-instrumentor'
  implementation 'com.amazonaws:aws-xray-recorder-sdk-slf4j'
  implementation 'com.amazonaws:aws-xray-recorder-sdk-sql-postgres'
  implementation 'com.amazonaws:aws-xray-recorder-sdk-spring'
}
〇ログ出力設定

標準出力ログにトレースIDを出力するようlogbackのアペンダーに%X{AWS-XRAY-TRACE-ID}を追加します。

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <charset>UTF-8</charset>
        <pattern>%d{yyyy/MM/dd HH:mm:ss.SSS} %-5level [%thread] - %X{AWS-XRAY-TRACE-ID} - %msg%n</pattern>
    </encoder>
</appender>
〇X-Rayの設定

X-Rayの設定はここを参考に設定していきます。またコントローラーやサービスをトレースするために、ここを参考にして「@XRayEnabled」アノテーションを利用できるようにします。

@Aspect
@Configuration
@EnableAspectJAutoProxy
public class XrayConfig extends AbstractXRayInterceptor {
    static {
        AWSXRayRecorderBuilder builder = AWSXRayRecorderBuilder
                .standard()
                .withPlugin(new EC2Plugin())
                .withPlugin(new ECSPlugin())
                .withSegmentListener(new SLF4JSegmentListener());

        AWSXRay.setGlobalRecorder(builder.build());
    }

    @Bean
    public Filter TracingFilter() {
        return new AWSXRayServletFilter("Eblog-202109");
    }
    
    @Override
    @Pointcut("""
             @within(com.amazonaws.xray.spring.aop.XRayEnabled)
               && execution(* jp.co.monex.example..*.*(..))
            """)
    protected void xrayEnabledClasses() {
    }
}
〇Aurora設定

ここを参考にデータソースの設定にSDK for Java JDBC インターセプターを追加して、SQLクエリを計測できるようにします。(dataSourceFactory.setJdbcInterceptors()の部分)ちなみにX-Rayのトレースには、SQLは出力されません。セキュリティ上の理由だそうです。クエリをX-Rayに送信したい場合は、手動でX-Rayのセグメント、サブセグメントを作成して追加する形になるかと思います。

@Configuration
public class RdsConfig {

    @Bean
    public RdsInstanceConfigurer instanceConfigurer() {
        return new RdsInstanceConfigurer() {
            @Override
            public DataSourceFactory getDataSourceFactory() {
                TomcatJdbcDataSourceFactory dataSourceFactory 
                   = new TomcatJdbcDataSourceFactory();
                dataSourceFactory.setInitialSize(10);
                dataSourceFactory.setMaxActive(50);
                dataSourceFactory.setDefaultAutoCommit(false);
                dataSourceFactory.setValidationQuery("SELECT 1");
                dataSourceFactory.setRemoveAbandoned(true);
                dataSourceFactory.setTestOnBorrow(true);
                dataSourceFactory.setTestWhileIdle(true);
                dataSourceFactory.setJdbcInterceptors(
                  "com.amazonaws.xray.sql.postgres.TracingInterceptor");  

                return dataSourceFactory;
            }
        };
    }
}
〇サービス

サービスクラスに「@XRayEnabled」をつけて、X-Rayでトレースできるようにします。また、以下のメソッドを実装します。

  • ランダムで任意の競技のメダル数(金、銀、銅)を返します。
    ⇒まずテーブルの件数を取得します。
    ⇒ランダムの番号のデータを取得し、返します。
  • 全件取得
@XRayEnabled
@Service
public class SampleService {
...
}
〇コントローラ

コントローラクラスに「@XRayEnabled」をつけて、X-Rayでトレースできるようにします。また、各APIに対応したメソッドを実装します。

  • ランダムで任意の競技のメダル数(金、銀、銅)を返します。
  • 日本が取った全部の競技のメダル数を返します。
  • 異常系
@XRayEnabled
@RestController
public class SampleController {
...
}

ちなみに異常系については、下記処理を追加することでX-Rayに例外を送信できます。

AWSXRay.getCurrentSegment().addException(例外);
または
AWSXRay.getCurrentSubsegment().addException(例外);
□Fargateの設定

上記に記載した通り、X-Rayデーモンと業務アプリケーションの2つのコンテナを起動します。さらにX-Ray用の設定があります。

  • ECSクラスタやサービスには特別な設定は不要です。
  • タスク定義の設定
    • タスクロールにX-Rayアクセスのポリシーを追加(今回はAWSXrayFullAccessでやっています)
    • X-Rayデーモンコンテナ
      • ポートマッピングはUDP2000ポートで行います。
    • 業務アプリケーションコンテナ
      • CloudWatch Logsの設定を忘れずに。

      • X-Rayデーモンと通信を行うための環境変数を定義します。X-RayデーモンのIPアドレスどうやって指定するのだろうと思っていたら、localhostでできました。

        環境変数 設定値
        AWS_REGION ap-northeast-1
        AWS_XRAY_DAEMON_ADDRESS localhost:2000

■API Gateway

API Gatewayについては、ステージ⇒「ログ/トレース」タブでX-Rayトレースの有効化にチェックを入れるだけでAPIのトレースがX-Rayに転送されます。(なんて簡単！)
※2021年8月現在東京リージョンはX-Rayに対応していますが、大阪リージョンはまだ対応されていないようです。(AWSさん対応してください)

X-Rayの画面を見てみる

構築したAPI Gatewayに対してリクエストを投げ、そのトレースをX-Rayの画面で確認します。

[API-1]ランダムで任意の競技のメダル数(金、銀、銅)を返します。

  • curlコマンドでリクエストを投げます。
    コマンド
$ curl https://xxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/prod/random
競技: 陸上、金: 0、銀: 1、銅: 1

  • トレースの画面

  • トレースの詳細
    API Gateway～Fargate～Aurora間の一連のトレースを見ることができます。それぞれの所要時間が表示されるため、処理性能に問題がある場合は、ここでボトルネックとなる部分を見つけることができます。

    • API Gatewayでは、API GatewayからFargateのエンドポイント(この場合はELBへのHTTPでのアクセス)の呼び出し部分が表示されます。
    • ECSではFargate～Aurora間の呼び出し部分が表示されます。getRandomDataが2つありますが、上はコントローラ、下はサービスとなります。サービス内で2回DB呼び出しをしているため、postgres(aurora)が2回表示されます。

  • トレースID
    API Gateway～データベースアクセスを紐づけるIDです。

  • ①
    詳細画面には以下の情報が表示されます。

    • 概要タブ
      リクエスト元のIPアドレスやユーザーエージェントなどを確認できます。

    • リソースタブ
      使用しているAWSアカウント、APIのIDやステージなどが表示されます。

  • ②
    API Gatewayから呼び出されるELBのURLやメソッド、ステータスなどの情報が表示されます。

  • ③
    ECS(Fargate)のトレース情報を表示します。呼び出し元のELBの情報が表示されますが、ユーザーエージェントが「AmazonAPIGateway_[APIのID]」となっています。業務アプリケーションからはクライアントのユーザーエージェントが分からないため、API Gatewayが送信するトレース情報との連携は重要です。

  • ④
    コントローラクラスのトレース情報を表示します。メタデータタブにコントローラのクラス名が表示されます。

  • ⑤
    サービスクラスのトレース情報を表示します。メタデータタブにサービスのクラス名が表示されます。

  • ⑥、⑦
    DBアクセスに対するトレース情報を表示します。getRandomメソッドでは1度目のDBアクセスでデータ件数を取得し、2度目のDBアクセスでデータの取得を行っているので、2件トレース情報が出力されます。SQLタブに接続先のDBやバージョン、JDBCドライバーのバージョン、URLなどが表示されます。タブ名からSQLが表示されるのかと思いますが、上記にも記載した通りセキュリティ上の理由のため表示されません。必要があれば手動で追加できます。

  • CloudWatch Logsでログを確認。
    上記の方でlogbackのアペンダーにトレースIDを出力するよう設定したので、CloudWatch LogsにてトレースIDでフィルタすると、API実行のログを表示することができます。
    以上でAPI Gatewayから実行されたAPIのトレースを確認でき、さらに紐づくログの確認まで行えました。

[API-2]日本が取った全部の競技のメダル数を返します。

  • curlコマンドでリクエストを投げます。
    コマンド
$ curl https://xxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/prod/all | jq
[
  "競技: アーチェリー、金: 0、銀: 0、銅: 2",
  "競技: ウエイトリフティング、金: 0、銀: 0、銅: 1",
  "競技: 空手、金: 1、銀: 1、銅: 1",
  "競技: 競泳、金: 2、銀: 1、銅: 0",
  "競技: ゴルフ、金: 0、銀: 1、銅: 0",
  "競技: サーフィン、金: 0、銀: 1、銅: 1",
  "競技: 自転車、金: 0、銀: 1、銅: 0",
  "競技: 柔道、金: 9、銀: 2、銅: 1",
  "競技: スケートボード、金: 3、銀: 1、銅: 1",
  "競技: スポーツクライミング、金: 0、銀: 1、銅: 1",
  "競技: 体操、金: 2、銀: 1、銅: 2",
  "競技: 卓球、金: 1、銀: 1、銅: 2",
  "競技: バスケットボール、金: 0、銀: 1、銅: 0",
  "競技: バドミントン、金: 0、銀: 0、銅: 1",
  "競技: フェンシング、金: 1、銀: 0、銅: 0",
  "競技: ボクシング、金: 1、銀: 0、銅: 2",
  "競技: 野球・ソフトボール、金: 2、銀: 0、銅: 0",
  "競技: 陸上、金: 0、銀: 1、銅: 1",
  "競技: レスリング、金: 5、銀: 1、銅: 1"
]
  • トレース詳細の画面 トレース詳細はこちら。前のメソッドと比べてもDBアクセス回数が少ないくらいです。

[API-3]異常系

  • curlコマンドでリクエストを投げます。
    コマンド
$ curl https://xxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/prod/exception
予期せぬエラーが発生しました。

  • トレース詳細の画面 ECS(Fargate)で異常が発生していることが確認できます。

  • ①
    レスポンスのステータスが500で、異常値を返していることが分かります。「エラーと障害」の障害もtrueとなっています。

  • ②
    例外タブで例外を確認することもできます。

  • CloudWatch Logsでログを確認 もちろんCloudWatch Logsからも例外は確認できます。ただトレースIDでフィルタするとスタックトレース部分が見えないので、X-Rayの方で見た方が分かりやすいかもしれません。

おわりに

今回はAWS X-Rayを使用して、APIのトレースをしてみました。マイクロサービスにおける処理性能のボトルネックを見つけたり、障害の根本原因の特定に役立てるかと思います。

人材募集