これは、なにをしたくて書いたもの?
ログ出力する時に、JSONフォーマットにするようなライブラリがないかな?ということで、少し調べてみました。
Fluentdなどを使ってログを収集する場合、ログのフォーマットはなかなか悩ましいなぁ、と…。
ロギングライブラリをLogbackにしたとすると、以下の2つが選択肢にありそうです。
GitHub - logstash/logstash-logback-encoder: Logback encoder which creates JSON for use with Logstash
Logback Contribの方は、だいぶ古そう&ドキュメントもほぼないので、今回はLogstashのLogback JSON encoderを試して
みたいと思います。
Logback JSON encoder
Logstash(Organization自体がLogstashの頃の)が提供する、Logback向けのライブラリです。
GitHub - logstash/logstash-logback-encoder: Logback encoder which creates JSON for use with Logstash
名前こそencoderですが、Logstashにログを送信するAppenderも備えます。logback-accessにも対応しているようです。
余談ですが、Log4j(1系)向けのLayoutもあるみたいです。
今回は、LogstashのLogback JSON encoderを使って、出力するログのフォーマットをJSONにしたいと思います。
環境
今回の環境は、こちら。
$ java -version openjdk version "1.8.0_191" OpenJDK Runtime Environment (build 1.8.0_191-8u191-b12-2ubuntu0.18.04.1-b12) OpenJDK 64-Bit Server VM (build 25.191-b12, mixed mode) $ mvn -version Apache Maven 3.6.0 (97c98ec64a1fdfee7767ce5ffb20918da4f719f3; 2018-10-25T03:41:47+09:00) Maven home: $HOME/.sdkman/candidates/maven/current Java version: 1.8.0_191, vendor: Oracle Corporation, runtime: /usr/lib/jvm/java-8-openjdk-amd64/jre Default locale: ja_JP, platform encoding: UTF-8 OS name: "linux", version: "4.15.0-46-generic", arch: "amd64", family: "unix"
準備
Maven依存関係は、こちら。
<dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>1.7.26</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.2.3</version> </dependency> <dependency> <groupId>net.logstash.logback</groupId> <artifactId>logstash-logback-encoder</artifactId> <version>5.3</version> </dependency>
Logback自体は、依存関係に個別に加える必要があります。また、LogbackはSLF4J経由で使うことにします。
Logbackの設定ファイルは、ドキュメントに書かれている単純な例をスタートにしたいと思います。
src/main/resources/logback.xml
<?xml version="1.0" encoding="UTF-8"?> <configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder> </appender> <root level="info"> <appender-ref ref="STDOUT" /> </root> </configuration>
では、ここから始めていきましょう。
プログラムの雛形
まずは、ライブラリを使うにあたっての、雛形となるコードを用意しましょう。
src/main/java/org/littlewings/logging/LogstashEncoderExample.java
package org.littlewings.logging; import net.logstash.logback.argument.StructuredArguments; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.slf4j.MDC; public class LogstashEncoderExample { public static void main(String... args) { Logger logger = LoggerFactory.getLogger(LogstashEncoderExample.class); // ここに、SLF4J+Logbackを使ったコードを書く! } }
とりあえず、ログ出力コードを書いてみます。
logger.info("Hello {}", "Logging!"); logger.error("Oops!!"); logger.error("Oops!!", new Exception("Error!"));
実行した時のログ。
21:59:05.322 [main] INFO o.l.logging.LogstashEncoderExample - Hello Logging! 21:59:05.326 [main] ERROR o.l.logging.LogstashEncoderExample - Oops!! 21:59:05.327 [main] ERROR o.l.logging.LogstashEncoderExample - Oops!! java.lang.Exception: Error! at org.littlewings.logging.LogstashEncoderExample.main(LogstashEncoderExample.java:14)
ここから、Logbackの設定ファイルやコードを変更しつつ、動きの変化を見ていきましょう。
encoderを変更する
最初に、encoderを変更します。今までこうだったのを
<encoder> <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder>
こうします。
<encoder class="net.logstash.logback.encoder.LogstashEncoder" />
パターンの指定はいりません。
これだけで、ログがJSONフォーマットになります。@timestamp、levelなどが勝手に入ります。
{"@timestamp":"2019-03-24T22:00:53.938+09:00","@version":"1","message":"Hello Logging!","logger_name":"org.littlewings.logging.LogstashEncoderExample","thread_name":"main","level":"INFO","level_value":20000} {"@timestamp":"2019-03-24T22:00:53.947+09:00","@version":"1","message":"Oops!!","logger_name":"org.littlewings.logging.LogstashEncoderExample","thread_name":"main","level":"ERROR","level_value":40000} {"@timestamp":"2019-03-24T22:00:53.949+09:00","@version":"1","message":"Oops!!","logger_name":"org.littlewings.logging.LogstashEncoderExample","thread_name":"main","level":"ERROR","level_value":40000,"stack_trace":"java.lang.Exception: Error!\n\tat org.littlewings.logging.LogstashEncoderExample.main(LogstashEncoderExample.java:14)\n"}
これではちょっと見づらい…という場合は、PrettyPrintingJsonGeneratorDecoratorを使います。
Customizing JSON Factory and Generator
こんな感じに設定します。
<encoder class="net.logstash.logback.encoder.LogstashEncoder"> <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/> </encoder>
ログ収集のことを考えると、1行で出力された方が本来は嬉しいと思いますので、これを利用するケースは手元で動かす時などに
限られるでしょう。
これで、先ほどのログはこうなります。
{ "@timestamp" : "2019-03-24T22:03:38.939+09:00", "@version" : "1", "message" : "Hello Logging!", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000 } { "@timestamp" : "2019-03-24T22:03:38.948+09:00", "@version" : "1", "message" : "Oops!!", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "ERROR", "level_value" : 40000 } { "@timestamp" : "2019-03-24T22:03:38.950+09:00", "@version" : "1", "message" : "Oops!!", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "ERROR", "level_value" : 40000, "stack_trace" : "java.lang.Exception: Error!\n\tat org.littlewings.logging.LogstashEncoderExample.main(LogstashEncoderExample.java:14)\n" }
見やすくなりましたね。今回は、Pretty Printを有効にしたままいきましょう。
MDCを使う
ここで、MDCを使ってみましょう。
MDC.put("mdc_key1", "mdc_value1"); logger.info("Hello MDC");
すると、JSONの項目自体が追加されます。
{ "@timestamp" : "2019-03-24T22:03:38.951+09:00", "@version" : "1", "message" : "Hello MDC", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "mdc_key1" : "mdc_value1" }
出力するMDCフィールドを絞ったり、除外したりすることもできます。
例えば、このように「excludeMdcKeyName」を使って除外するキーを指定します。
<encoder class="net.logstash.logback.encoder.LogstashEncoder"> <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/> <excludeMdcKeyName>mdc_exclude_key</excludeMdcKeyName> </encoder>
確認コード。最初のMDCの例で追加したフィールドは、そのままです。
MDC.put("mdc_key2", "mdc_value2"); MDC.put("mdc_exclude_key", "mdc_exclude_value"); logger.info("Hello MDC");
結果。
{ "@timestamp" : "2019-03-24T22:11:05.009+09:00", "@version" : "1", "message" : "Hello MDC", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "mdc_key2" : "mdc_value2", "mdc_key1" : "mdc_value1" }
「mdc_exclude_key」は含まれませんが、それ以外にMDCで追加したフィールドは含まれていますね。
反対に、「includeMdcKeyName」を使うと、指定したフィールドのみを出力するように絞り込むことができるようです。
また、「includeMdcKeyName」と「excludeMdcKeyName」は排他の関係にあります。
設定したMDCは、クリアしておきましょう。
MDC.clear();
カスタムフィールドを使う
MDC以外にも、カスタムフィールドを追加することができます。
固定で追加する場合は、「customFields」を使います。中身はJSONで書きます。
<encoder class="net.logstash.logback.encoder.LogstashEncoder"> <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/> <customFields>{"app": "example", "tag": "v0.0.1-SNAPSHOT"}</customFields> </encoder>
これで、ログに指定したカスタムフィールドが常に追加されるようになります。
{ "@timestamp" : "2019-03-24T22:17:55.525+09:00", "@version" : "1", "message" : "Hello Logging!", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "app" : "example", "tag" : "v0.0.1-SNAPSHOT" }
動的にフィールドを追加する場合は、「StructuredArguments」か「Makers」を使います。
ここでは、「StructuredArguments」を使ってみます。
ドキュメントのサンプルを見てもよいのですが…まあ簡単に。valueおよびkeyValueメソッドを使います。
logger.info("with value / {}", StructuredArguments.value("skey", "svalue")); logger.info("with value", StructuredArguments.value("skey", "svalue")); logger.info("with key=value / {}", StructuredArguments.keyValue("skey", "svalue")); logger.info("with key value", StructuredArguments.keyValue("skey", "svalue"));
メソッドの違いと、ログメッセージのプレースホルダーに含めるかどうかで挙動が変わります。
まずはvalue。valueという割には、キーも指定する必要があります。
logger.info("with value / {}", StructuredArguments.value("skey", "svalue")); logger.info("with value", StructuredArguments.value("skey", "svalue"));
出力されるログ。
{ "@timestamp" : "2019-03-24T22:25:22.452+09:00", "@version" : "1", "message" : "with value / svalue", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "skey" : "svalue" } { "@timestamp" : "2019-03-24T22:25:22.452+09:00", "@version" : "1", "message" : "with value", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "skey" : "svalue" }
両方とも、指定したキーと値がJSONとして追加されます。プレースホルダーを含めた方は、値のみがログメッセージに出力されます。
これに対してkeyValueの場合。
logger.info("with key=value / {}", StructuredArguments.keyValue("skey", "svalue")); logger.info("with key value", StructuredArguments.keyValue("skey", "svalue"));
追加したキーと値がJSONの項目に含まれるのは同じですが、プレースホルダーを含めた場合は「キー=値」の形式で追加されます。
{ "@timestamp" : "2019-03-24T22:25:22.453+09:00", "@version" : "1", "message" : "with key=value / skey=svalue", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "skey" : "svalue" } { "@timestamp" : "2019-03-24T22:25:22.453+09:00", "@version" : "1", "message" : "with key value", "logger_name" : "org.littlewings.logging.LogstashEncoderExample", "thread_name" : "main", "level" : "INFO", "level_value" : 20000, "skey" : "svalue" }
Loggerのメソッドが可変長引数なので、項目を複数追加したり、keyValueの場合はデリミタ(=)を変更することもできます。
また、これらのメソッドの引数にするものは、JSON内に含まれる関係上、JSONに変換できる項目であることが求められます。
その他
カスタマイズもいろいろできるようですが、こちらは必要に応じて見ていく感じですね。
Customizing Standard Field Names
Customizing Logger Name Length
JSONへマッピングしている箇所などは、このあたりなどを見ていくとよいでしょう。
こんなところで。