こんにちは、門脇(@blac_k_ey)です。
Tetris99に進捗を奪われるのが趣味です。
…
最近、アプリケーションログ周りを整えるお仕事をしておりまして、
その中で logstash-logback-encoder というライブラリを触りました。
使い心地がとても良かったので、今回はScalaアプリケーションでこれを利用する方法をご紹介したいと思います。
- logstash-logback-encoderとは
- JSONでログを出力することの嬉しさ
- 前置き
- logstash-logback-encoderを使うための設定
- logstash-logback-encoder を使ってログを出力する
- まとめ
logstash-logback-encoderとは
LogbackでJSONログを出力するためのライブラリです。
元々はLogstash向けに開発されたものですが、現在は汎用的に使えるものになったそうです。
JSONでログを出力することの嬉しさ
ログの検索、分析が容易になります。
平文のログは正規表現などによるパースが必要になり機械的に扱うのが困難です。
例えば、AWSのCloudWatch LogsではJSONフォーマットに対応しており、JSONのフィールドを用いたフィルタが可能です。
また、最近CloudWatch Logs Insightsが登場しました。こちらもJSONフォーマットのログに対応しています。
専用のクエリを記述することで、ログの集計や簡単な可視化が可能です。
前置き
今回紹介するソースコードは 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>
encoder に LogstashEncoder を追加します。
今回は読みやすい出力をするために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に静的なフィールドを追加する
出力されるログにアプリケーション名や環境名を入れたくなったとします。
このような静的なフィールドを追加したい場合はlogbackの encoder に対して設定を追加します。
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>
customFields にJSONを記述しました。
この状態でログを出力してみましょう。
{ "@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_name と env が追加されました!
フィールドを動的に追加する
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-scalaはScala向けの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ログを出力するようになってから、本番環境のデバッグの負担が軽くなったのを感じています!
ぜひ試してみてください!
良いロギング生活を!
