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

[Instana Observability Advent Calendar 2023](https://qiita.com/advent-calendar/2023/instana)の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]              |

https://www.ibm.com/docs/en/instana-observability/current?topic=machine-instrumented-frameworks-libraries#logging-frameworks

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

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

**公式ドキュメント**

https://www.ibm.com/docs/en/instana-observability/current?topic=references-configuration-based-java-trace-sdk

**@iwashinat さんの記事**

https://community.ibm.com/community/user/blogs/tomonori-iwashina/2023/04/06/collecting-custom-log-library-message

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

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

構成ベースのJavaトレースSDKは、既存のコードを変更することなく、Instanaエージェントの設定ファイルを通じてカスタム・トレースを実現するものです。
（一部制約事項があります。詳細は[ドキュメント](https://www.ibm.com/docs/en/instana-observability/current?topic=references-configuration-based-java-trace-sdk#limitations)を参照してください）

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

## 検証用プログラムの作成

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

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

```java: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()`メソッドにてログの出力を行います。
エージェントが正しくログ収集できるようにするため、実行前後に待機時間を設けています。詳細は後述します。

```java
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`です。

:::note info
Instanaエージェントの設定ファイルは、configuration-\<suffix\>.yaml という名前で作成することで設定ファイルの分割が可能です。 （\<suffix\> 部分は英数字）
同様の設定を複数のサーバーに対して行う場合は、設定ごとに分割しておくと管理が容易となります。
（[ドキュメント](https://www.ibm.com/docs/en/instana-observability/current?topic=cha-configuring-host-agents-by-using-agent-configuration-file#creating-multiple-configuration-files)）
:::

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

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

```yaml: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`タグの値として収集する設定となっています。

```java
public void info(String msgID, String message)
```

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

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

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

## 動作確認

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

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3634361/8c0ab0d2-5d95-6bfa-0db9-cce8fa0c0495.png)

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

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

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

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3634361/19130931-ccd1-cb10-4cd3-aef61c436e68.png)


## 考慮点

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

### コードの変更に影響する

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

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

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

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

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

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

```java:ログ・レベルを分けることができないメソッドの例
public void log(String loglevel, String msgID, String message)
```

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

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

今回作成したロガーの場合、
```java
public void info(String msgID, String message)
```
`log.message`の値として設定できるのは`msgID`か`message`のどちらかとなります。
`msgID + ' ' + message` のように組み合わせることはできません。

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

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

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

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

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

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

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

- quartzなどのジョブ・スケジューラーやLibertyのバッチ機能などを使い、Javaプロセスが常にエージェントに監視されている状態としておく
    - [ドキュメント](https://www.ibm.com/docs/en/instana-observability/current?topic=references-tutorial-instrumenting-custom-scheduler-instana-tracing-sdk#enabling-tracing-for-the-custom-scheduler)では、quartz以外のカスタム・スケジューラーを使った例が紹介されています
- 今回サンプルで作成したプログラムのように、実行前後に待機時間を設けておく

必要がありそうです。

### 大量のログ出力に注意

この方法で設定されたログはSpanとしてSaaSへ送信されますが、大量のSpanを処理することによるパフォーマンスの悪化を防ぐため、レート制限が行われています。

レート制限はエージェントとSaaSの双方で行われており、実際に出力されているログ情報がSaaS側で確認できない場合があります。

#### エージェント
agent.logに `Suppressed spans due to high number of short or Discarded span due to queue overflow` と出力されている場合、レート制限が行われます。

レート制限が行われると、呼び出し時間の短い一部のSpanがエージェントによりドロップされてしまいます。これはSpan Rate Limittingと呼ばれています。

https://www.ibm.com/docs/en/instana-observability/current?topic=machine-system-requirements#span-rate-limiting

ロガーのメソッド呼び出しは一瞬で完了してしまうため、大量にログ出力が行われるとこのレート制限にすぐに達してしまいます。

設定により制限の上限値を引き上げることが可能です。
```
com.instana.plugin.javatrace:
  instrumentation:
    span-suppression-start: 1000 #デフォルト値は200, 最大4999
```

設定によりシステム負荷が大きく上昇する可能性があります。採用する場合には十分なテストを実施してください。

#### SaaS

agent.logに`Suppressed spans...`の出力がないのにログ情報がSaaS側で確認できない場合、SaaS側でドロップされている可能性があります。

SaaSの負荷状況はユーザーからは確認できないため、サポートへ問い合わせてSpan情報がドロップされていないか確認してもらう必要があります。

必要に応じてリソースを増強してもらうことで、より多くのSpanを処理できるようになります。

# まとめ

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

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

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