Spring Boot なぜ Tomcat のログをアプリケーションから管理できるのか?

疑問点

Tomcatにwarをデプロイする方式では、Tomcatのログはconf/logging.properties で設定し、アプリケーションからはTomcatのログ設定を変更することができない
参考 tomcat ロギング リファレンス

しかし組み込みTomcatを利用する方式では、アプリケーションからTomcatに関するログの設定を変更することができ、アプリケーションのログと同じようにTomcatのログが出力される。

例えば以下のログでは、Spring Frameworkに混じってTomcatのログも出力されている。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.0.2.RELEASE)

2018-05-31 20:14:14.158  INFO 7188 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on kimura-pc with PID 7188 (C:\Users\pbreh_000\Desktop\study\demo\target\classes started by pbreh_000 in C:\Users\pbreh_000\Desktop\study\demo)
2018-05-31 20:14:14.158  INFO 7188 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-05-31 20:14:14.205  INFO 7188 --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@6b419da: startup date [Thu May 31 20:14:14 JST 2018]; root of context hierarchy
2018-05-31 20:14:15.360  INFO 7188 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2018-05-31 20:14:15.375  INFO 7188 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2018-05-31 20:14:15.391  INFO 7188 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet Engine: Apache Tomcat/8.5.31

warをデプロイするときと、組み込みTomcatで、どういう違いがあるのか?

結論

  • warをデプロイするときは、アプリケーションからTomcatのログを制御できない
  • 組み込みTomcatのときは、アプリケーションからTomcatのログを制御できる

理由

以下の話を読む前の前提知識。ライブラリで実装しているログをアプリケーションから設定したいときは、アダプタ用のjar(log4j-over-slf4j や jul-to-slf4j )に、実行時に差し替える必要がある。
参考 Java ログ出力パターン

Tomcatの内部ロガー

リファレンスによると

  • Tomcatは JULI という独自ロガーの実装を持っている
  • JULI は Apache Commons Logging をforkしてパッケージ名を変えている
  • JULI は 実装クラスにjava.util.loggingを使うようにハードコードされている
  • なぜ上記のようになっているかというと、java.util.logging はデフォルトだと VMごとにしか設定が切り替えられないため、独自のLogManager(ClassLoaderLogManager)によってクラスローダごとに設定を読み込めるようにしたいから

Tomcatにwarをデプロイするとき

catalina.shを利用したときの起動クラスは org.apache.catalina.startup.Bootstrap

Tomcatのクラスローダはwarごとにライブラリを管理できるように階層化されている。
参考 Class Loader HOW-TO

  Bootstrap
          |
       System
          |
       Common
       /     \
  Webapp1   Webapp2 ...

親のクラスローダ(複数の場合あり)が要求されたクラスやリソースを見つけられなかった場合だけ、自分のリポジトリを見にいくことになる。

例えば、Tomcatのログをアプリケーションからコントロールするためにアダプタを設定しようとしてwarに jul-to-slf4j.jar を含めた場合でも、Tomcatのクラスを読み込んでいるクラスローダ(Common)から、WEBアプリケーションのクラスは参照できない。そのため、ログ実装をアプリケーションから差し替えることができない

組み込みTomcatとして使うとき

組み込みTomcatの起動クラスは org.apache.catalina.startup.Tomcat

org.apache.catalina.startup.Bootstrap で起動したときとは違い、Catalina系のクラスとWEBアプリケーションのクラスが同一クラスローダに読み込まれる

そのため jul-to-slf4j.jar をクラスパスに通せば、ロガーの差し替えができる

検証する

pom.xmlを用意する。

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <packaging>jar</packaging>

    <groupId>example.com</groupId>
    <artifactId>embedded-tomcat-logging</artifactId>
    <version>1.0-SNAPSHOT</version>

    <dependencies>
        <dependency>
            <groupId>org.apache.tomcat.embed</groupId>
            <artifactId>tomcat-embed-core</artifactId>
            <version>8.5.23</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-core</artifactId>
            <version>1.2.3</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.3</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jul-to-slf4j</artifactId>
            <version>1.7.25</version>
        </dependency>
    </dependencies>

    <properties>
        <java.version>1.8</java.version>
        <maven.compiler.target>${java.version}</maven.compiler.target>
        <maven.compiler.source>${java.version}</maven.compiler.source>
    </properties>
</project>

logback.xmlを用意する。

<configuration>

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%c %d [%thread] %-5level - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>

</configuration>

組み込みTomcatを起動する。

public class Main {
    public static void main(String[] args) throws LifecycleException, InterruptedException {
        SLF4JBridgeHandler.removeHandlersForRootLogger();
        SLF4JBridgeHandler.install();
        Tomcat tomcat = new Tomcat();
        tomcat.setPort(8080);
        Context ctx = tomcat.addContext("/sample", new File(".").getAbsolutePath());
        Logger logger = LoggerFactory.getLogger(Main.class);
        logger.info("start...");

        Tomcat.addServlet(ctx, "hello", new HttpServlet() {
            protected void service(HttpServletRequest req, HttpServletResponse resp)
                    throws ServletException, IOException {
                Writer w = resp.getWriter();
                w.write("Hello, World!");
                w.flush();
            }
        });
        ctx.addServletMappingDecoded("/*", "hello");

        tomcat.start();
        tomcat.getServer().await();
    }
}

コンソール出力を見ると、Logbackに実装が切り替えられている。

org.apache.coyote.http11.Http11NioProtocol 2018-05-31 20:37:47,682 [main] INFO  ---- Initializing ProtocolHandler ["http-nio-8080"]
org.apache.tomcat.util.net.NioSelectorPool 2018-05-31 20:37:47,745 [main] INFO  ---- Using a shared selector for servlet write/read
org.apache.catalina.core.StandardService 2018-05-31 20:37:47,747 [main] INFO  ---- Starting service [Tomcat]
org.apache.catalina.core.StandardEngine 2018-05-31 20:37:47,748 [main] INFO  ---- Starting Servlet Engine: Apache Tomcat/8.5.23
org.apache.coyote.http11.Http11NioProtocol 2018-05-31 20:37:47,889 [main] INFO  ---- Starting ProtocolHandler ["http-nio-8080"]

実際にクラスローダを確認してみると、Tomcat関連のクラスとWEBアプリケーションのクラスが同一のクラスローダに読み込まれている。

f:id:kimulla:20191201213306p:plain

Spring Bootの場合

動作確認バージョンは以下。

 <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.0.2.RELEASE</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

Spring Bootはもう少し複雑なことをしていて、Java標準のクラスローダで spring boot loader classes を読み込み、そこから依存する各jarをロードしている。

example.jar
 |
 +-META-INF
 |  +-MANIFEST.MF
 +-org
 |  +-springframework
 |     +-boot
 |        +-loader
 |           +-<spring boot loader classes>
 +-BOOT-INF
    +-classes
    |  +-mycompany
    |     +-project
    |        +-YourClasses.class
    +-lib
       +-dependency1.jar
       +-dependency2.jar

参考 E.1.1 The Executable Jar File Structure

まあどっちにしろ、Tomcat関連のクラスからWEBアプリケーションのクラスが参照できているので同じことかなと。

f:id:kimulla:20191201213323p:plain

f:id:kimulla:20191201213337p:plain

SpringBootの組み込みTomcatの注意点

「Tomcat関連のログはアプリケーションのログ設定で一元管理できる」といきたいところだが、Tomcatのアクセスログは上記のログでは出力されない。Tomcatのアクセスログは独自のValveで実装されているため、ログ部分をアダプタで差し替えできないから。

Access logging is a related but different feature, which is implemented as a Valve. It uses self-contained logic to write its log files. 参考 Logging in Tomcat

ただし、Spring Boot だとプロパティで設定できる。
参考 Appendix A. Common application properties

server.tomcat.accesslog.buffered=true # Whether to buffer output such that it is flushed only periodically.
server.tomcat.accesslog.directory=logs # Directory in which log files are created. Can be absolute or relative to the Tomcat base dir.
server.tomcat.accesslog.enabled=false # Enable access log.
server.tomcat.accesslog.file-date-format=.yyyy-MM-dd # Date format to place in the log file name.
server.tomcat.accesslog.pattern=common # Format pattern for access logs.
server.tomcat.accesslog.prefix=access_log # Log file name prefix.
server.tomcat.accesslog.rename-on-rotate=false # Whether to defer inclusion of the date stamp in the file name until rotate time.
server.tomcat.accesslog.request-attributes-enabled=false # Set request attributes for the IP address, Hostname, protocol, and port used for the request.
server.tomcat.accesslog.rotate=true # Whether to enable access log rotation.
server.tomcat.accesslog.suffix=.log # Log file name suffix.
...