独自のJavaロガーを使ったログ・メッセージをInstanaで収集する

Instana Observability Advent Calendar 2023の17日目です。

はじめに

InstanaエージェントがJavaアプリケーションのログ情報を収集するには、エージェントがサポートしているロギング・ライブラリーを使用する必要があります。

2023/12/13時点では以下のロギング・ライブラリーをサポートしています。これらのライブラリーを使用していれば、特別な設定をすることなくログ情報を収集することができます。

Name	Versions
Java Util Logging	All supported JDKs
Log4j	[1.2]
Log4j 2	[2.4, 2.20]
Log4j over SLF4J	[1.5, 1.7]
Logback	[0.9, 1.0, 1.4]
SLF4J	[1.5, 1.7]
SLF4J over Log4j	[1.1, 1.7]

上記に記載のないライブラリーを使っていたり、独自のロガーを実装している場合でも、「構成ベースのJavaトレースSDK」を活用することで、ログ情報を収集することが可能となります。

今回は以下の文献を参考に、独自に作成したロガーの情報をInstanaバックエンドへ送信できるか検証してみました。

公式ドキュメント

@iwashinat さんの記事

構成ベースのJavaトレースSDKについて

InstanaではJava Trace SDK(github)を用いて、ユーザー独自のカスタム・トレース設定を行うことができます。
しかし、様々な理由からコードの変更が難しい場合もあります。

構成ベースのJavaトレースSDKは、既存のコードを変更することなく、Instanaエージェントの設定ファイルを通じてカスタム・トレースを実現するものです。
（一部制約事項があります。詳細はドキュメントを参照してください）

今回は、この機能を用いてログ情報のトレース設定を行います。

検証用プログラムの作成

簡易的なロガーを作成します。

ファイル出力はせず、標準出力へ出力するだけのものです。

CustomLogger.java

package com.mycompany.util;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class CustomLogger {
    private static final String LOGLEVEL_INFO = "INFO";
    private static final String LOGLEVEL_WARN = "WARN";
    private static final String LOGLEVEL_ERROR = "ERROR";
    private static final DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss");

    public CustomLogger(){}

    public void info(String msgID, String message){
        log(LOGLEVEL_INFO, msgID, message);
    }

    public void warn(String msgID, String message){
        log(LOGLEVEL_WARN, msgID, message);
    }

    public void error(String msgID, String message){
        log(LOGLEVEL_ERROR, msgID, message);
    }

    private void log(String loglevel, String msgID, String message) {
        String formattedDateTime = LocalDateTime.now().format(formatter);
        System.out.println(String.format("[%s][%s]%s %s", loglevel, msgID, formattedDateTime, message));
    }  
}

このクラスを使ったAppクラスを作成します。

短時間で実行されるバッチ・ジョブを想定したjob()メソッドにてログの出力を行います。
エージェントが正しくログ収集できるようにするため、実行前後に待機時間を設けています。詳細は後述します。

package com.mycompany.app;

import java.util.Random;
import com.mycompany.util.CustomLogger;

public class App 
{
    static CustomLogger logger = new CustomLogger();
    public static void main(String[] args) {
        try {
            logger.info("MSG0000", "Waiting for 30 seconds....");
            Thread.sleep(30000); //ジョブ実行前30秒待機
            job(); //ジョブ実行
            Thread.sleep(1000); //ジョブ実行後1秒待機            
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    private static void job() throws InterruptedException{
        Random random = new Random();
        
        logger.info("MSG0001", "Job start");

        Thread.sleep(random.nextInt(5000));
        logger.info("MSG0002", "Info test");

        Thread.sleep(random.nextInt(5000));
        logger.warn("MSG0003", "Warn test");

        Thread.sleep(random.nextInt(5000));
        logger.error("MSG0004", "Error test");
        
        Thread.sleep(random.nextInt(5000));
        logger.info("MSG0005", "Job end");
    }
}

実行すると、以下のように標準出力へメッセージが出力されます。

[INFO][MSG0000]2023-12-13 20:33:10 Waiting for 30 seconds....
[INFO][MSG0001]2023-12-13 20:33:40 Job start
[INFO][MSG0002]2023-12-13 20:33:43 Info test
[WARN][MSG0003]2023-12-13 20:33:43 Warn test
[ERROR][MSG0004]2023-12-13 20:33:47 Error test
[INFO][MSG0005]2023-12-13 20:33:47 Job end

Instanaエージェントの設定ファイル作成

{エージェントのインストール先}/etc/instana以下に、configuration-javatrace.yamlという名前で設定ファイルを作成します。

Linuxの場合、エージェントのデフォルトのインストール先は/opt/instana/agentです。

Instanaエージェントの設定ファイルは、configuration-<suffix>.yaml という名前で作成することで設定ファイルの分割が可能です。 （<suffix> 部分は英数字）
同様の設定を複数のサーバーに対して行う場合は、設定ごとに分割しておくと管理が容易となります。
（ドキュメント）

利用者によって設定値が異なる部分にコメントを入れています。

エージェントの再起動は不要ですが、起動中のJVMを監視する場合にはJVMを再起動してください。

configuration-javatrace.yaml

com.instana.plugin.javatrace:
  instrumentation:
    enabled: true # カスタム・トレースを有効化するため必ずtrueを指定
    opentracing: false # 上記と競合するため必ずfalseを指定(デフォルトでfalse)
    sdk:
      packages: # トレース対象としたいパッケージを指定
        - 'com.mycompany.util'
        - 'com.mycompany.app'
      targets:
        # ①ERRORログを収集するための設定
        - match:
            type: 'baseclass'
            name: 'com.mycompany.util.CustomLogger' # トレース対象としたいクラスを指定
            method: 'error' # トレース対象としたいメソッドを指定
          span:
            type: 'EXIT'
            name: 'CustomLog.error' # 任意の名前を指定
            tags:
              - kind: 'constant'
                name: 'log.level'
                value: 'error' # ログ・レベルを指定
              - kind: 'argument'
                name: 'log.message'
                index: 1 # メソッドの何番目の引数を渡すか（0始まりのため、この例では2番目）
        # ②WARNログを収集するための設定
        - match:
            type: 'baseclass'
            name: 'com.mycompany.util.CustomLogger' # トレース対象としたいクラスを指定
            method: 'warn' # トレース対象としたいメソッドを指定
          span:
            type: 'EXIT'
            name: 'CustomLog.warn' # 任意の名前を指定
            tags:
              - kind: 'constant'
                name: 'log.level'
                value: 'warn' # ログ・レベルを指定
              - kind: 'argument'
                name: 'log.message'
                index: 1 # メソッドの何番目の引数を渡すか（0始まりのため、この例では2番目）
        # ③INFOログを収集するための設定
        - match:
            type: 'baseclass'
            name: 'com.mycompany.util.CustomLogger' # トレース対象としたいクラスを指定
            method: 'info' # トレース対象としたいメソッドを指定
          span:
            type: 'EXIT'
            name: 'CustomLog.info' # 任意の名前を指定
            tags:
              - kind: 'constant'
                name: 'log.level'
                value: 'info' # ログ・レベルを指定
              - kind: 'argument'
                name: 'log.message'
                index: 1 # メソッドの何番目の引数を渡すか（0始まりのため、この例では2番目）
        # ④job()をトレースするための設定
        - match:
            type: 'baseclass'
            name: 'com.mycompany.app.App' # トレース対象としたいクラスを指定
            method: 'job' # トレース対象としたいメソッドを指定
          span:
            type: 'ENTRY'
            name: 'Job' # 任意の名前を指定
            tags:
              - kind: 'constant'
                name: 'endpoint'
                value: 'com.mycompany.app.App.job()' # 任意のエンドポイント名を指定
              - kind: 'constant'
                name: 'batch.job'
                value: 'Test Job' # 任意のジョブ名を指定

①②③では、com.ibm.util.CustomLoggerクラスのinfo / warn / errorメソッドをトレース収集対象として設定しています。

また、このメソッドの2番目の引数をlog.messageタグの値として収集する設定となっています。

public void info(String msgID, String message)

今回は各メソッドの2番目の引数であるmessageをログとして収集したいため、引数の順序としては(0始まりのため)1を指定しています。

④では、ジョブを実行しているcom.mycompany.app.Appクラスのjobメソッドをトレース収集対象として設定しています。

ログ・メッセージの収集のためには必須ではありませんが、Instanaの分析画面でこのメソッドの実行時間やログの出力タイミングを確認できるようになります。

動作確認

準備が整ったところで、プログラムを実行してみましょう。

実行後、アプリケーション・パースペクティブ > ログ・メッセージ にてログが表示されることが確認できます。

Log4Jなど標準でサポートされているロガーの場合、ログ・レベルがWARN以上のログのみが収集対象となっています。

しかし、上記のように構成ベースのJavaトレースSDKを用いることで、ログ・レベルINFOとしても収集できることが確認できました。

今回は未検証ですが、「Log4Jを使用しているがINFOのログも収集対象としたい」場合にも活用できそうです。

分析画面では、job()メソッドの実行時間やログの出力タイミングが視覚的に分かりやすく表示されました。

考慮点

今回の検証を通して、Instanaがサポートしていないロガーのログ情報をInstanaのログ・メッセージとして収集できることが確認できましたが、検証を通して感じた考慮点をいくつか紹介します。

コードの変更に影響する

構成ベースのJavaトレースSDKは、収集対象のクラスやメソッドを設定することでトレース対象を特定する仕組みとなっています。このため、これらの要素が変更されると動作しなくなります。

また、新しいクラスやメソッドが実装された場合にも逐一設定ファイルに追記していく必要があります。

頻繁に変更される可能性が低い場合でも、アプリケーション側のコード変更の影響があることを認識しておく必要があります。

ログ・レベルごとにメソッドが分かれている必要がある

今回の設定は、Instanaエージェントの設定ファイル上でログ・レベルごとに異なるメソッドを指定することで、Instanaが収集するログ・レベルを分ける仕組みとなっています。

そのため、ログを出力するメソッドは単一で引数でログ・レベルを指定するようなロガーの場合は、ログ・レベルを分けることができません。

ログ・レベルを分けることができないメソッドの例

public void log(String loglevel, String msgID, String message)

収集可能なメソッドの引数は1つだけ

執筆時点では、1つのタグに設定できる引数は1つだけとなっています。

今回作成したロガーの場合、

public void info(String msgID, String message)

log.messageの値として設定できるのはmsgIDかmessageのどちらかとなります。
msgID + ' ' + message のように組み合わせることはできません。

プログラム実行前後のトレースは収集されない

今回はWebアプリケーションではなく、シェル・スクリプトから定期的に呼び出されるJavaアプリケーションを想定して検証を行いました。

Instanaエージェントは30秒ごとにディスカバリーの処理が行われ、未知のJavaプロセスを発見すると監視対象に含める挙動となっています。そのため、エージェントが監視対象に含める前のデータは収集されません。

また、今回の検証では処理の終了直前に待機時間を設けない場合、job()メソッドのトレース情報は収集されませんでした。

1秒程度の待機時間を設けることで収集されることを確認しましたが、環境によって異なる可能性があります。

これは個人的な予想ですが、監視対象のプロセスが終了するとエージェントはすぐに監視を停止するため、直前のデータが送信されないものと思われます。

バッチ・ジョブの実行状況を正確にトレースしたい場合、

• quartzなどのジョブ・スケジューラーやLibertyのバッチ機能などを使い、Javaプロセスが常にエージェントに監視されている状態としておく
  • ドキュメントでは、quartz以外のカスタム・スケジューラーを使った例が紹介されています
• 今回サンプルで作成したプログラムのように、実行前後に待機時間を設けておく

必要がありそうです。

まとめ

構成ベースのJavaトレースSDKを用いて、カスタム・ロガーのメッセージ情報をInstanaで収集できることを確認しました。

ERROR, WARNだけでなくINFOのログも送信することができるため、プログラムの実行状況を分析する際に役立つかもしれません。

ログ以外のメソッドについても、既存のコードを変更することなくトレース設定できる非常に便利な機能なので、ぜひ一度試してみてください。