logbackでラッパー機能を作ったときに正しくログ出力実施行を出力する方法

概要

logbackではlogback.xmlのappnderのpatternタグに以下のように記載すれば、ログ出力メソッドを実行したファイルや行番号、メドッド名を出力することができます。

logback.xml

<!-- [%file:%line %method] でファイルと行番号とメソッドを出力 -->
<pattern>%date %level [%thread] %logger{64} [%file:%line %method] %msg%n</pattern>

このとき、org.slf4j.Loggerをラップするようなメソッドを作ってログ機能を拡張しようとすると、上記のログ出力箇所が意図しないものになります。

例えば、以下のような「任意のオブジェクトを文字列化してログ出力するメソッド」を作ったとします。

val logger: org.slf4j.Logger = LoggerFactory.getLogger(Hoge) 

def debug(arg: Any) {
  logger.debug(arg.toString);
}

def run(args: List[String]) {
  debug(args)
  〜〜
}

上記の例では、runメソッド内でログ出力をしようとdebugを実行しています。
期待としては、ログ出力箇所はこのrunメソッドの場所を出力してくれた方が嬉しいところですが、この場合はlogger.debug()を実行した場所になってしまいます。

対処方法

こういう場合には、以下の方法で特定のパッケージをログ出力箇所の対象外にすることができます。

AddFrameworkPackageLoggerContextListener.scala

package logging

import ch.qos.logback.classic.spi.LoggerContextListener
import ch.qos.logback.classic.{ Level, Logger, LoggerContext }
import ch.qos.logback.core.Context
import ch.qos.logback.core.spi.ContextAwareBase
import ch.qos.logback.core.util.ContextUtil

class AddFrameworkPackageLoggerContextListener extends ContextAwareBase with LoggerContextListener {

  override def setContext(context: Context): Unit = {
    super.setContext(context)

    // 自分のログ出力機能のパッケージを登録
    val packageName = "myapp.logging"
    addInfo("Adding framework package [" + packageName + "]")

    val lc = context.asInstanceOf[LoggerContext]
    val contextUtil = new ContextUtil(context)
    contextUtil.addFrameworkPackage(lc.getFrameworkPackages, packageName)
  }

  override def isResetResistant: Boolean = { false } // do nothing
  override def onReset(context: LoggerContext): Unit = {} // do nothing
  override def onStart(context: LoggerContext): Unit = {} // do nothing
  override def onLevelChange(logger: Logger, level: Level): Unit = {} // do nothing
  override def onStop(context: LoggerContext): Unit = {} // do nothing

}

logback.xml

<configuration debug="true">
    <contextListener class="logging.AddFrameworkPackageLoggerContextListener"/>

（略）
</configuration>

解説

logbackでは、一時的に生成した例外オブジェクトを生成し、それが持つコールスタックを上から辿ることで実際のログ出力実行行を取得します。
このとき、コールバックに含まれるlogbackフレームワーク自身の内容を除去することで、ログ出力箇所(logger.debug()を実行した箇所)を特定しています。
この「logbackフレームワークかどうか」という判定が、「パッケージ名がLoggerContext.getFramweworkPackages()に含まれているかどうか」によって行われます。
そこで、getFrameworkPackages()のリストに自前のログ出力機能のパッケージを追加してあげると、自前のログ出力メソッドを実行した箇所が%fileや%lieで出力されるようになります。

なお、LoggerContextListenerはログ出力設定に割り込める機能のようですが、ドキュメントが整っていないのでいまいちどのように使うのかが正解がわかりません。
試してみると、onResetやonStart、onStopが呼び出されている様子がなく、onLevelChangeがlogback.xmlの読解中にタグごとに実行されていました。
ContextAwareBaseを継承していると、初期化時にsetContextが呼ばれていたので、とりあえずここで目的の処理を記述することで対処しました。

このLoggerContextListenerの機能は公式ドキュメントの以下に記載がありますが、あまり内容がありません...
http://logback.qos.ch/manual/configuration.html#contextListener

詳細

以下に、メモがてらにlogbackフレームワークの具体的に関連する箇所を列挙しておきます。

• ch.qos.logback.classic.spi.CallerData#extract
  • ログ出力箇所のコールスタックの内容を生成する
• ch.qos.logback.classic.spi.LoggingEvent#getCallerData
  • CallerData#extractを使ってログ出力箇所のコールスタックを取得
• ch.qos.logback.classic.PatternLayout
  • ここで<pattern>タグのキーワードとその出力処理を定義
• ch.qos.logback.classic.pattern.FileOfCallerConverter
  • ログ出力箇所のファイル名を取得
  • LoggingEvent#getCallerDataで生成されたコールスタックの先頭の内容からファイル名を取得
• ch.qos.logback.classic.joran.JoranConfigurator
  • logback.xmlのパースルール定義
• ch.qos.logback.classic.joran.action.LoggerContextListenerAction
  • <contextListener>タグを登録する処理

まとめ

PlayやSkinnyなどのWebフレームワークなどではログ出力処理をフレームワーク内のログ機能でラップしていることがあり、この問題によってログ出力箇所が無意味になっていることがあります。
上記の対処を行えば、そういったフレームワークの機能を使いつつ、ログ出力箇所を期待する出力にすることができます。