ロガーを自分で実装するのはやめよう
最近以下のようなコードと出会いました。
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
期待する出力が得られました!
また、今度は ClassC
の INFO
ログも不要になったとします。
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-loggingの StrictLogging
を使うことでロガー生成のボイラープレートを削減できます。
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を使いましょう。
まとめ
「ロガーを自分で実装するのはやめよう」というちょっと主語の大きいタイトルになってしまいましたが、
正確には「自作ロガーで単一のロガーインスタンスを使うのはやめよう」かもしれないです。
いずれにしろ、自作ロガーを自分で実装する必要がある際は、上記のデメリットを考慮して実装するのがよいでしょう。
用法用量を守って正しく自作ロガーを使いましょう!