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 ↓.

jul.jpg

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 ↓.

jul.jpg

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 ↓.

jul.jpg

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 ↓.

jul.jpg

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

Recommended Posts

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
What to do if the background image is not applied after deployment
Deploy the WEB application by Spring Boot to Tomcat server as WAR
[Rails / Docker] What to do if access is denied by the browser (localhost: 3000) after adding a gem
What to do if the server tomcat dies
[Swift] What to do if the app icon is set but not reflected
What to do if the update does not take effect after deploying Rails AWS
[Maven] What to do if you are asked to incorporate a jar that is not in the remote repository into the war
Output embedded Tomcat access log to standard output with Spring Boot
What do you need after all to create a web application using java? Explain the mechanism and what is necessary for learning
[Spring Boot] What to do if an HttpMediaTypeNotAcceptableException occurs on an endpoint for which produces is set
What to do if the app is not created with the latest Rails version installed when rails new
[Ubuntu 20.04] What to do if the external monitor is not recognized
What to do if Cloud9 is full in the Rails tutorial
What to do if the Eclipse Maven dependency Jar is wrong
What to do if the image posted by refile disappears after setting a 404 error page in Rails
What to do if Operation not permitted is displayed when you execute a command in the terminal
What to do if you get the error Too long with no output (exceeded 10m0s) on CircleCI
What to do if tomcat process remains when tomcat is stopped in eclipse
Steps to create a simple camel app using Apache Camel Spring Boot starters
After using Android Studio 3, Java application dependencies can no longer be resolved, so what to do about it
What is a Spring Boot .original file?
What to do if you get a SQLite3 :: BusyException: database is locked error
Androd: What to do about "The Realm is already in a write transaction in"
[Solution] What to do if you get a Docker error'ERROR: Cannot connect to the Docker daemon at unix: ///var/run/docker.sock. Is the docker daemon running?'
What to do if you get the warning "Uniqueness validator will no longer enforce case sensitive comparison in Rails 6.1." in Rails 6.0
From building an AWS cloud environment to deploying a Spring Boot app (for beginners)
What to do if you can't find your API key after deploying to Rails heroku
What to do if the breakpoint is shaded and does not stop during debugging