アプリへのslf4j + logback 導入時の java.util.logging 向け対処

アプリのログ出力を slf4j + logback の構成にするときに、依存モジュールのログ出力もslf4jに集める必要があります。
Javaには複数のロガーがあっていろいろとわかりにくい状況になっていますが、以下の記事などで状況や対処方法がまとめられています。
 
  * javaのロガーが多すぎて訳が解らないので整理してみました - 文系プログラマによるTIPSブログ
    * http://www.bunkei-programmer.net/entry/2012/10/20/javaのロガーが多すぎて訳が解らないので整理して
  * Javaのロガーの種類が多すぎ、一元化したい - Qiita
    * http://qiita.com/k_ui/items/7ed7d9f9c15dc9bcc26f

大体はこれらの記事の内容でいいのですが、`jul-to-slf4j`についてだけは導入方法などが不足しているようだったので、そこのあたりのことをまとめておきます。

なお、slf4jの公式の説明は以下のページになります。

 *  Log4j Bridge
    * http://www.slf4j.org/legacy.html


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. アプリの起動時の初期化相当の部分で以下の２行を実行すること**

```java
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();
```

**対処 2. `logback.xml`の定義の最初に以下の記述を追記すること**

```diff: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のログ出力の流れ**

1. `Logging.fine()`, `finner()`, `info()` などのログ出力メソッドが呼ばれる
2. そのロガーの出力ログレベルと、実行されたログ出力メソッドのログレベルを比較し、
   ログ出力対象かどうかを判定する
3. ログ出力内容を `LogRecord`オブジェクトとしてまとめる
4. 作成した`LogRecord`を そのロガーが持つ `handler`に渡す
5. `handler`が受け取った`LogRecord`の内容を出力先に書き出す

  * 参考: Logger (Java Platform SE 7 )
    * https://docs.oracle.com/javase/jp/7/api/java/util/logging/Logger.html


この中の`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`の効果を確認するために、以下の様なサンプルを作成しました。

```java:sample/Main.java
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 についてはちょっと対処が必要ですので、上記を参考にしていただければと思います。