Javaの構造化ロギングをもっとうまく使うためのError ProneのPluginを作った

errorprone-logstash-logback-encoder v0.0.1をリリースしました。 Error Proneのプラグイン機構を使って、logstash-logback-encoder向けのLintしてくれるPluginを作りました。 maven centralから実際にダウンロードして利用することが可能です。 github.com

このライブラリを作った背景を踏まえて、以下の流れで説明していきます。

はじめに
logstash-logback-encoderとは
どういう場面でLinterで自動的にエラーにしてほしかったか
どういうカスタムチェックを作ったか
終わりに

1. はじめに

最近、Javaで構造化ロギングをするなら、logstash-logback-encoderを使っています。これは、slf4jの実装である、logbackを拡張するためのライブラリです。構造化ロギングする時にこれを使っていますが、このライブラリを使っていて、いくつか困ったケースがありました。これを解決するために作ったのが、errorprone-logstash-logback-encoderです。

errorproneは、Javaのコンパイラ内部のAPIに依存したLinterのツールですが今回作ったerrorprone-logstash-logback-encoderはerrorproneのpluginのAPIを使って作成した自作のLinterのルールです。

この記事では、logstash-logback-encoderに軽く触れ、どういった問題を解決したかったのかを書いていきます。

2. logstash-logback-encoderとは

まず初めに、logstash-logback-encoderとは、どういうライブラリなのかというと Elastic社の製品である、logstash向けにログフォーマットを調整して出力するためだけのライブラリではありません。

このライブラリには、以下の機能があります。

UDP/TCP/Async Appenderなどのlogbackの標準に含まれていない機能を補助するための機能
構造化ロギング(JSONログ)をよりうまく扱うため機能

今回は、構造化ロギングの機能でLintして欲しい場面があったので、errorprone-logstash-logback-encoderを作りました。

どのような場面でLintして欲しいかというとは、それは以下のような場面です。

構造化ログのための引数をログで placeholder展開をされたくない
構造化ログを使うならログでplaceholderを使わないようにしたい
構造化ログを扱うためのMarkerへのmutationの抑制したい

上記内容をサンプルコードを交えながら、説明していきます。

3. なぜ/どういう場面でLinterで自動的にエラーにしてほしかったか

ここでは、サンプルコードを交え、どういう場面でLinterに自動的にエラーにしてほしかったかを説明します。

3.1. 構造化ログのための引数をログで placeholder展開をされたくない

まず、logstash-logback-encoderでは、構造化ログを出力する際、以下のようなコードを記述します。

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
import net.logstash.logback.argument.StructuredArguments;
public class Test {
 private static final Logger LOG = org.slf4j.LoggerFactory.getLogger(Test.class);
 // marker経由でも構造化ログにキーを増やせる
 private static final LogstashMarker MARKER = Markers.append("log_type", "test");

 public void test() {
   // 構造化ログにStructuredArgumentsのstaticメソッドでログにキーを増やせる
   LOG.info("some message", StructuredArguments.keyValue("userId", "foo"));

   // デフォルト設定では以下のようなログが出る。(ログレベルなどデフォルトで出力されるキーのいくつかは省略してあります)
   // => {"logger": "some.package.Test", "message": "some message", "userId": "foo", "log_type": "test"}
 }
}

ただ、既存のツールでは、placeholderの数が合わずにLinterでエラーになることがありました。そのため、以下のようなコードを書いてしまうと、ログメッセージに情報が重複しています。 "message"にuserId=fooという文字列と"userId"に"foo"という情報が乗ってしまい、ログのデータ量も大きくなってしまいます。

LOG.info("some message. {}", StructuredArguments.keyValue("userId", "foo"));

// 以下のようなログが出る。
// => {..., "message": "some message. userId=foo", "userId": "foo", ...}

これを避けるために、placeholderに構造化ログのための引数を無視できるようなLinterが欲しかったのです。

3.2. 構造化ログを使うならログでplaceholderを使わないようにしたい

「構造化ログを使うならログでplaceholderを使わないようにしたい」というのは placeholderでコンテキスト情報を付加するのではなく、構造化ログの追加のキーとしてログにコンテキスト情報を付与する形に統一したいと考えていました。

これは、一つ前に話した内容をより厳格にしたものですが、これには別の課題もあり、解決したい意識がありました。それは、Sentryなどのエラーレポーティングツールでの扱いです。

例えば、APIのリクエストの情報を載せてログ出力した際に、以下のようなログ出力になることがあります。 2つのメッセージは同じログ出力箇所から出たログではありますが、エラーレポーティングツールでは、別のエラーとして取り扱われます。そのため、placeholderを完全に排除することで、この問題を解決したいと考えていました。

LOG.error("some message. userId:{}", "foo"); // 引数は実際には、変数から取ってくるが説明のためにリテラルで書いている。
LOG.error("some message. userId:{}", "bar");

3.3. 構造化ログを扱うためのMarkerが、mutableであることの検査

logstash-logback-encoderには、MarkersというAPIがあり、そこからslf4jのMarkerから構造化ログに情報を付与することが出来ます。しかし、このMarkerには罠があり、このMarkerはmutableなのです。 immutableに扱いたいため、Lintしてほしい場面がありました。

private static final LogstashMarker MARKER = Markers.append("log_type", "test");

4. どういうカスタムチェックを作ったか

これらを踏まえて、errorprone-logstash-logback-encoderでは、以下の4つのルールを作りました。（一つはslf4j 2.0のFluent APIに対する検査です。）

Slf4jPlaceholderShouldNotContainStructuredArgument
Slf4jDoNotUsePlaceholder
Slf4jConstantMarkerMutation
Slf4jFluentApiFormatShouldBeConst

4.1. Slf4jPlaceholderShouldNotContainStructuredArgument

一番最初の課題であった、「構造化ログのための引数をログで placeholder展開をされたくない」を解決するためのLintルールです。 placeholderに対応する引数がStructuredArgumentであった場合にエラーになります。また、このルールでは、errorprone-slf4jのSlf4jPlaceholderMismatchを置き換える目的で作ったため、 placeholderにStructuredArgumentが指定されているか、placeholderの数と引数の数が合わない場合にエラーになるようにしています。

import org.slf4j.Logger;
import net.logstash.logback.argument.StructuredArguments;
public class Test {
  private static final Logger logger = org.slf4j.LoggerFactory.getLogger(Test.class);

  public void test() {
    // invalid: placeholder should not contain StructuredArgument
    logger.info("{}", StructuredArguments.keyValue("key", "value"));

    // invalid: count of placeholders does not match with the count of arguments
    logger.info("{}");

    // valid
    logger.info("{}", "safe", StructuredArguments.keyValue("key", "value"));
  }
}

4.2. Slf4jDoNotUsePlaceholder

これは2番目の課題であった「構造化ログを使うならログでplaceholderを使わないようにしたい」という課題に対するルールです。ログのメッセージにplaceholderを含まないかどうかを確認します。

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
import net.logstash.logback.argument.StructuredArguments;
public class Test {
 private static final Logger logger = org.slf4j.LoggerFactory.getLogger(Test.class);
 private static final Marker MARKER = MarkerFactory.getMarker("marker");

 public void test() {
   // invalid: format should not contain placeholder. use structured argument instead.
   logger.info("some message. userId:{}", "foo");

   // valid
   logger.info("some message", StructuredArguments.keyValue("userId", "foo"));
 }
}

4.3. Slf4jConstantMarkerMutation

これは3番目の課題として挙げた、「構造化ログを扱うためのMarkerへのmutationの抑制したい」という課題に対するルールです。 finalなstatic変数もしくはfinalなinstance変数に保存されたMarkerに対するmutationを発行するメソッドの呼び出しを抑制してくれます。

import net.logstash.logback.marker.LogstashMarker;
import net.logstash.logback.marker.Markers;
public class Test {
 private static final LogstashMarker MARKER = Markers.append("key", "value");

 public void test() {
   // invalid: Constant marker should not mutate, or use net.logstash.logback.marker.Markers.aggregate instead
   MARKER.add(Markers.append("key", "value"));
   
   // valid
   Markers.aggregate(MARKER, Markers.append("key", "value"));
 }
}

4. Slf4jFluentApiFormatShouldBeConst

これは、slf4j 2.0から導入されたFluent APIに対応するために入れたルールです。ログメッセージはリテラルで書くべきだと思っていて、errorprone-slf4jのカバー範囲を補うルールになっています。ぶっちゃけこれはここに入れずに、errorprone-slf4jにPR送るべきだったかなとちょっと思っています。

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
import net.logstash.logback.argument.StructuredArguments;
public class Test {
 private static final Logger logger = org.slf4j.LoggerFactory.getLogger(Test.class);
 private static final Marker MARKER = MarkerFactory.getMarker("marker");

 public void test() {
   // invalid: format should be constant
   logger.atInfo().setMessage(() -> "test").log();

   // invalid: format should be constant
   logger.atInfo().log(() -> "test");

   var message = "test";
   // invalid: format should be constant
   logger.atInfo().log(message);

   // invalid: format should be constant
   logger.atInfo().setMessage(message).log();

   // valid
   logger.atInfo().setMessage("safe").log();

   // valid
   logger.atInfo().log("safe");
 }
}

5. 利用方法

maven centralからダウンロードして利用する事ができます。 central.sonatype.com

実際には、以下のように依存の追加が必要です。gradleであれば以下のような形で利用が可能です。 Error Proneの依存も一緒に追加してください。

dependencies {
  annotationProcessor 'com.google.errorprone:error_prone_core:2.27.1'
  annotationProcessor 'io.github.wreulicke.errorprone.logstash:errorprone-logback-logstash-encoder:0.0.1'

  # or you can write below when you use net.ltgt.errorprone plugin
  errorprone 'com.google.errorprone:error_prone_core:2.27.1'
  errorprone 'io.github.wreulicke.errorprone.logstash:errorprone-logback-logstash-encoder:0.0.1'
}

5. 終わりに

今回の記事では、実際に作ったerrorprone-logstash-logback-encoderというライブラリの紹介をしました。実際に、maven centralからダウンロードして利用することが可能です。ぜひ使ってみてください。より良い構造化ログを出力出来るようになると良いかなと思っています。

ソースコードはこちらに置いてあります。 github.com

6. おまけ

maven centralにリリースするの思ったより簡単でした。 io.github.{github-username}であれば、すぐリリースすることが可能でした。以下の記事にめちゃくちゃ感謝しています。 https://zenn.dev/orangain/articles/publish-to-maven-central-using-gradle