FLINTERS Engineer's Blog

FLINTERSのエンジニアによる技術ブログ

Scala + logstash-logback-encoder でJSONログを出力しよう!

こんにちは、門脇(@blac_k_ey)です。

Tetris99に進捗を奪われるのが趣味です。

最近、アプリケーションログ周りを整えるお仕事をしておりまして、
その中で logstash-logback-encoder というライブラリを触りました。

使い心地がとても良かったので、今回はScalaアプリケーションでこれを利用する方法をご紹介したいと思います。

logstash-logback-encoderとは

github.com

LogbackJSONログを出力するためのライブラリです。

元々はLogstash向けに開発されたものですが、現在は汎用的に使えるものになったそうです。

JSONでログを出力することの嬉しさ

ログの検索、分析が容易になります。
平文のログは正規表現などによるパースが必要になり機械的に扱うのが困難です。

例えば、AWSのCloudWatch LogsではJSONフォーマットに対応しており、JSONのフィールドを用いたフィルタが可能です。

f:id:Nomad_Blacky:20190306201310p:plain

引用: https://aws.amazon.com/jp/blogs/aws/new-cloudwatch-events-track-and-respond-to-changes-to-your-aws-resources/

また、最近CloudWatch Logs Insightsが登場しました。こちらもJSONフォーマットのログに対応しています。
専用のクエリを記述することで、ログの集計や簡単な可視化が可能です。

f:id:Nomad_Blacky:20190306201314p:plain

引用: https://aws.amazon.com/jp/blogs/aws/new-amazon-cloudwatch-logs-insights-fast-interactive-log-analytics/

前置き

今回紹介するソースコードsepteni-original/logstash-logback-encoder-in-scala に公開しております。

logstash-logback-encoderを使うための設定

Scalaアプリケーションで logstash-logback-encoder を使う準備をしましょう。

ライブラリ依存を追加する

build.sbt にライブラリ依存を追加します。
バージョンは執筆時点の最新です。

libraryDependencies ++= Seq(
  "ch.qos.logback" % "logback-classic" % "1.2.3",
  "net.logstash.logback" % "logstash-logback-encoder" % "5.3",
  "com.fasterxml.jackson.module" %% "jackson-module-scala" % "2.9.8"
)

logstash-logback-encoder はlogbackに直接依存していないので、今回は logback-classic を追加します。

jackson-module-scala に関しては後述します。

Logbackを設定する

logback.xml を編集します。

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

        <!-- JSONログを出力するエンコーダ -->
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">

            <!-- Pretty Print -->
            <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>
        </encoder>
    </appender>

    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

encoderLogstashEncoder を追加します。

今回は読みやすい出力をするためにPretty Printする設定を jsonGeneratorDecorator で設定しています。
ログのデータ量を減らすためにも、本番環境ではこの設定を外すのがよいでしょう。

以上の設定でJSONログを出力する準備が整いました!

logstash-logback-encoder を使ってログを出力する

では、実際にScalaからログを出力してみましょう!

Hello, Logging with JSON!

以下のScalaコードを用意します。

Example.scala

import org.slf4j.LoggerFactory

object Example extends App {

  val logger = LoggerFactory.getLogger(getClass)

  logger.info("Hello, Logging with JSON!")
}

実行してみます。

{
  "@timestamp" : "2019-02-18T14:49:45.947+09:00",
  "@version" : "1",
  "message" : "Hello, Logging with JSON!",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000
}

JSONログが出力できました!
(実際の出力に色は付きません)

ログメッセージが message フィールドに出力されているのがわかります。
また、 @timestamp level などのフィールドもデフォルトで出力されます。

JSONに静的なフィールドを追加する

出力されるログにアプリケーション名や環境名を入れたくなったとします。
このような静的なフィールドを追加したい場合はlogbackencoder に対して設定を追加します。

logback.xml

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

        <!-- JSONログを出力するエンコーダ -->
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">

            <!-- Pretty Print -->
            <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>

            <!-- グローバルなカスタムフィールドを追加 -->
            <customFields>
                {
                  "app_name": "logstash-logback-encoder-in-scala",
                  "env": "staging"
                }
            </customFields>
        </encoder>
    </appender>

    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

customFieldsJSONを記述しました。
この状態でログを出力してみましょう。

{
  "@timestamp" : "2019-02-22T11:26:38.392+09:00",
  "@version" : "1",
  "message" : "Hello, Logging with JSON!",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

app_nameenv が追加されました!

フィールドを動的に追加する

HTTPリクエストの結果など、その時々で内容が変わるフィールドはどのようにすれば良いでしょうか?
もちろん、logstash-logback-encoderはそのようなケースに対応しています。

次はScalaから動的にJSONのフィールドを追加する方法を見ていきましょう。

StructuredArguments

ログメッセージに対する引数に StructuredArgument を使うと、引数の内容をログメッセージに出力するとともに、JSONのフィールドに追加することが可能です。

Example.scala に以下を追加します。

// StructuredArgument で動的にフィールドを追加
import net.logstash.logback.argument.StructuredArguments._
logger.info("StructuredArguments.value {}", value("KEY", "VALUE"))
logger.info("StructuredArguments.keyValue {}", keyValue("KEY", "VALUE"))
logger.info("StructuredArguments.entries {}", entries(Map("k1" -> "v1", "k2" -> "v2").asJava))
logger.info("StructuredArguments.array {}", array("array", "a", "b", "c"))
logger.info("StructuredArguments.raw {}", raw("raw", """{"KEY":"VALUE"}"""))

単一の値を追加する value, keyValue
複数の値を追加する entiries, array
生のJSONを追加する raw などがあります。

logstash-logback-encoderは内部実装に Jackson を使っているので、ログに追加する値はJacksonでエンコードできる型である必要があります。
( Map(...).asJava しているのはそのためです。これを回避する方法は後述します。)

ログを出力してみます。

{
  "@timestamp" : "2019-03-04T20:33:44.355+09:00",
  "@version" : "1",
  "message" : "StructuredArguments.value VALUE",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "KEY" : "VALUE",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T20:33:44.357+09:00",
  "@version" : "1",
  "message" : "StructuredArguments.keyValue KEY=VALUE",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "KEY" : "VALUE",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T20:33:44.369+09:00",
  "@version" : "1",
  "message" : "StructuredArguments.entries {k1=v1, k2=v2}",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "k1" : "v1",
  "k2" : "v2",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T20:33:44.371+09:00",
  "@version" : "1",
  "message" : "StructuredArguments.array array=[a, b, c]",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "array" : [ "a", "b", "c" ],
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T20:33:44.379+09:00",
  "@version" : "1",
  "message" : "StructuredArguments.raw raw={\"KEY\":\"VALUE\"}",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "raw" : {"KEY":"VALUE"},
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

ログメッセージとJSONログのフィールドに値が追加されました!

Markers

Markerを使ってフィールドを追加することも可能です。

// Marker で動的にフィールドを追加
import net.logstash.logback.marker.Markers._
logger.info(append("KEY", "VALUE"), "Markers.append")
logger.info(appendEntries(Map("k1" -> "v1", "k2" -> "v2").asJava), "Markers.appendEntries")
logger.info(appendArray("array", "a", "b", "c"), "Markers.appendArray")
logger.info(appendRaw("raw", """{"KEY":"VALUE"}"""), "Markers.appendRaw")

StructuredArgumentsと同様に追加する値によって複数の方法をサポートしています。

ログを出力してみましょう。

{
  "@timestamp" : "2019-03-04T21:44:23.692+09:00",
  "@version" : "1",
  "message" : "Markers.append",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "KEY" : "VALUE",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T21:44:23.692+09:00",
  "@version" : "1",
  "message" : "Markers.appendEntries",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "k1" : "v1",
  "k2" : "v2",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T21:44:23.692+09:00",
  "@version" : "1",
  "message" : "Markers.appendArray",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "array" : [ "a", "b", "c" ],
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}
{
  "@timestamp" : "2019-03-04T21:44:23.692+09:00",
  "@version" : "1",
  "message" : "Markers.appendRaw",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "raw" : {"KEY":"VALUE"},
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

StructuredArguments と同様にログが出力されました!

また、 StructuredArguments と異なり、複数のMarkerを組み合わせることが可能です。

val marker: LogstashMarker =
  append("KEY_A", "VALUE_A").and(append("KEY_B", "VALUE_B"))
logger.info(marker, "multiple markers")
{
  "@timestamp" : "2019-03-04T21:44:23.692+09:00",
  "@version" : "1",
  "message" : "multiple markers",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "KEY_A" : "VALUE_A",
  "KEY_B" : "VALUE_B",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

ふたつのMarkerが出力に現れています。

「ある条件のときにフィールドが追加される」といった場合に使えそうです。

MDC

MDCを使ってフィールドを追加することも可能です。

// MDC で動的にフィールドを追加
import org.slf4j.MDC
MDC.put("KEY", "VALUE")
logger.info("logging with MDC")
MDC.remove("KEY")
{
  "@timestamp" : "2019-03-06T10:18:26.113+09:00",
  "@version" : "1",
  "message" : "logging with MDC",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "KEY" : "VALUE",
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

StructedArguments や Markers と異なりStringの値しか取れない点に注意してください。

Scalaオブジェクトをフィールドに追加する

先程までScalaのMapなどの引数はJavaのクラスに変換していました。
Scalaを使っている我々からするとその変換処理は億劫です。

Mapの中にMapがあるようなパターンを考えます。

logger.info("map in map", value(
  "scala_map",
  Map(
    "map" -> Map(
      "list" -> List(1, 2, 3).asJava
    ).asJava
  ).asJava
))

見ていてつらいですね…
また、case classも自動的に展開してくれないので、自分で変換する必要があります…

case class User(id: Long, name: String, interests: List[String])
val user = User(100, "userA", List("Scala", "Logging"))

logger.info("case class", value(
  "case_class_user" -> Map(
    "id" -> user.id,
    "name" -> user.name,
    "interests" -> user.interests.asJava
  ).asJava
))

いやだ~

そこで登場するのが、 jackson-module-scala です。

"com.fasterxml.jackson.module" %% "jackson-module-scala" % "2.9.8"

jackson-module-scalaScala向けのJacksonモジュールです。
Scalaのコレクションやcase classをJSONマッピング可能になります。

logstash-logback-encoderはクラスパスに存在するJacksonのモジュールを自動的に取得し、マッピングに登録してくれます。
なので、依存関係を追加するだけでコードを変更する必要はありません!

(この動作はバージョン 5.3 でサポートされた動作です。それ以前のバージョンは手動で追加する必要があります。)

実際にScalaオブジェクトがJSONマッピングされるのか見てみましょう。

// Scala由来のオブジェクトをフィールドに追加
case class User(id: Long, name: String, interests: List[String])
case class Group(id: Long, name: String, users: Set[User])

val group = Group(9000, "The Scala Group", Set(
  User(100, "userA", List("Scala", "Logging")),
  User(200, "userB", List("Java", "Kotlin"))
))

val scalaMap = Map(
  "KEY" -> "VALUE",
  "map_in_map" -> Map(
    "INNER_KEY" -> "INNER_VALUE"
  ),
  "group" -> group
)

logger.info("logging with Scala: {}", value("scala_map", scalaMap))
{
  "@timestamp" : "2019-03-06T10:38:03.688+09:00",
  "@version" : "1",
  "message" : "logging with Scala: Map(KEY -> VALUE, map_in_map -> Map(INNER_KEY -> INNER_VALUE), group -> Group(9000,The Scala Group,Set(User(100,userA,List(Scala, Logging)), User(200,userB,List(Java, Kotlin)))))",
  "logger_name" : "Example$",
  "thread_name" : "main",
  "level" : "INFO",
  "level_value" : 20000,
  "scala_map" : {
    "KEY" : "VALUE",
    "map_in_map" : {
      "INNER_KEY" : "INNER_VALUE"
    },
    "group" : {
      "id" : 9000,
      "name" : "The Scala Group",
      "users" : [ {
        "id" : 100,
        "name" : "userA",
        "interests" : [ "Scala", "Logging" ]
      }, {
        "id" : 200,
        "name" : "userB",
        "interests" : [ "Java", "Kotlin" ]
      } ]
    }
  },
  "app_name" : "logstash-logback-encoder-in-scala",
  "env" : "staging"
}

変換処理が要らなくなってすっきり!
ネストしていてもばっちり変換してくれていますね!

まとめ

ScalaアプリケーションでJSONログを出力する方法をご紹介しました。

今回は例外時のスタックトレースなど、説明を端折ったところも多いです。
紹介した機能以外にも様々な機能があるので、興味がある方はlogstash-logback-encoderのREADMEを読んでみてください。

JSONログを出力するようになってから、本番環境のデバッグの負担が軽くなったのを感じています!
ぜひ試してみてください!

良いロギング生活を!