Izumi logstageを試してみた

既存プロジェクトのロガーの置き換えとしてScalaのロガーライブラリであるLogStageを適用できるか検討しました。

#Scala

佐々木一洋

2021.02.26

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

はじめに

最近気になっているScalaのProject Izumi のなかからロガーであるlogstageを試してみました。

背景

この記事は現在プロジェクトで使っているscala logging + logback + logstash logback encoder を置き換えが可能かどうかを調査した内容をまとめたものです。

logstageについて

logstageはProject Izumiに含まれるロガーライブラリです。特徴や基本的な使い方は公式ドキュメントをどうぞ。

やりたいこと

前述の通り既存のロガーの置き換えをする上で必要なことは以下の通りです。今回はこれを実現できるか検討しました。

JSONで構造化したログ出力が行える
- メッセージの他に任意のパラメータを"key" -> "value" の形式で出力できる
- JSONの構造をカスタマイズできる
slf4jを使っているサードパーティライブラリのログ出力ができる
- ロガーごとにレベルを指定できる
HTTPリクエストの情報をコンテキストとしてスレッド間で持ち回れる(具体的にはimplicitパラメータで持ち回る)
- 複数のExecutionContextにまたがって処理を行う場合はLogbackでいうmdcのようなスレッドローカルストレージは使えないのでこれが必要になります

JSONで構造化したログ出力が行える

logstageには標準でJSONによる構造化ログをサポートしていますが、ログの構造をカスタマイズにするには独自のRenderingPolicyを実装する必要があります。

メッセージに指定したパラメータの展開はLogstageCirceRenderingPolicy を参考にて、LogstageCirceRenderingPolicy.Formatを使用しました。この実装だとログにパラメータを構造化してログに含めるにはメッセージに埋め込む必要がありますが、パラメータはメッセージには含めないパターンも欲しいところです。

//JSONの構造のカスタマイズ
  val policy: RenderingPolicy = (entry: Log.Entry) => {
    val formatted = Format.formatMessage(entry, RenderingOptions(withExceptions = false, colored = false))
    val msg: Json = formatted.parameters
      .foldLeft(obj())((acc, p) => acc deepMerge obj(p.normalizedName -> fromString(p.repr)))
      .deepMerge(obj("message" -> fromString(formatted.message)))
      .deepMerge(
        formatted.entry.context.customContext.values.foldLeft(obj()) { (acc, v) =>
          val writer = new LogstageCirceWriter
          v.codec.fold(())(c => c.write(writer, v.value))
          acc deepMerge obj(v.name -> writer.translate())
        })

    obj(
      "level_value" -> fromInt(
        entry.context.dynamic.level.toLogBackLevelValue),
      "time" -> fromString(
        ISO_DATE_TIME_3NANO.format(
          ZonedDateTime.ofInstant(
            Instant.ofEpochMilli(entry.context.dynamic.tsMillis),
            ZoneId.of("Asia/Tokyo")))),
      "logger" -> fromString(entry.context.static.id.id),
      "level" -> fromString(entry.context.dynamic.level.toString.toLowerCase),
      "message" -> msg
    ).toString()
  }

  //ロガーのセットアップ
  val jsonSink = ConsoleSink(policy)
  val sinks = List(jsonSink)
  val logger: IzLogger = IzLogger(Trace, sinks)

//ログ出力
logger.info(s"here's the birb, ${"name" -> "anne"}")

/*
{
  "level_value" : 20000,
  "time" : "2021-02-25T20:50:06.708+09:00[Asia/Tokyo]",
  "logger" : "example.IzumiExample.19",
  "level" : "info",
  "message" : {
    "message" : "here's the birb, anne=name",
    "anne" : "name"
  }
}
*/

slf4j経由でログ出力できる

これは公式ドキュメントに例が掲載されています。ロガーを作成してそのrouterをStaticLogRouterに設定します。ロガー名もLoggerFactory#getLoggerで指定した通りになっていてフォーマットも元のロガーに設定したものが適用されています。

しかしロガー名ごとにログレベル（出力のしきい値）を変える方法がわからなかったです。

//Slf4jロガー経由で出力
val slf4jLogger: Logger = LoggerFactory.getLogger("com.github.someapp")
StaticLogRouter.instance.setup(logger.router)
slf4jLogger.info("this is slf4j log")
/*
{
  "level_value" : 20000,
  "time" : "2021-02-25T20:50:06.870+09:00[Asia/Tokyo]",
  "logger" : "com.github.someapp",
  "level" : "info",
  "message" : {
    "message" : "this is slf4j log"
  }
*/

HTTPリクエストの情報をコンテキストとしてスレッド間で持ち回れる

続いてコンテキストの持ち回りです。以下のようにCustomContextを指定して新たにロガーを作成することでコンテキストを含めたログ出力が行えます。以下の例では持ち回ったRequestContextを使ってCustomContextを設定するのをイメージしています。

//case class
final case class Birb(name: String)

final case class RequestContext(uri: String, method: String) {
  def asMap: Map[String, AnyEncoded] = Map("uri" -> uri, "method" -> method)
}

val loggerWithContext = logger.withCustomContextMap(RequestContext("/v1/some_api/", "GET").asMap)
loggerWithContext.info("log with request context")

/*
{
  "level_value" : 20000,
  "time" : "2021-02-25T20:50:06.864+09:00[Asia/Tokyo]",
  "logger" : "example.IzumiExample.19",
  "level" : "info",
  "message" : {
    "method" : "GET",
    "uri" : "/v1/some_api/",
    "message" : "log with request context"
  }
}
*/

上位の例ではリクエストの情報を含めたログを出力できたのですが、以下の点が気になりました。

RequestContextからログ出力の度にロガーを生成するオーバーヘッドが多くなりそう（生成したロガーを持ち回るとロガー名が生成したクラス名になってしまう）
ネストしたコンテキストの設定方法がわからなかった（CustomContextにネストしたMapを渡すと値がnullになってしまった）
ログに出力するためだけにtoMapを実装するのが冗長（shapelessと型クラスで自動化はできるが）