LogstashのLogback JSON encoderで、Logbackで出力するログを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>

Chapter 3: 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" />

パターンの指定はいりません。

Encoders / Layouts

これだけで、ログが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フィールドを絞ったり、除外したりすることもできます。

MDC fields

例えば、このように「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以外にも、カスタムフィールドを追加することができます。

Custom Fields

固定で追加する場合は、「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に変換できる項目であることが求められます。