Spring Boot アプリを war にして Tomcat にデプロイしたら JUL を使ったログがアプリのログに出力されなくなった場合の対処方法

組み込み Tomcat で起動していた Spring Boot アプリケーションを、諸事情により war 化して Tomcat サーバーにデプロイすることになった。
しかし、その際 [java.util.logging](https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/package-summary.html) （以下 JUL）のロガーを使って出力してたログがアプリのログに出力されなくなり、代わりに Tomcat のログファイル（catalina.log）に出力されるようになるという問題が発生した。

その原因と対応方法、および学んだことについてのメモ。

# 環境
**OS**

`Windows 10 (64bit)`

**Java**

`openjdk 11.0.2`

**Tomcat Server**

`9.0.19`

**Spring Boot**

`2.1.4`

# 組み込み Tomcat で動かしていたときの様子
## ソースコード
```text:プロジェクト構成
|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-ExecutableJarApplication.java
  `-resources/
    `-logback.xml
```

```gradle:build.gradle
plugins {
    id 'org.springframework.boot' version '2.1.4.RELEASE'
    id 'java'
}

apply plugin: 'io.spring.dependency-management'

sourceCompatibility = '11'
targetCompatibility = '11'
compileJava.options.encoding = "UTF-8"

repositories {
    mavenCentral()
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
}
```

```java:ExecutableJarApplication.java
package sample.jul;

import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class ExecutableJarApplication {
    public static void main(String[] args) {
        SpringApplication.run(ExecutableJarApplication.class, args);
    }
    
    private static final java.util.logging.Logger julLogger = java.util.logging.Logger.getLogger(ExecutableJarApplication.class.getName());
    private static final org.slf4j.Logger slf4jLogger = LoggerFactory.getLogger(ExecutableJarApplication.class);

    @GetMapping("/hello")
    public void hello() {
        julLogger.info("Hello JUL Logger!!");
        slf4jLogger.info("Hello SLF4J Logger!!");
    }
}
```

これはあくまで検証用であり、実際のアプリケーションで異なるロガーを１つのクラスで混在させることはないと思う。
実際には、利用していたサードパーティーのライブラリが JUL を使ってログ出力しているようなケースを想定している。

```xml:logback.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%-5level] %-15logger{15} - %m%n</pattern>
        </encoder>
    </appender>
    
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>
```

## 実行結果
`bootRun` で起動したのち、 `http://localhost:8080/hello` に GET リクエストを送信する。

```text:コンソール出力
[INFO ] s.j.ExecutableJarApplication - Hello JUL Logger!!
[INFO ] s.j.ExecutableJarApplication - Hello SLF4J Logger!!
```

どちらのロガーも、問題なく出力されている。

# War 化して Tomcat にデプロイした場合
## ソースコード
```text:プロジェクト構成
|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-WarApplication.java
  `-resources/
    `-logback.xml
```

```gradle:build.gradle
plugins {
    id 'org.springframework.boot' version '2.1.4.RELEASE'
    id 'war'
}

apply plugin: 'io.spring.dependency-management'

sourceCompatibility = '11'
targetCompatibility = '11'
compileJava.options.encoding = "UTF-8"

war {
    enabled = true
    baseName = "sample"
}

repositories {
    mavenCentral()
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    providedRuntime 'org.springframework.boot:spring-boot-starter-tomcat'
}
```

```java:WarApplication.java
package sample.jul;

import org.slf4j.LoggerFactory;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.boot.web.servlet.support.SpringBootServletInitializer;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class WarApplication extends SpringBootServletInitializer {
    @Override
    protected SpringApplicationBuilder configure(SpringApplicationBuilder builder) {
        return builder.sources(WarApplication.class);
    }

    private static final java.util.logging.Logger julLogger = java.util.logging.Logger.getLogger(WarApplication.class.getName());
    private static final org.slf4j.Logger slf4jLogger = LoggerFactory.getLogger(WarApplication.class);

    @GetMapping("/hello")
    public void hello() {
        julLogger.info("Hello JUL Logger!!");
        slf4jLogger.info("Hello SLF4J Logger!!");
    }
}
```

War 化で必要な変更以外（ログ出力など）はそのまま。

`logback.xml` は変更なし。

## 実行結果
Tomcat にデプロイし、 `http://localhost:8080/sample/hello` に GET リクエストを送信する。

```text:Tomcatのコンソール出力
24-Apr-2019 22:15:57.041 情報 [http-nio-8080-exec-3] sample.jul.WarApplication.hello Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!
```

出力はされているが、JUL の方のフォーマットが `logback.xml` で指定していたものとは違うものになっている。

さらに Tomcat のログである `catalina.log` を見ると、

```text:catalina.log
24-Apr-2019 22:15:57.041 情報 [http-nio-8080-exec-3] sample.jul.WarApplication.hello Hello JUL Logger!!
```

出力されている。

# 何が起こっているのか
## JUL と SLF4J のブリッジ
SLF4J には、 JUL のロガーに出力された内容を SLF4J 側のロガーにブリッジ（橋渡し）する機能が用意されている。

これには、 JUL のハンドラと呼ばれる仕組みが利用されている。

JUL のロガーは、内部にハンドラというものを持っている（クラスでいうと [Handler](https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/Handler.html)）。
ロガーに出力されたログ情報は、このハンドラに渡され、実際のログ出力処理はハンドラが行うようになっている。

たとえば、 [ConsoleHandler](https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/ConsoleHandler.html) はその名前の通りコンソールにログを出力する。
一方、 [FileHandler](https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/FileHandler.html) はファイルにログを出力する。

SLF4J の提供する `jul-to-slf4j.jar` には、「SLF4J のロガーに出力を委譲するハンドラ」が用意されている。
これを JUL のルートロガーに登録することで、 JUL のロガーに出力されたログ情報が SLF4J のロガーにも渡されるようになる。

実際、 `jul-to-slf4j.jar` に入っているブリッジ用のクラスは次のようになっている。

```java:SLF4JBridgeHandler.java
...
public class SLF4JBridgeHandler extends Handler {
    ...
    public static void install() {
        LogManager.getLogManager().getLogger("").addHandler(new SLF4JBridgeHandler());
    }
    ...
```

`install()` メソッドを実行すると、 `LogManager` からルートロガーを取得し、 `SLF4JBridgeHandler` を追加しているのがわかる。

## ブリッジの条件
Spring Boot で SLF4J を使う場合、この `SLF4JBridgeHandler.install()` メソッドが起動時に実行されるようになっている。

具体的には `Slf4JLoggingSystem` というクラスで行われており、実装は次のようになっている。

```java:Slf4JLoggingSystem.java
    private void configureJdkLoggingBridgeHandler() {
        try {
            if (isBridgeJulIntoSlf4j()) {
                removeJdkLoggingBridgeHandler();
                SLF4JBridgeHandler.install(); // ★ここでブリッジを登録している
            }
        }
        catch (Throwable ex) {
            // Ignore. No java.util.logging bridge is installed.
        }
    }

    protected final boolean isBridgeJulIntoSlf4j() {
        return isBridgeHandlerAvailable() && isJulUsingASingleConsoleHandlerAtMost();
    }

    protected final boolean isBridgeHandlerAvailable() {
        return ClassUtils.isPresent(BRIDGE_HANDLER, getClassLoader());
    }

    private boolean isJulUsingASingleConsoleHandlerAtMost() {
        Logger rootLogger = LogManager.getLogManager().getLogger("");
        Handler[] handlers = rootLogger.getHandlers();
        return handlers.length == 0
                || (handlers.length == 1 && handlers[0] instanceof ConsoleHandler);
    }
```

なにやら `install()` を呼ぶための条件がいろいろ書かれているが、最後の `isJulUsingASingleConsoleHandlerAtMost()` のところを見ると、次の**いずれか**の条件を満たさなければならないことがわかる。

- ルートロガーに登録されているハンドラが 0 である（ハンドラが登録されていない）
- ハンドラが、 `ConsoleHandler` しか登録されていない（JUL のデフォルトの状態）

## Tomcat がデフォルトで登録するハンドラ
Tomcat は、ログ出力に JUL を使用している（厳密には独自拡張を含んでいるが、詳細後述）。

Tomcat のデフォルトの JUL 設定ファイルは、 `${CATALINA_HOME}/conf/logging.properties` に存在する。
そして、ルートロガーのハンドラは次のように設定されている。

```properties:logging.properties
.handlers = 1catalina.org.apache.juli.AsyncFileHandler, java.util.logging.ConsoleHandler
```

ファイル出力とコンソール出力の、２つのハンドラが登録されている。
（この `1catalina.org.apache.juli.AsyncFileHandler` が、 `catalina.log` を出力するハンドラ）

つまり、 Tomcat にデプロイしたアプリケーションでは、 `LogManager.getLogManager().getLogger("")` で取得できるルートロガーには、デフォルトで２つのハンドラが登録されていることになる。

すると、先程の「Spring Boot で SLF4J のブリッジを登録するための条件」を満たさないことになる。

結果、 SLF4J のブリッジは登録されず、 JUL 経由のログ出力には Tomcat のデフォルト設定（`catalina.log` とコンソールへの出力）が適用されていた。

雰囲気を図で表すと↓のような感じ。

![jul.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/28302/88eca021-6d54-b309-99b9-7d04fcc51dd4.jpeg)

## 試しにブリッジを無理やり登録してみる
Spring Boot が決めてる条件に合わないから登録されていないだけなので、無理やりブリッジを登録することはできる。

```java:WarApplication.java
package sample.jul;

import org.slf4j.bridge.SLF4JBridgeHandler;
...

@SpringBootApplication
@RestController
public class WarApplication extends SpringBootServletInitializer {
    @Override
    protected SpringApplicationBuilder configure(SpringApplicationBuilder builder) {
        SLF4JBridgeHandler.install(); // ★無理やりブリッジを登録
        return builder.sources(WarApplication.class);
    }

    ...
}
```

```text:実行結果
24-Apr-2019 22:59:23.405 情報 [http-nio-8080-exec-18] sample.jul.WarApplication.hello Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!
```

`logback.xml` で指定した書式で出力されるようになった。
ただ、 Tomcat デフォルト設定の方も依然有効なままとなっている。

先程と同じく雰囲気を図で表すと、↓のような感じとなっている。

![jul.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/28302/6864a5c0-90c9-66dd-5e83-e05a00db49fd.jpeg)

ブリッジを追加しただけなので、 Tomcat 側の出力とアプリ側の出力とで、ログ出力が重複した状態になっている。

# 対処方法
## ルートロガーのハンドラを消す
```java:
package sample.jul;

...

import java.util.logging.Handler;
import java.util.logging.LogManager;
import java.util.logging.Logger;

@SpringBootApplication
@RestController
public class WarApplication extends SpringBootServletInitializer {
    @Override
    protected SpringApplicationBuilder configure(SpringApplicationBuilder builder) {
        Logger rootLogger = LogManager.getLogManager().getLogger("");
        for (Handler handler : rootLogger.getHandlers()) {
            rootLogger.removeHandler(handler);
        }

        return builder.sources(WarApplication.class);
    }

    ...
}
```

Spring Boot の条件では、ルートロガーにハンドラがなければブリッジが登録されることになる。
また、 Tomcat がデフォルト設定するハンドラが残っていると、ログ出力が重複することになる。

ということで、起動前にルートロガーからハンドラを全削除してしまえば、組み込み Tomcat で実行していたときと同じ状態になるはず。

これをデプロイして動作確認をすると、次のようになる。

```text:Tomcatコンソール出力
[INFO ] s.j.WarApplication - Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!
```

Tomcat デフォルト設定の出力はなくなり、アプリで設定した SLF4J によるログ出力だけになった。
`catalina.log` にも、当然出力されなくなっている。

イメージは、↓のような感じ。

![jul.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/28302/c21948f8-056e-d602-4804-e35e6b785038.jpeg)

## ルートロガーの設定を書き換えて大丈夫？
```java
        Logger rootLogger = LogManager.getLogManager().getLogger("");
        for (Handler handler : rootLogger.getHandlers()) {
            rootLogger.removeHandler(handler);
        }
```

この実装を見ると、 `LogManager` は `static` メソッドを経由して取得している。
ということは、 `LogManager` のインスタンスはシングルトンの気配がする。

試しに `LogManager` の実装を見ると、次のようになっている。

```java:LogManager.java
...
public class LogManager {
    // The global LogManager object
    private static final LogManager manager;
    ...
    private volatile Logger rootLogger;
    ...

    public static LogManager getLogManager() {
        if (manager != null) {
            manager.ensureLogManagerInitialized();
        }
        return manager;
    }
    ...
```

`LogManager` のインスタンス（`manager`） は `static final` なフィールドに保存されていて、シングルトンになっている。
そして、ルートロガーはその `LogManager` のインスタンスフィールドとして宣言されている。

`LogManager` は標準 API に含まれており、ブートストラップ・クラスローダーによってロードされる。
ということは、 `LogManager` のインスタンスは JVM 上で共有されることになる。

Tomcat を動かしている JVM 自体は１つなので、その上にデプロイされる各 Web アプリケーションからアクセスする `LogManager` は、全て同じインスタンスを参照することになる。

となると、あるデプロイされた１つのアプリがルートロガーの状態を変更すると、他にデプロイされているアプリや、それどころか Tomcat 本体に対しても影響を与えてしまいそうな気がする。

果たして、ルートロガーのハンドラを全削除するというのは問題ないのか、不安になる。

## Tomcat はクラスローダー単位でロガーの管理を分けている
JUL のデフォルトの実装だと、 JVM 内で１つのルートロガーが共有されることになるため、前述のような問題が起こり得る。

そこで Tomcat では、クラスローダー単位でロガーを分けて管理できる独自の `LogManager` を用意して、デフォルトの実装を差し替えるようにしている。

つまり、雰囲気としては↓のようなことができるようになっている。

![jul.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/28302/c8982c30-231a-59c4-73da-285014532335.jpeg)

このへんの、 Tomcat における JUL の扱いについては、公式ドキュメントで説明されている。

[Apache Tomcat 9 (9.0.19) - Logging in Tomcat](https://tomcat.apache.org/tomcat-9.0-doc/logging.html#Using_java.util.logging_(default))

### LogManager の実装を差し替える方法
`LogManager` の実装自体は標準ライブラリ内に存在している。
それなのにどうやって実装を差し替えているかと言うと、 `LogManager` 自体に実装を差し替えるための仕組みが用意されている。

`LogManager` のインスタンス生成部分の実装を見ると、次のようになっている。

```java:LogManager.java

    static {
        manager = AccessController.doPrivileged(new PrivilegedAction<LogManager>() {
            @Override
            public LogManager run() {
                LogManager mgr = null;
                String cname = null;
                try {
                    cname = System.getProperty("java.util.logging.manager");
                    if (cname != null) {
                        try {
                            @SuppressWarnings("deprecation")
                            Object tmp = ClassLoader.getSystemClassLoader()
                                .loadClass(cname).newInstance();
                            mgr = (LogManager) tmp;
                        } catch (ClassNotFoundException ex) {
                            @SuppressWarnings("deprecation")
                            Object tmp = Thread.currentThread()
                                .getContextClassLoader().loadClass(cname).newInstance();
                            mgr = (LogManager) tmp;
                        }
                    }
                } catch (Exception ex) {
                    System.err.println("Could not load Logmanager \"" + cname + "\"");
                    ex.printStackTrace();
                }
                if (mgr == null) {
                    mgr = new LogManager();
                }
                return mgr;

            }
        });
    }
```

`static` イニシャライザで `manager` のインスタンスを初期化している。

このとき、システムプロパティ `java.util.logging.manager` が指定されているかを確認している。
もし指定されている場合は、そこで指定されたクラスをロードし、生成したインスタンスを `manager` に代入している。

一応、 `LogManager` の [Javadoc](https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/LogManager.html) には「LogManagerクラスは、起動時に `java.util.logging.manager` システム・プロパティを使用して配置されます。」と説明が書かれている[^1]。

[^1]: この説明で誰が分かんねん

Tomcat の起動スクリプトを見ると、確かに次のように指定されているのが確認できる。

```bash:catalina.bat
if not "%LOGGING_MANAGER%" == "" goto noJuliManager
set LOGGING_MANAGER=-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
```

## 設定ファイルでハンドラを空にする
ところで、 Tomcat はデプロイする Web アプリケーション単位で JUL の設定ファイル（`logging.properties`）を配置できるようにしてくれている。

なので、次のようにすれば実装でルートロガーを空にする必要もない。

```text:プロジェクト構成
|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-WarApplication.java
  `-resources/
    |-logging.properties ★追加
    `-logback.xml
```

```properties:logging.properties
.handlers=
```

内容は、ルートロガーのハンドラを空にするようにしている。

デプロイして動作を確認する。

```text:Tomcatコンソール出力
[INFO ] s.j.WarApplication - Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!
```

うまくいってるっぽい気がする気配な雰囲気。

# 参考
- [jul-to-slf4jのしくみ - Qiita](https://qiita.com/kochoru/items/f4318654b188369830e3)
- [java.util.loggingの使い方 - Qiita](https://qiita.com/Qui/items/40077ce9e33738dd3914)