SIerだけど技術やりたいブログ

5年目のSIerのブログです

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

Tomcatにwarをデプロイして運用することに慣れ親しんでいる自分は

Tomcatのログは conf/logging.properties で設定する
Apache Tomcat 8 (8.5.23) - Logging in Tomcat

と思っていましたが、Spring Bootから制御できています。

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

2017-10-22 18:59:44.026  INFO 11864 --- [           main] c.example.embedded.EmbeddedApplication   : Starting EmbeddedApplication on kimura-pc with PID 11864 (C:\Users\pbreh_000\Desktop\study\log\embedded\target\classes started by pbreh_000 in C:\Users\pbreh_000\Desktop\study\log\embedded)
2017-10-22 18:59:44.029  INFO 11864 --- [           main] c.example.embedded.EmbeddedApplication   : No active profile set, falling back to default profiles: default
2017-10-22 18:59:44.114  INFO 11864 --- [           main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@33cb5951: startup date [Sun Oct 22 18:59:44 JST 2017]; root of context hierarchy
2017-10-22 18:59:45.077  INFO 11864 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 8080 (http)
2017-10-22 18:59:45.086  INFO 11864 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2017-10-22 18:59:45.087  INFO 11864 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet Engine: Apache Tomcat/8.5.23

※ 最終行にTomcatのログが出力されている


どういう事なんでしょうか?

結論

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

詳細

以下の話を読む際に前提となる内容です。
kimulla.hatenablog.com

Tomcatの内部ロガー

リファレンスによると
Apache Tomcat 8 (8.5.23) - Logging in 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ごとにライブラリを管理できるように階層化されている。
Apache Tomcat 8 (8.5.23) - Class Loader HOW-TO

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

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

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に実装が切り替えられている。

Main 2017-10-22 20:04:33,884 [main] INFO  - start...
org.apache.coyote.http11.Http11NioProtocol 2017-10-22 20:04:34,066 [main] INFO  - Initializing ProtocolHandler ["http-nio-8080"]
org.apache.tomcat.util.net.NioSelectorPool 2017-10-22 20:04:34,124 [main] INFO  - Using a shared selector for servlet write/read
org.apache.catalina.core.StandardService 2017-10-22 20:04:34,126 [main] INFO  - Starting service [Tomcat]
org.apache.catalina.core.StandardEngine 2017-10-22 20:04:34,126 [main] INFO  - Starting Servlet Engine: Apache Tomcat/8.5.23
org.apache.coyote.http11.Http11NioProtocol 2017-10-22 20:04:34,246 [main] INFO  - Starting ProtocolHandler ["http-nio-8080"]

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

f:id:kimulla:20171022200154p:plain

Spring Boot

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

Appendix E. The executable jar format

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

f:id:kimulla:20171022220026p:plain

f:id:kimulla:20171022221017p:plain

注意

「よし、これでTomcat関連のログはアプリケーションのログ設定で一元管理できるようになった」といきたいところだけど、アクセスログは上記のログでは出力されない。

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


Spring Boot だとプロパティで設定できるようす。
Appendix A. Common application properties

server.tomcat.accesslog.directory=logs # Directory in which log files are created. Can be relative to the tomcat base dir or absolute.
server.tomcat.accesslog.enabled=false # Enable access log.
server.tomcat.accesslog.file-date-format=.yyyy-MM-dd # Date format to place in log file name.
server.tomcat.accesslog.pattern=common # Format pattern for access logs.
server.tomcat.accesslog.prefix=access_log # Log file name prefix.
...