scala-loggingを使ってみる

概要

typesafe系のログ出力ライブラリを見かけたので使ってみる。名前はscala-logging。Scala2.11から利用可能らしい。

内容的にはよくあるSLF4Jのラッパーだけど、Scalaのマクロ機能を利用しており

logger.debug(s"Some $expensive message!")

と書くだけで

if (logger.isDebugEnabled) logger.debug(s"Some $expensive message!")

的な意味合いに変換してくれるのが売りらしい。マクロ便利。

広告枠

準備

build.sbtにdepencencyを設定。

libraryDependencies ++= Seq(
    "com.typesafe.scala-logging" %% "scala-logging" % "3.1.0",
    "ch.qos.logback" % "logback-classic" % "1.1.3"
)

scala-loggingの依存にslf4jは入っている。scala-loggingに加えてlogbackかlog4jを入れれば済む。

ここではlogbackを選択。

logback.xmlの準備

classpathの通ってるところにlogback.xmlファイルを作って下記を記述。

せっかくなので実用的っぽい記述を貼っておく。

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> utEncoder -->
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
 
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>logs/app.log</file>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>INFO</level>
    </filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>logs/app.log.%d{yyyy-MM-dd}.%i</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
        <maxFileSize>1MB</maxFileSize>
      </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
  </root>
 
</configuration>

意味的には、DEBUG以上なら標準出力して、INFO以上ならファイル出力。ファイルは日付でrotate、ログファイルサイズが1MB以上になった時もrotate。という設定。

普段はだいたいこれくらいの設定で動かしてるのだけど、一般的にはどうなのだろう。

普通にログ出力

まずは自前でloggerを生成してログ出力してみる。

import com.typesafe.scalalogging.Logger
import org.slf4j.LoggerFactory

object Example extends App {
  val logger = Logger(LoggerFactory.getLogger("logger_name"))
  logger.debug("foo")
  logger.info("bar")
  logger.warn("baz")
}

これでfoo, bar, bazが標準出力され、bar, bazがログファイルに出力される。

LazyLoggingでログ出力

scala-loggingの中にはLazyLoggingというtraitが入っていて、中にはprotected lazy val loggerという変数が設定されている。

これを利用すると下記のようにextendsするだけでログ出力が可能。

class Foo extends LazyLogging {
  logger.info("foo")
}

これまで自前で似たようなtraitを使ってログ出力していたので、これがデフォルトで用意されているのはありがたい。

LazyLoggingの他にも、遅延評価しない版のStrictLoggigというクラスもある。

詳細はgithubの当該コードを参照。

マクロの当該コードも見ておく

実際にどういったコードの変換されているのか、マクロを見て確認しておく。

下記はLoggerクラスのinfoのところ。

  def info(message: String): Unit = macro LoggerMacro.infoMessage

同パッケージ内にあるLoggerMacroのinfoMessageを呼び出している。

  type LoggerContext = Context { type PrefixType = Logger }

  def infoMessage(c: LoggerContext)(message: c.Expr[String]) = {
    import c.universe._
    val underlying = q"${c.prefix}.underlying"
    q"if ($underlying.isInfoEnabled) $underlying.info($message)"
  }

ちゃんとif(logger.isInfoEnabled)が加えられていることがわかる。