LoginSignup
12
12

More than 3 years have passed since last update.

@opengl-8080inTIS株式会社

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

Last updated at Posted at 2019-04-24

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

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

環境

OS

Windows 10 (64bit)

Java

openjdk 11.0.2

Tomcat Server

9.0.19

Spring Boot

2.1.4

組み込み Tomcat で動かしていたときの様子

ソースコード

プロジェクト構成
|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-ExecutableJarApplication.java
  `-resources/
    `-logback.xml
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'
}
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 を使ってログ出力しているようなケースを想定している。

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 リクエストを送信する。

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

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

War 化して Tomcat にデプロイした場合

ソースコード

プロジェクト構成
|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-WarApplication.java
  `-resources/
    `-logback.xml
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'
}
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 リクエストを送信する。

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 を見ると、

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）。
ロガーに出力されたログ情報は、このハンドラに渡され、実際のログ出力処理はハンドラが行うようになっている。

たとえば、 ConsoleHandler はその名前の通りコンソールにログを出力する。
一方、 FileHandler はファイルにログを出力する。

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

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

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 というクラスで行われており、実装は次のようになっている。

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 に存在する。
そして、ルートロガーのハンドラは次のように設定されている。

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

試しにブリッジを無理やり登録してみる

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

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);
    }

    ...
}
実行結果
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

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

対処方法

ルートロガーのハンドラを消す

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 で実行していたときと同じ状態になるはず。

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

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

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

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

jul.jpg

ルートロガーの設定を書き換えて大丈夫？

        Logger rootLogger = LogManager.getLogManager().getLogger("");
        for (Handler handler : rootLogger.getHandlers()) {
            rootLogger.removeHandler(handler);
        }

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

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

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

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

Apache Tomcat 9 (9.0.19) - Logging in Tomcat

LogManager の実装を差し替える方法

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

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

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 には「LogManagerクラスは、起動時に java.util.logging.manager システム・プロパティを使用して配置されます。」と説明が書かれている1。

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

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

設定ファイルでハンドラを空にする

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

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

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

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

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

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

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

参考

  1. この説明で誰が分かんねん ↩

12
12
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
12
12