アプリのログ出力を slf4j + logback の構成にするときに、依存モジュールのログ出力もslf4jに集める必要があります。
Javaには複数のロガーがあっていろいろとわかりにくい状況になっていますが、以下の記事などで状況や対処方法がまとめられています。
- javaのロガーが多すぎて訳が解らないので整理してみました - 文系プログラマによるTIPSブログ
- Javaのロガーの種類が多すぎ、一元化したい - Qiita
大体はこれらの記事の内容でいいのですが、jul-to-slf4jについてだけは導入方法などが不足しているようだったので、そこのあたりのことをまとめておきます。
なお、slf4jの公式の説明は以下のページになります。
- Log4j Bridge
log4j と commons-logging(略称: jcl)
log4j と commons-logging のログ出力をslf4jへバイパスするには、それぞれの元々のモジュールを依存から除外し、代わりに log4j-over-slf4j と jcl-over-slf4j を依存に追加すれば対処できます。
これだけで対処できているのは、各ロガーのLoggerクラスの実体を挿げ替えているためです。
log4jではorg.apache.log4j.Loggerでログを出力していますが、依存を切り替えたことでlog4jの本来のjarにあるクラスではなくlog4j-over-slf4jのjarに含まれるものを使うようにしています。log4j-over-slf4jに含まれるorg.apache.log4j.Loggerはinterfaceはlog4jの形をしていますが出力先がslf4jになっています。
java.util.logging (略称: jul)
一方で、java.util.logging (以降: jul) はこの方法が使えません。
julはJava本体に含まれるクラスであるため、依存から除外するということができず、クラスを挿げ替えるという方法をとれません。
そのため、jul-to-slf4jでは事前準備処理を組み込む必要があります。
組み込む内容としては以下の２つになります。
対処 1. アプリの起動時の初期化相当の部分で以下の２行を実行すること
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();
対処 2. logback.xmlの定義の最初に以下の記述を追記すること
<configuration>
+ <!-- jul-to-slf4j の対応 ここから -->
+ <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
+ <resetJUL>true</resetJUL>
+ </contextListener>
+ <!-- ここまで -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<logger name="sample" level="ERROR"/>
<logger name="sample.sub" level="DEBUG"/>
<root level="ALL">
<appender-ref ref="STDOUT" />
</root>
</configuration>
これらはそれぞれ、どういう意味なのでしょうか？
それを知るためには、 まず jul でのログ出力のステップを知る必要があります。
julのログ出力の流れ
-
Logging.fine(),finner(),info()などのログ出力メソッドが呼ばれる - そのロガーの出力ログレベルと、実行されたログ出力メソッドのログレベルを比較し、
ログ出力対象かどうかを判定する - ログ出力内容を
LogRecordオブジェクトとしてまとめる - 作成した
LogRecordを そのロガーが持つhandlerに渡す -
handlerが受け取ったLogRecordの内容を出力先に書き出す
- 参考: Logger (Java Platform SE 7 )
この中のhandlerは、logbackなどでいう Appender に相当するものだと思いますが、jul-to-slf4jは「LogRecordを受け取るとslf4jのロガーにログ出力を渡すhandler」を使うことでログのバイパスを行っています。
この「slf4jへバイパスするhandler」を設定する処理が 対処 1 になります。
１行目の removeHandlersForRootLogger() で初期に登録されているhandlerを全て除去し、２行目の install() で slf4jバイパス用のhandlerを登録しています。
さて、handler の挿げ替えでログの出力自体はできますが、上記のログ出力処理の Step 2 のレベル判定部分で問題が残ります。
slf4j のログレベルの設定は、通常では jul には反映されません。
そうすると、logback.xmlで jul が出力しているロガーに対するレベルをWARNやERRORに変えた場合でも、FINEやINFOレベルでもStep 2と3の部分は実行され、slf4j用handlerにLogRecordが渡ってきた時点で再度ログレベルを判定して出力するかどうかが決まる という流れになってしまいます。
その問題への対処が、対処２の意図になります。このLevelChangePropagatorを登録することで、slf4j 上でのログレベル変更(setLevel()メソッド呼び出し)が jul へ反映されるようになります。
公式ドキュメントにおいては、上記の 対処2 の内容を性能問題への対処として説明されていますが、それはこの点への言及になります。 本来 Step 2の時点で捨てられるレベルのログが、handlerに渡されるまで処理してしまう部分が性能低下になるとしているようです。
また、実際には性能の問題だけでなく 対処 2 をしておかないと jul でのINFO未満(FINE、FINERなど)のレベルのログが出力されないという問題もあります。jul ではデフォルトのログレベルが INFO になっているため、Step 2の時点でログ出力が抑制されてしまうからです。
動作確認
実際に、LevelChangePropagatorの効果を確認するために、以下の様なサンプルを作成しました。
package sample;
import org.slf4j.bridge.SLF4JBridgeHandler;
import java.util.logging.*;
public class Main {
// slf4jのロガーを１つでも作らないとちゃんと初期化が行われない様子
private static org.slf4j.Logger notuse = org.slf4j.LoggerFactory.getLogger("");
private static Logger log = Logger.getLogger("sample.Main");
private static Logger logSub = Logger.getLogger("sample.sub.Sub");
public static void main(String[] args) {
// jul-to-slf4jのhandlerを設定
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();
// jul で handler に渡された内容を確認するための処理
LogManager.getLogManager().getLogger("").addHandler(new Handler() {
@Override
public void publish(LogRecord record) {
System.out.printf("----- [%s] %s : %s\n",
record.getLoggerName(), record.getLevel(), record.getMessage()
);
}
@Override
public void flush() {}
@Override
public void close() throws SecurityException {}
});
System.out.println("\n# MAIN");
exec(log);
System.out.println("\n# SUB");
exec(logSub);
}
private static void exec(Logger log) {
log.fine("fine");
log.finer("finer");
log.finest("finest");
log.config("config");
log.info("info");
log.warning("warning");
log.severe("severe");
}
}
この処理を、前述のlogback.xmlを使って実行した結果が以下になります。
LevelChangePropagatorを使った場合
# MAIN
23:29:27.460 ERROR sample.Main - severe
----- [sample.Main] SEVERE : severe
# SUB
23:29:27.467 DEBUG sample.sub.Sub - fine
----- [sample.sub.Sub] FINE : fine
23:29:27.468 INFO sample.sub.Sub - config
----- [sample.sub.Sub] CONFIG : config
23:29:27.469 INFO sample.sub.Sub - info
----- [sample.sub.Sub] INFO : info
23:29:27.469 WARN sample.sub.Sub - warning
----- [sample.sub.Sub] WARNING : warning
23:29:27.470 ERROR sample.sub.Sub - severe
----- [sample.sub.Sub] SEVERE : severe
LevelChangePropagatorを使わなかった場合
# MAIN
----- [sample.Main] INFO : info
----- [sample.Main] WARNING : warning
23:29:44.067 ERROR sample.Main - severe
----- [sample.Main] SEVERE : severe
# SUB
23:29:44.071 INFO sample.sub.Sub - info
----- [sample.sub.Sub] INFO : info
23:29:44.073 WARN sample.sub.Sub - warning
----- [sample.sub.Sub] WARNING : warning
23:29:44.073 ERROR sample.sub.Sub - severe
----- [sample.sub.Sub] SEVERE : severe
上記のとおり、LevelChangePropagatorを使った場合は期待通りの出力になっています。handlerに渡されるログも、実際に出力されるものだけです。
一方で、LevelChangePropagatorを使わなかった場合は、そもそもinfo未満のレベルのログがでていません。また、handlerに出力対象ではないレベルのログも渡されてきています。
性能の問題について
ちなみに、上記のサンプルプログラムを使って処理時間の差異を簡単にみてみたのですが、雑な計測だったからなのかイマイチ優位な違いは見て取れませんでした。
まとめ
Javaのロガーの世界はいろいろとわかりにくところがあります。
その上で、組み込み方も jul についてはちょっと対処が必要ですので、上記を参考にしていただければと思います。