構造化ログという概念がある。ログをこれまでのプレーンテキストではなく、なんか良い感じのシリアライズフォーマットを使って出力することで、各種の再利用性を高めるのが目的だ。一般には、ログの各メッセージをJSONに収め、JSON Lines形式にすることが多い。
Google CloudやAWSなどの各サービスがこの構造化ロギングの概念はに対応しており、ログ検索などで便利に使えるようになっている。JSONのフィールドでフィルタしたり、詳しいフィルタリングができる。 すくなくとも仕事ではかなり使われていて、コンテナネイティブなアプリケーションだとほぼ必須事項みたいになっている。
今回仕事でいろいろとScalaを使っていてちょっとしたコンテナを作る用事があり、Scalaでも構造化ロギングをやりたいと思ったので色々調べて試したところある程度の正解に辿り着いた。環境によって正解は変わるけれど、簡素に組むならこんな感じだよね、という構成を作ったので、ぜひ真似してください。
こんな方法もあるよとか、こういう点がイケてないなどあったらお知らせください。
2024/05/19追記: 新規採用するのであればScribeがおすすめです
- 構成
- 今回の用途
- ファサードAPI: なぜSystem.Logger(JEP 246)か
- ログバックエンド: なぜLogbackか
- ログの構造化: なぜLogbackか
- ログレベル
- 出力されるJSON
- 追加のフィールドを生やす
- まとめ
- 参考文献
構成
先に、構成を全部書いておく。今すぐ試せるリポジトリもあります。
% git clone git@github.com:windymelt/scala-structured-logging-exercise.git % cd scala-structured-logging-exercise % ./build_and_run.sh ... {"sequenceNumber":0,"timestamp":1710175572725,"nanoseconds":725406056,"level":"INFO","threadName":"main","loggerName":"io.github.windymelt.structuredloggingexample.Example","context":{"name":"default","birthdate":1710175572600,"properties":{}},"mdc": {},"message":"Hello, JSON Logger !","throwable":null}
- インターフェイスとして
System.Loggerを使う - ログバックエンドとしてLogbackを使う
System.LoggerとLogbackとの橋渡しのためにslf4j-jdk-platform-loggingを使う
// build.sbt // ... lazy val root = project .in(file(".")) .settings( // ... libraryDependencies ++= Seq( "org.slf4j" % "slf4j-jdk-platform-logging" % "2.0.12", // bridge for Logback "ch.qos.logback" % "logback-classic" % "1.5.3", ), )
src/main/resources/logback.xmlは以下の通り:
<?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE configuration > <configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.JsonEncoder"/> </appender> <root> <level value="INFO"/> <appender-ref ref="STDOUT"/> </root> </configuration>
ロギング用のtraitは以下の通り:
import java.lang.System.Logger.Level /** 継承することでロガーを利用できるようにする。 */ trait Loggable { self => lazy val logger: java.lang.System.Logger = java.lang.System.getLogger(self.getClass().getName()) extension (l: java.lang.System.Logger) { inline def info(msg: String) = logger.log(Level.INFO, msg) inline def warn(msg: String) = logger.log(Level.WARNING, msg) inline def error(msg: String) = logger.log(Level.ERROR, msg) inline def debug(msg: String) = logger.log(Level.DEBUG, msg) } }
inline defで便利なヘルパを書いている。
今回の用途
- JVM上で動作させる
- バッチ処理システム
- 呼ばれる頻度はそれほど高くない
- 1hrに1度くらいでいい
- Cloud Runで動作させる想定
ファサードAPI: なぜSystem.Logger(JEP 246)か
Why (not) SLF4J
JavaやScalaでは、基本的に、ロガーはSLF4Jに対応していればそれでよいという認識でいる。デファクトスタンダードであり、あえて外す理由がないからだ。 今回はAPIとロガーバックエンドに対して求められる積極的な要求がなく、構造化ロギングできさえすればよかったので、ほぼこれで良いと思った。
Why System.Logger
その一方、System.Logger(JEP 264)というのがある。
JEP 246により、Java 9からはログ用のファサードAPIが標準に追加されている。一般論として、標準で提供されているなら可能な限りそちらに寄せたほうがいい。Scalaからももちろん動く。
JEP 246に乗っておくと、将来的にScala Nativeとかを使いたいときに有利になる可能性がある。というのもこのAPI自体はJava標準ライブラリに乗っているのでポートしやすいはずだからだ。
弱みもある。構文上、warnするときにlogger.log(Level.WARN, "foobar")しないといけない(logger.warnしたい)し、ロガー名に文字列しか渡すことができない。つまりクラスだけ渡して勝手に名前を決めてもらうといったことはできない。
今回はこれでも問題なかった。Scalaはextension methodで既存のクラスを拡張できるし、ユースケース的にロガー名に凝ったことはしないからだ。
ちなみに、このAPIだけでstring interpolation的なこともできる(ScalaだとScalaの機能を使えばよいが)。以下の記事によれば、Sentryなどのツールはformat stringを利用してエラーのkeyを決めている？のでこちらが必要なこともあるかもしれない:
この記事は別のライブラリのものなので、どこまで適用していいかはわからない。
嬉しい点として、標準の最低限のロガーバックエンドの他にLogbackを呼び出せるので、Logback用ライブラリを使いたければLogbackを介して利用できる。
あと、何もバックエンドを設定しないデフォルトの出力がスレッドセーフか気になったけど、問題なかった。
Loggerのすべてのメソッドは、マルチスレッド・セーフです。
今回はSLF4Jでもよかったが、標準に寄せたいという気持ちと好奇心でSystem.Loggerに寄せた。問題があればすぐLogbackに戻せるという逃げ道もあったので困らない。
Why not scala-logging
SLF4JのScalaラッパーとして、scala-loggingというライブラリがある。コミュニティメンテで、そこそこにメンテされている。
build.sbtを見た限りではScala 3.3.1に対応しているみたいだし、ScalaはLTSからの後方バイナリ互換性があるので、アプリケーションが3.4とかでも問題なく使えるはずだ。
弱みとして、あくまでこれはSLF4Jのラッパーなので、JEP 264に対応していないという問題がある。 SLF4Jでなければならない理由がなければ、依存しなくてもいいはずと思ったので今回は選ばなかった。
ログバックエンド: なぜLogbackか
Why Logback
Logbackはデファクトスタンダードの地位であり、特に理由がないならこれでよいという認識だ。
Why not log4s
log4sというScalaで書かれたログバックエンドがある。
しかしここ2年メンテされていない(枯れている？)。これはバイナリ互換性が破壊されるような破壊的バージョンアップで弊害になる可能性がある一方、今のところScala 3に対応しているようだ。
バージョンアップに耐えられてほしい堅牢な部品は既にあるJavaのものでいいように思うので、今回はパスした。 将来的にJVMに依存せずScala Nativeを使いたいときなどに浮上する可能性はあると思う。
Why not log4j
既に1系は寿命を迎えており、積極的に採用する理由がない。
Why not log4j2
log4j2はパフォーマンスが良いらしい。しかしそこまでパフォーマンスを追求する用途ではなく、積極的に採用する理由がない。
ログの構造化: なぜLogbackか
ここではどのライブラリで構造化を行ったかについて述べる。
ちなみに各クラウドプロバイダの特殊フィールドは以下のような感じだ:
Logback JSON Encoder
実は、Logbackには最初からJSON用のEncoderが付いてくる。
これはLogback 1.4.8から使える(2023-06-13に1.4.8が出たのでかなり最近だ)。
これでいいならこれにしたい(依存性が減るため)。
弱みとして、timestampフィールドのフォーマットがマイクロ秒unix timeなので認識されないおそれがある、というのがある。できれば、RFC 3339にしたい。とはいえ、JSONを後からいじってtimestampフィールドをRFC3339に変換してtimeフィールドに戻す小細工をすれば終わりなので、やろうと思えばすぐできる。
ちなみにGoogle Cloudではtimestampがなくても勝手にセットされるので、Encoder側で出力を抑制するだけでもいい。
謎の点として、Maven SearchするとなぜかCVE出てるけどミスだったのかrejectされてるというのがある。
Why not logstash-logback-encoder
以前は、logstash-logback-encoderを使うのが定番だった。
アーティファクト名にはlogstashと書いてあるが、単にLogbackのEncoderとして使えるライブラリだ。
Logback標準のものもこちらのライブラリも、裏側ではJacksonを使っている。
Why not 手作り
あたりまえだが、よほどの事情が無い限り手作りするべきではない。今回も既存のものを使いつつ、必要に応じていじる方針にした。
ログレベル
主要なクラウドプロバイダーはseverityによるフィルタリングを提供するため、INFOくらいでどんどん流すことにした。
出力されるJSON
以下のようなJSONが出てくる(実際は1行に収められている):
{ "sequenceNumber": 0, "timestamp": 1710174514796, "nanoseconds": 796747131, "level": "INFO", "threadName": "main", "loggerName": "foo.Bar.Buzz", "context": { "name": "default", "birthdate": 1710174514667, "properties": {} }, "mdc": {}, "message": "Hello, Logger!", "arguments": [ 42, 42 ], "throwable": null }
追加のフィールドを生やす
以下のようなコードを書くと、出力されるJSONにフィールドを追加できる(ここではJSON用ライブラリとしてujsonを使っているが、なんでもいい):
class MyJsonEncoder extends ch.qos.logback.classic.encoder.JsonEncoder { override def encode(event: ILoggingEvent): Array[Byte] = val j = ujson .read(String(super.encode(event))) j("additionalField") = "here it is" (j.toString + "\n") .getBytes() .clone() }
logback.xmlでEncoderのクラス名を書き換えれば終わりだ。
まとめ
- Scalaで構造化ロギングを構成できた。
- Javaには既にロギング用ファサードAPI
System.Loggerが実装されていることを学んだ。 - 最新のLogbackにはJSON出力のサポートがあることを学んだ。
- 少し手直しすると任意のフィールドを追加できることを学んだ。
