ぶらっ記ぃ

日本語の練習をしています

ロガーを自分で実装するのはやめよう

最近以下のようなコードと出会いました。

package logging

import org.slf4j.LoggerFactory

object Logger {
  private val logger = LoggerFactory.getLogger("LOGGER")

  def debug(message: String): Unit = {
    logger.debug(message)
  }

  def info(message: String): Unit = {
    logger.info(message)
  }
  
  // warn, error...
}

いわゆる「自作ロガー」と言うものですね。
みなさんもこのようなコードを見たことがあるのではないでしょうか。

今回は、この自作ロガーのメリット・デメリットを考えてみます。

(前提)

今回の例では slf4j + Logback を使います。

自作ロガーのメリット

クラスごとにインスタンス生成が不要

このような自作ロガーのメリットはクラスごとにインスタンス生成が不要なことでしょう。

import logging.Logger
import org.slf4j.LoggerFactory

// 自作ロガーを使った場合
object Sample01 {
  def doSomething(): Unit = {
    Logger.info("do something!")
  }
}

// 使わない場合
object Sample02 {
  private[this] val logger = LoggerFactory.getLogger(getClass)
  
  def doSomething(): Unit = {
    logger.info("do something!")
  }
}

自作ロガーを使った方がシンプルに見えます。
ロギングをしたいクラスごとにインスタンス生成をする必要がないのでタイプ量が少なくて楽そうですね。

自作ロガーのデメリット

しかしながら、このような自作ロガーを使うことはメリットを大きく上回るデメリットがあると思っています。

ログに関心のないスタックが入り込む

以下のような logback.xml があるとします。

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>[%class#%method\(%file:%line\)] %logger{0} - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="LOGGER" level="debug">
    <appender-ref ref="STDOUT" />
  </logger>
</configuration>

%class#%method\(%file:%line\) の部分でロガーが呼ばれた箇所を出力しています。

自作ロガーを使ってロギングしてみましょう

object Sample03 {
  def main(args: Array[String]): Unit = {
    Logger.info("logging!!!!!!")
  }
}
[logging.Logger$#info(Logger.scala:9)] LOGGER - logging!!!!!!

Sample03$#main... の出力を期待してしまいますが、実際に出力されたのは logging.Logger$#info(Logger.scala:9) です。

まぁよく考えれば当たり前なのですが、これではどこでログが吐かれたのかわかりにくくデバッグの際に困ってしまいます。
また、例えばSentryなどでエラーログが吐かれた箇所のスタックトレースが表示されたときに関心のないスタックが含まれてしまうのは良くないです。

※ただし、この問題に関しては LocationAwareLogger を使うことで回避できます。

参考: 自作LoggerではLocationAwareLoggerを使おう

ロギングライブラリの仕組みに乗れない

以下のようなクラスがあるとします。
logback.xml の設定は上記と同じものを使っています。

import logging.Logger

package pkgA {
  class ClassA {
    def doSomething(): Unit = {
      Logger.debug("DEBUG A")
      Logger.info("INFO A")
    }
  }
}

package pkgB {
  class ClassB {
    def doSomething(): Unit = {
      Logger.debug("DEBUG B")
      Logger.info("INFO B")
    }
  }

  class ClassC {
    def doSomething(): Unit = {
      Logger.debug("DEBUG C")
      Logger.info("INFO C")
    }
  }
}

package main {

  import pkgA.ClassA
  import pkgB.{ClassB, ClassC}

  object Main {
    def main(args: Array[String]): Unit = {
      (new ClassA).doSomething()
      (new ClassB).doSomething()
      (new ClassC).doSomething()
    }
  }
}

mainを実行します。

[logging.Logger$#debug(Logger.scala:9)] LOGGER - DEBUG A
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO A
[logging.Logger$#debug(Logger.scala:9)] LOGGER - DEBUG B
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO B
[logging.Logger$#debug(Logger.scala:9)] LOGGER - DEBUG C
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO C

ログが出力されました。

ここで、 pkgB パッケージの DEBUG ログに関心がなくなったので出力を止めたいと思ったとします。
logback.xml を以下のように書き換えてみますが…

  <!-- debug -> info -->
  <logger name="LOGGER" level="info">
    <appender-ref ref="STDOUT" />
  </logger>
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO A
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO B
[logging.Logger$#info(Logger.scala:13)] LOGGER - INFO C

関係のない ClassA のログまでもログが止まってしまいました。
Logger オブジェクトがひとつのロガーインスタンスを使いまわしているのが原因です。

自作ロガーを使うのをやめてみましょう。

import org.slf4j.LoggerFactory

class ClassA {
  private[this] val logger = LoggerFactory.getLogger(getClass)

  def doSomething(): Unit = {
    Logger.debug("DEBUG A")
    Logger.info("INFO A")
  }
}
// ClassB, ClassC も同様に修正

また、 logback.xml を以下のように書き換えます。

<!-- コメントアウト
  <logger name="LOGGER" level="debug">
    <appender-ref ref="STDOUT" />
  </logger>
-->

  <logger name="pkgB" level="info" />

  <root name="LOGGER" level="debug">
    <appender-ref ref="STDOUT" />
  </root>

mainを実行してみましょう。

[pkgA.ClassA#doSomething(Sample.scala:11)] ClassA - DEBUG A
[pkgA.ClassA#doSomething(Sample.scala:12)] ClassA - INFO A
[pkgB.ClassB#doSomething(Sample.scala:27)] ClassB - INFO B
[pkgB.ClassC#doSomething(Sample.scala:36)] ClassC - INFO C

期待する出力が得られました!

また、今度は ClassCINFO ログも不要になったとします。
logback.xml に以下を追加します。

  <logger name="pkgB.ClassC" level="warn" />
[pkgA.ClassA#doSomething(Sample.scala:11)] ClassA - DEBUG A
[pkgA.ClassA#doSomething(Sample.scala:12)] ClassA - INFO A
[pkgB.ClassB#doSomething(Sample.scala:27)] ClassB - INFO B

ClassC のログがなくなりました!

このように、ロガーインスタンスを使い分けることで柔軟なログ設計が可能になります。

おまけ: ロガーインスタンスの生成にscala-loggingを使う

scala-loggingStrictLogging を使うことでロガー生成のボイラープレートを削減できます。

import com.typesafe.scalalogging.StrictLogging

class ClassA extends StrictLogging {
  // ↓と同等のことを行ってくれる
  // private[this] val logger = LoggerFactory.getLogger(getClass)

  def doSomething(): Unit = {
    logger.debug("DEBUG A")
    logger.info("INFO A")
  }
}

そのほか、macroによってログ出力が有効になっているかチェックするif式で挟んでくれたり、
StringInterpolationによるログメッセージを {} によるフォーマットに書き換えてくれたりなど、細かな最適化を行ってくれます。

Scalaでslf4jを使っているならぜひscala-loggingを使いましょう。

まとめ

「ロガーを自分で実装するのはやめよう」というちょっと主語の大きいタイトルになってしまいましたが、
正確には「自作ロガーで単一のロガーインスタンスを使うのはやめよう」かもしれないです。

いずれにしろ、自作ロガーを自分で実装する必要がある際は、上記のデメリットを考慮して実装するのがよいでしょう。

用法用量を守って正しく自作ロガーを使いましょう!