ENGINEER BLOG

こんにちは。CI本部の石田です。

「Observability」や「可観測性」と言ったキーワードを聞いたことありますか？今回は、最近、目にすることも多くなったObservabilityの紹介と、その考え方を簡易的に取り入れる事で、トラブルシューティングの進め方がどのように変わるのかお伝えしたいと思います。

1. エラー検知、調査開始

1.1. プロローグ

AWS環境でコンテナ化された複数のWebアプリケーションが連携して業務を提供するシステムでエラーを検知しメール通知があったのですぐに調査を開始。

検知したエラーはフロントエンドであることがメールを確認すればわかるため、まずは、フロントエンドのログを参照しエラー箇所を特定後、どういった経緯でエラーとなったのかを確認するためログを遡る。なお、フロントエンドのログにはユーザ識別IDがすべてのログに書き込まれているので、ログ量が多くても調査対象のログを簡単に遡って確認することが出来る。

エラーとなった理由はバックエンドのAPIからの戻りが想定外だったのが原因のようなので、フロントエンドからリクエストしているバックエンドのAPIのログを参照するため、フロントエンドのAPIリクエスト時間とURL情報からバックエンドのAPIログを特定する。なお、バックエンドは多くのリクエストを受け付けているため複数のリクエストのログが混在しているが、ユーザ識別IDなどは出力されないのでスレッド名を頼りにログを調査していく。

調査を進めたところ、バックエンドのAPIは更に複数のAPIをコールしており、最終的に規定の時間内に全処理が完了できなかったためタイムアウトしてフロントエンドにエラーレスポンスを返したが、そのレスポンスに不備があったのが今回のエラーに繋がっている事がわかった。

フロントエンドでエラーとなった原因は分かったが、バックエンドAPIがコールしているAPIで時間がかかっている箇所も合わせて調査をする必要がある。すぐに取り掛かりたいが、調査に入る前にコールしたAPIのリクエスト時間からログを一つ一つ抽出しなくてはならない・・・APIを8回コールしているのでログ抽出だけでそれなりに時間を要しそうだ・・・

1.2. トラブルシューティングにおける課題

ここまで大変では無いかもしれませんが、近い経験をしたことのある方は多いのではないでしょうか(システム全体で日々数十GBのログを出力するシステムで経験したことがあります(苦笑))。

従来の3層アーキテクチャの場合、構成や依存関係がシンプルなため人手でも原因の追跡が可能でしたが、マイクロサービスアーキテクチャなどを採用すると多くのサービスと連携したシステムとなり、人間の力だけでは原因の追跡が困難になってきます。また、今までの監視はサーバダウンやリソースの閾値超えなど今までの経験から想定できる障害に対応できる監視でしたが、コンテナ化されたシステムはサーバは使い捨て、APIも呼び出し先の更に先のAPIの処理遅延が原因でエラーになるなど、どこでどのような障害が起きるかわからないため、それらを想定した監視を行うのも難しくなります。さらに最近では、Webサービスにおけるユーザ体験(UX)が重要視され、ユーザからのリクエストに短時間でレスポンスできるシステムが求められることにより、レイテンシの監視やコンテンツが表示されるまでの時間なども監視対象となってきています。

このような想定できない障害の発生や利用者の操作性など、システム全体のボトルネックとなる部分を見える化するニーズに応えるため、Observability(オブザーバビリティ：可観測性)という考え方が登場しました。

2. What’s Observability?

2.1. Observabilityについて

Observabilityというキーワード、クラウドネイティブなシステム開発を経験されている方は聞いたことがあるかもしれませんが、聞いたことが無いという方も多いと思います。Observabilityがどういったものであるかは、Observabilityを実現するための標準化を行っている、CNCF(Cloud Native Computing Foundation)プロジェクトであるOpen Telemetryのサイトに記載されている説明が参考になるかと思います。

What is Observability?

Observability lets us understand a system from the outside, by letting us ask questions about that system without knowing its inner workings. Furthermore, allows us to easily troubleshoot and handle novel problems (i.e. “unknown unknowns”), and helps us answer the question, “Why is this happening?”

Open Telemetryの言葉を借りると、Observabilityとは システムの内部構造を知らなくてもシステムがどういった状態なのかを把握することが出来ること で、トラブルシューティングや新たな問題への対応を容易にし、”なぜこのようなことが発生するのか”という疑問を解消するために役立てることを実現するための考え方になります。「システムがどういった状態なのかを把握」するために、

• リクエストなどのイベントが起きた時に何が起きているのかを把握するためのTraces(トレース)
• CPU使用率やJVMヒープサイズなど定期的に収集する計測データであるMetrics(メトリクス)
• 処理の実行を遡って調査するための記録情報であるLogs(ログ)

の3つを利用します。また、具体的に「把握」とはどういったことが出来るかと言うと、主に以下のようなものになります。

機能	把握できる状態
データ管理/検索	システムが生成するTraces、Metrics、Logsをリアルタイムに収集し、一元管理を行うと同時に高速な検索/集計の提供を行う
データ分析/ダッシュボード	検索/集計した結果をグラフなどに可視化し、データ分析のサポートや、関連する複数の可視化したデータをダッシュボードとして一覧表示を行う
インフラストラクチャ/ネットワークモニタリング	Kubernetesなどのコンテナ環境、オンプレなどのインフラ環境のモニタリング、SNMPやVPCなどのネットワーク情報のモニタリングを行う
APM(Application Performance Monitoring)	アプリケーションを構成する各コンポーネントのパフォーマンスモニタリングや調査を行う
RUM(Real User Monitoring)	利用者のブラウザ情報からページロード情報やJavaScript等のエラー情報の把握を行う
Synthetics	定期的にWebサイトにアクセスし、シナリオ通りに画面遷移が行え、ページロードに関するパフォーマンスに問題が起きていないことの監視を行う
機械学習との統合	AIを利用することで、大規模なシステムであっても事前に把握できない異常の監視/検知を行う

2.2. Observabilityを実現する製品やサービス

Observabilityを取り入れることでシステムの状態を把握できるようになりますが、自ら準備するのは現実的ではないため、Observabilityを実現するための製品やサービスが多く提供されています。CNCF LandscapeのObservability and Analysisカテゴリを見ても80を超えています。

※出典：Landscape

これらの製品やサービスを導入することで多くのメリットを得られますが、解決したい課題や開発・運用体制などに合わせて適切な製品を選定する必要があります。また、これらを導入する／関連する技術を取り込むだけはObservabilityを実現できるわけではなく、「自分たちはどのようにシステムの状態を把握したいのか」を常に意識しながら運用を行い、設計に反映していくことでObservabilityを実現できると考えています。

3. Observability(分散トレース)を体感

今回は、Observabilityを体感する事が目的ですので、既存の機能を修正しObservabilityの基本である分散トレースを実装して、冒頭のログ調査時間短縮を目指したいと思います。なお、分散トレースとは複数のサービスやサーバと連携して処理をする際に、リクエストが辿るパスを記録することでリクエストの追跡やパフォーマンスの問題の原因を特定をすることです。

3.1. サンプルアプリケーション

今回準備したアプリケーションは、URLに指定されたカンマ(,)区切りの数字に従って、分散されたサーバへのアクセスとsleepによる処理待ちを行い、5つのアプリケーションが連携を行います。開発、実行環境の概要は以下の通りです。

• Spring Tool Suite 4.17.2
• Java 1.8.0 Update 361
• Springboot v2.7.8
• Apache Tomcat 9.0.71
• 全アプリケーション同じプログラムで動作(ポート番号(18080～18084)のみ異なる)
• ソースコードはなるべくクラス数を少なくし、説明に必要な箇所のみを記載しております

【アプリケーション構成・連携イメージ】

3.2. 分散トレースを取り入れていないアプリケーション

■ レスポンスAPI用DTO

public class ApiResponse {

    private String requestData; 
    private long processingMilliseconds;

    // Constructor/Getter/Setterは省略
}

■ Controller

/sampleApi/nnn1,nnn2,nnn3 のようなリクエストから、先頭の nnn1 と残りの nnn2,nnn3 をcallSampleApiメソッドに渡しています。その際に、nnn1 の値を使ってsleepしています。なお、/sampleApi/nnn のように1つしか指定されていない場合は、callSampleApiメソッドは実行せず、最後の処理であることがわかるようログ出力のみを行っています。

@RestController
public class SampleApi {

    @GetMapping("/sampleApi/{instruction:[0-9]+[0-9,]*}")
    public ApiResponse getRequest(@PathVariable String instruction, HttpServletRequest req) throws Exception {
        long startTime = System.currentTimeMillis();
        logger.info("Received request   : " + req.getRequestURI());

        String[] splitInstruction = instruction.split(",");
        String nextInstruction = instruction.substring(instruction.indexOf(",") + 1);
        int InstructionNumber = Integer.parseInt(splitInstruction[0]);

        Thread.sleep((InstructionNumber * 4) / 10);

        if(splitInstruction.length != 1) {
            webClient.callSampleApi(InstructionNumber, nextInstruction);
        } else {
            logger.info("Last processing.");
        }

        Thread.sleep((InstructionNumber * 6) / 10);
        logger.info("Finished request   : " + req.getRequestURI());
        // Responseを生成して返す
        return new ApiResponse(instruction, System.currentTimeMillis() - startTime);
    }
}

■ APIコールUtil

number引数の値と稼働しているインスタンス数(NUMBER_OF_INSTANCE)の剰余からアクセスするアプリケーションを決定し、instruction引数をURLに指定してAPIをコールしています。

@Component
@Scope(ConfigurableBeanFactory.SCOPE_PROTOTYPE)
public class SampleApiWebClient {

    private static final String BASE_URL = "http://localhost";
    private static final int BASE_PORT = 18080;
    private static final int NUMBER_OF_INSTANCE = 5;    // 稼働しているインスタンス数
    
    public ApiResponse callSampleApi(int number, String instruction) {
        int port = BASE_PORT + number % NUMBER_OF_INSTANCE;
        String url = BASE_URL + ":" + port + "/sampleApi/" + instruction;
        logger.info("Call API URL       : " + url);

        HttpHeaders header = new HttpHeaders();
        header.setAccept(Arrays.asList(MediaType.APPLICATION_JSON));
        HttpEntity<String> requestEntity = new HttpEntity<>(null, header);
        ResponseEntity<ApiResponse> result = 
            restTemplate.exchange(url, HttpMethod.GET, requestEntity, ApiResponse.class);

        logger.info("Result of Call API : " + result.getBody().toString());
        return result.getBody();
    }
}

■ 実行

リクエスト受付時と処理完了時、APIコール時とその結果しかログを出力しないプログラムですので、次の2リクエストを同タイミングでアクセスを行った結果は以下の通りです。

http://localhost:18080/sampleApi/123,456,789
http://localhost:18082/sampleApi/321,654,987

【 service #0 ( localhost:18080 ) 】

16:12:17.791 --- Received request   : /sampleApi/123,456,789
16:12:17.841 --- Call API URL       : http://localhost:18083/sampleApi/456,789
16:12:19.097 --- Result of Call API : ApiResponse [requestData=456,789, processingMilliseconds=1249]
16:12:19.171 --- Finished request   : /sampleApi/123,456,789

【 service #1 ( localhost:18081 ) 】

16:12:18.029 --- Received request   : /sampleApi/789
16:12:18.345 --- Last processing.
16:12:18.383 --- Received request   : /sampleApi/654,987
16:12:18.644 --- Call API URL       : http://localhost:18084/sampleApi/987
16:12:18.818 --- Finished request   : /sampleApi/789
16:12:19.637 --- Result of Call API : ApiResponse [requestData=987, processingMilliseconds=987]
16:12:20.030 --- Finished request   : /sampleApi/654,987

【 service #2 ( localhost:18082 ) 】

16:12:18.251 --- Received request   : /sampleApi/321,654,987
16:12:18.379 --- Call API URL       : http://localhost:18081/sampleApi/654,987
16:12:20.033 --- Result of Call API : ApiResponse [requestData=654,987, processingMilliseconds=1647]
16:12:20.226 --- Finished request   : /sampleApi/321,654,987

【 service #3 ( localhost:18083 ) 】

16:12:17.845 --- Received request   : /sampleApi/456,789
16:12:18.027 --- Call API URL       : http://localhost:18081/sampleApi/789
16:12:18.820 --- Result of Call API : ApiResponse [requestData=789, processingMilliseconds=789]
16:12:19.094 --- Finished request   : /sampleApi/456,789

【 service #4 ( localhost:18084 ) 】

16:12:18.646 --- Received request   : /sampleApi/987
16:12:19.041 --- Last processing.
16:12:19.633 --- Finished request   : /sampleApi/987

アプリケーションの識別名付きで時系列にソートすると以下のようになりますが、個別ログもマージしたログも、追跡するのが厳しい印象です。皆さんが見られている実際のログはもう少し読み手に優しいかと思いますが、何も考えずにローカル環境の感覚で開発すると似たようなログになるかと思います。

16:12:17.791 --- [service #0] Received request   : /sampleApi/123,456,789
16:12:17.841 --- [service #0] Call API URL       : http://localhost:18083/sampleApi/456,789
16:12:17.845 --- [service #3] Received request   : /sampleApi/456,789
16:12:18.027 --- [service #3] Call API URL       : http://localhost:18081/sampleApi/789
16:12:18.029 --- [service #1] Received request   : /sampleApi/789
16:12:18.251 --- [service #2] Received request   : /sampleApi/321,654,987
16:12:18.345 --- [service #1] Last processing.
16:12:18.379 --- [service #2] Call API URL       : http://localhost:18081/sampleApi/654,987
16:12:18.383 --- [service #1] Received request   : /sampleApi/654,987
16:12:18.644 --- [service #1] Call API URL       : http://localhost:18084/sampleApi/987
16:12:18.646 --- [service #4] Received request   : /sampleApi/987
16:12:18.818 --- [service #1] Finished request   : /sampleApi/789
16:12:18.820 --- [service #3] Result of Call API : ApiResponse [requestData=789, processingMilliseconds=789]
16:12:19.041 --- [service #4] Last processing.
16:12:19.094 --- [service #3] Finished request   : /sampleApi/456,789
16:12:19.097 --- [service #0] Result of Call API : ApiResponse [requestData=456,789, processingMilliseconds=1249]
16:12:19.171 --- [service #0] Finished request   : /sampleApi/123,456,789
16:12:19.633 --- [service #4] Finished request   : /sampleApi/987
16:12:19.637 --- [service #1] Result of Call API : ApiResponse [requestData=987, processingMilliseconds=987]
16:12:20.030 --- [service #1] Finished request   : /sampleApi/654,987
16:12:20.033 --- [service #2] Result of Call API : ApiResponse [requestData=654,987, processingMilliseconds=1647]
16:12:20.226 --- [service #2] Finished request   : /sampleApi/321,654,987

3.3. 分散トレースを取り入れてみる

リクエストが辿るパスを記録するために識別子としてtraceIdを新しく準備し、リクエストの開始から終了まで記録し続けることで対応したいと思います。

■ トレースIDの保管クラス

@Component
public class RequestStorage {
    private static RequestStorage instance = new RequestStorage();
    private ThreadLocal<String> traceId = new ThreadLocal<>();
    
    public static String getTraceId() {
        String tid = instance.traceId.get();
        return tid;
    }

    public static void setTraceId(String traceId) {
        instance.traceId.set(traceId);
    }
}

■ Filterクラス

APIのコール先でもtraceIdを記録できるよう、リクエストヘッダにX-TRACE-IDを追加します。もし、リクエストヘッダが指定されていない場合は、新規リクエストと判断して新規のtraceIdを発行しています。なお、独自ログ項目であるtraceIdはMDC(Mapped Diagnostic Context)を利用して追加することで、既存への影響を小さくしています。

@Component
public class InitializeObservabilityFilter extends OncePerRequestFilter{

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) 
        throws ServletException, IOException {
        try {
            String traceId = request.getHeader("X-TRACE-ID");
            if(traceId == null || traceId.trim().length() == 0) {
                traceId = UUID.randomUUID().toString();
            }
            RequestStorage.setTraceId(traceId);
            MDC.put("trace.id", traceId);
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove("trace.id");
        }
    }
}

■ APIコールUtil(修正)

Filterクラスで説明した通り、traceIdをリクエストヘッダにセットしてAPIをコールするよう修正しています。

    public ApiResponse callSampleApi(int number, String instruction) {
        ～ 省略 ～

        HttpHeaders header = new HttpHeaders();
        header.setAccept(Arrays.asList(MediaType.APPLICATION_JSON));
        header.add("X-TRACE-ID", RequestStorage.getTraceId());          // ★追加
        HttpEntity<String> requestEntity = new HttpEntity<>(null, header);
        ResponseEntity<ApiResponse> result = 
            restTemplate.exchange(url, HttpMethod.GET, requestEntity, ApiResponse.class);

        ～ 省略 ～
    }

■ logback

JSON形式のログ出力の場合はMDCを使うことでMDC.putで指定した trace.id キーが追加されますが、テキストベースの出力の場合、規定のログ項目に加えてMDCで設定した項目を出力するには、 %X{trace.id} のように指定することで実現できます。設定イメージは以下の通りです。

    <appender name="CONSOLE_ADD_TRACEID" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>
                <!-- ${service.name}は、プロパティにて指定しています -->
                %date{HH:mm:ss.SSS} --- [${service.name}][%X{trace.id}] %msg%n
            </pattern>
        </encoder>
    </appender>

■ 実行

それでは、先ほどと同じリクエストを実行し、時系列でソートした結果は以下の通りです。

17:04:28.685 --- [service #0][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Received request   : /sampleApi/123,456,789
17:04:28.735 --- [service #0][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Call API URL       : http://localhost:18083/sampleApi/456,789
17:04:28.739 --- [service #3][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Received request   : /sampleApi/456,789
17:04:28.921 --- [service #3][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Call API URL       : http://localhost:18081/sampleApi/789
17:04:28.924 --- [service #1][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Received request   : /sampleApi/789
17:04:28.930 --- [service #2][7fab3c5e-4330-43bb-b981-415f0adbb7de] Received request   : /sampleApi/321,654,987
17:04:29.058 --- [service #2][7fab3c5e-4330-43bb-b981-415f0adbb7de] Call API URL       : http://localhost:18081/sampleApi/654,987
17:04:29.061 --- [service #1][7fab3c5e-4330-43bb-b981-415f0adbb7de] Received request   : /sampleApi/654,987
17:04:29.240 --- [service #1][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Last processing.
17:04:29.325 --- [service #1][7fab3c5e-4330-43bb-b981-415f0adbb7de] Call API URL       : http://localhost:18084/sampleApi/987
17:04:29.331 --- [service #4][7fab3c5e-4330-43bb-b981-415f0adbb7de] Received request   : /sampleApi/987
17:04:29.713 --- [service #1][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Finished request   : /sampleApi/789
17:04:29.715 --- [service #3][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Result of Call API : ApiResponse [requestData=789, processingMilliseconds=789]
17:04:29.726 --- [service #4][7fab3c5e-4330-43bb-b981-415f0adbb7de] Last processing.
17:04:29.989 --- [service #3][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Finished request   : /sampleApi/456,789
17:04:29.991 --- [service #0][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Result of Call API : ApiResponse [requestData=456,789, processingMilliseconds=1250]
17:04:30.064 --- [service #0][8a1e7f63-6d9b-4c24-966d-d339d5d6a987] Finished request   : /sampleApi/123,456,789
17:04:30.318 --- [service #4][7fab3c5e-4330-43bb-b981-415f0adbb7de] Finished request   : /sampleApi/987
17:04:30.325 --- [service #1][7fab3c5e-4330-43bb-b981-415f0adbb7de] Result of Call API : ApiResponse [requestData=987, processingMilliseconds=987]
17:04:30.719 --- [service #1][7fab3c5e-4330-43bb-b981-415f0adbb7de] Finished request   : /sampleApi/654,987
17:04:30.720 --- [service #2][7fab3c5e-4330-43bb-b981-415f0adbb7de] Result of Call API : ApiResponse [requestData=654,987, processingMilliseconds=1658]
17:04:30.912 --- [service #2][7fab3c5e-4330-43bb-b981-415f0adbb7de] Finished request   : /sampleApi/321,654,987

traceIdが追加となったことでログボリュームが増えましたが、「リクエスト：/sampleApi/321,654,987」に着目したい場合、 7fab3c5e-4330-43bb-b981-415f0adbb7de でフィルタやgrepすると、リクエストを経由したサーバ横断で追跡することができるようになります。正常終了時のtraceIdと異常終了時のtraceIdでリクエストを抽出して、挙動の違いを比較するなども簡単にできるようになります。

4. まとめ

今回、Observabilityの基本概要と既存アプリケーションに少し手を加えることで、ログの追跡を容易にするための具体的な手段についてご紹介しました。後半にご紹介した分散トレーシングだけでは「システム状態の把握」をイメージするのが難しいですが、システム内部構造を知らなくてもtraceIdで検索することでエラーとなった一連の処理に焦点を絞ってトラブルシューティングが行えるという初動対応の容易性はイメージいただけたのではないかと思います。

最後に、Observabilityの考え方を取り入れ、製品やサービスを利用することでシステムの様々な状態を把握できるようになります。しかし、トラブルシューティングを行う上で重要情報となるLogsにおいて、適切なログレベルが設定されていなかったり、カテゴライズされていなかったり、必要な情報が出力されていなかったり、読み手の立場に立った情報ではなかった場合、原因調査に時間を要する点は今までと変わりません。Logsは開発者主導で出力するケースが多いかと思いますので、出力された情報を利用する人のことを意識して出力してもらえたらと思います。