[JAVA] What to do if the log using JUL is no longer output to the app log after deploying the Spring Boot app to Tomcat as a war

Due to various reasons, the Spring Boot application that was running on the embedded Tomcat has been turned into a war and deployed to the Tomcat server. However, at that time java.util.logging (below There was a problem that the log output using the JUL) logger is no longer output to the app log, but instead is output to the Tomcat log file (catalina.log).

A note about the cause, how to deal with it, and what you have learned.

environment

OS

Windows 10 (64bit)

Java

openjdk 11.0.2

Tomcat Server

9.0.19

Spring Boot

2.1.4

State when running with embedded Tomcat

Source code

Project structure

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

This is just for verification, and I don't think that different loggers will be mixed in one class in an actual application. Actually, it is assumed that the third-party library used is outputting logs using 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>

Execution result

After booting with bootRun, send a GET request to http: // localhost: 8080 / hello.

Console output

[INFO ] s.j.ExecutableJarApplication - Hello JUL Logger!!
[INFO ] s.j.ExecutableJarApplication - Hello SLF4J Logger!!

Both loggers are outputting without problems.

When converted to War and deployed to Tomcat

Source code

Project structure

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

Other than the changes required for War conversion (log output, etc.), they remain as they are.

logback.xml is unchanged.

Execution result

Deploy to Tomcat and send a GET request to http: // localhost: 8080 / sample / hello.

Tomcat console output

24-Apr-2019 22:15:57.041 Information[http-nio-8080-exec-3] sample.jul.WarApplication.hello Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!

Although it is output, the format of JUL is different from the one specified in logback.xml.

Furthermore, if you look at the Tomcat log catalina.log,

catalina.log

24-Apr-2019 22:15:57.041 Information[http-nio-8080-exec-3] sample.jul.WarApplication.hello Hello JUL Logger!!

It is being output.

What's going on

JUL and SLF4J bridge

SLF4J has a function to bridge the contents output to the JUL logger to the logger on the SLF4J side.

A mechanism called a JUL handler is used for this.

JUL loggers have a handler inside (in the class, Handler /logging/Handler.html)). The log information output to the logger is passed to this handler, and the actual log output processing is performed by the handler.

For example, ConsoleHandler outputs logs to the console as its name suggests. To do. On the other hand, FileHandler outputs the log to a file.

The jul-to-slf4j.jar provided by SLF4J provides a" handler that delegates output to the SLF4J logger. " By registering this in the JUL root logger, the log information output to the JUL logger will also be passed to the SLF4J logger.

In fact, the bridge class in jul-to-slf4j.jar looks like this:

SLF4JBridgeHandler.java

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

If you run the ʻinstall ()method, you'll see that you're getting the root logger fromLogManager and adding SLF4JBridgeHandler`.

Bridge conditions

When using SLF4J with Spring Boot, this SLF4JBridgeHandler.install () method is executed at startup.

Specifically, it is done in a class called Slf4JLoggingSystem, and the implementation is as follows.

Slf4JLoggingSystem.java

    private void configureJdkLoggingBridgeHandler() {
        try {
            if (isBridgeJulIntoSlf4j()) {
                removeJdkLoggingBridgeHandler();
                SLF4JBridgeHandler.install(); //★ Register the bridge here
            }
        }
        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);
    }

There are various conditions for calling ʻinstall (), but if you look at the last ʻisJulUsingASingleConsoleHandlerAtMost (), you can see that the following ** one of ** conditions must be met. ..

--The handler registered in the root logger is 0 (handler is not registered) --Only ConsoleHandler is registered as a handler (JUL default state)

Handler that Tomcat registers by default

Tomcat uses JUL for log output (strictly speaking, it contains its own extension, but details will be described later).

The default JUL configuration file for Tomcat is located in $ {CATALINA_HOME} /conf/logging.properties. And the handler of the root logger is set as follows.

logging.properties

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

Two handlers, file output and console output, are registered. (This 1catalina.org.apache.juli.AsyncFileHandler is the handler that outputs catalina.log)

In other words, in the application deployed on Tomcat, two handlers are registered by default in the root logger that can be obtained by LogManager.getLogManager (). GetLogger ("") .

Then, the previous "conditions for registering the SLF4J bridge with Spring Boot" will not be satisfied.

As a result, the SLF4J bridge was not registered and Tomcat's default settings (catalina.log and output to the console) were applied to log output via JUL.

The atmosphere is like ↓.

Forcibly register the bridge as a trial

You can forcibly register the bridge because it is not registered because it does not meet the conditions set by 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(); //★ Forcibly register the bridge
        return builder.sources(WarApplication.class);
    }

    ...
}

Execution result

24-Apr-2019 22:59:23.405 Information[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!!

It is now output in the format specified in logback.xml. However, the Tomcat default settings are still valid.

If you show the same atmosphere as before, it looks like ↓.

Since I just added a bridge, the log output is duplicated between the output on the Tomcat side and the output on the application side.

Workaround

Delete the root logger handler

python

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

    ...
}

Under the conditions of Spring Boot, if there is no handler in the root logger, the bridge will be registered. Also, if the handler that Tomcat defaults remains, the log output will be duplicated.

So if you remove all the handlers from the root logger before booting, you should be in the same state as when you were running on the embedded Tomcat.

If you deploy this and check the operation, it will be as follows.

Tomcat console output

[INFO ] s.j.WarApplication - Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!

There is no output of Tomcat default setting, only log output by SLF4J set in the application. Of course, it is no longer output to catalina.log.

The image looks like ↓.

Is it okay to rewrite the root logger settings?

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

Looking at this implementation, LogManager is getting via the static method. This means that the instance of LogManager seems to be a singleton.

Looking at the implementation of LogManager as a trial, it is as follows.

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

An instance of LogManager (manager) is stored in a static final field and is a singleton. And the root logger is declared as an instance field of that LogManager.

LogManager is included in the standard API and is loaded by the bootstrap class loader. This means that an instance of LogManager will be shared on the JVM.

Since there is only one JVM running Tomcat, all LogManagers accessed from each web application deployed on it will refer to the same instance.

Then, if one deployed app changes the state of the root logger, it seems that it will affect other deployed apps and even Tomcat itself.

I'm worried whether it's okay to delete all the handlers of the root logger.

Tomcat separates logger management by class loader

The default implementation of JUL would cause one root logger to be shared within the JVM, which could lead to the problems mentioned above.

Therefore, Tomcat provides its own LogManager that can manage loggers separately for each class loader, and replaces the default implementation.

In other words, the atmosphere is such that you can do something like ↓.

The handling of JUL in Tomcat is explained in the official documentation.

Apache Tomcat 9 (9.0.19) - Logging in Tomcat

How to replace the LogManager implementation

The LogManager implementation itself exists in the standard library. However, how to replace the implementation is that LogManager itself has a mechanism for replacing the implementation.

Looking at the implementation of the instantiation part of LogManager, it looks like this:

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;

            }
        });
    }

Initializing an instance of manager with the static initializer.

At this time, it is confirmed whether the system property java.util.logging.manager is specified. If it is specified, the class specified there is loaded and the created instance is assigned to manager.

For the time being, in the [Javadoc] of LogManager (https://docs.oracle.com/javase/jp/11/docs/api/java.logging/java/util/logging/LogManager.html)," LogManager class is , It is placed using the java.util.logging.manager system property at startup." [^ 1].

[^ 1]: I don't know who this explanation is

If you look at the Tomcat startup script, you can see that it is certainly specified as follows.

catalina.bat

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

Empty handler in config file

By the way, Tomcat allows you to place the JUL configuration file (logging.properties) for each Web application you deploy.

So you don't even have to empty the root logger in your implementation if you do the following:

Project structure

|-build.gradle
`-src/main/
  |-java/
  | `-sample/jul/
  |   `-WarApplication.java
  `-resources/
    |-logging.properties ★ Added
    `-logback.xml

logging.properties

.handlers=

The content is to empty the handler for the root logger.

Deploy and check the operation.

Tomcat console output

[INFO ] s.j.WarApplication - Hello JUL Logger!!
[INFO ] s.j.WarApplication - Hello SLF4J Logger!!

Atmosphere that seems to be working well.

reference

-How jul-to-slf4j works-- Qiita -How to use java.util.logging --Qiita