アプリのログ出力を 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に変更しても、Step 2の部分でのレベル判定では変更したレベル設定が利用されません。そのため、例えばINFOなどの本来制限されるレベルのログはStep.2〜5の処理をしたうえで、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 についてはちょっと対処が必要ですので、上記を参考にしていただければと思います。