Excess LoggerContext reinitialization

[ogmios-voice]

Logger is updated/reinitialized after application start in SpringApplication.run() > ... > LoggingApplicationListener.initializeSystem() > AbstractLoggingSystem.initialize().

Environment: Tomcat 8.0.26, Gradle 2.7, Spring Boot 1.2.6, Log4j2 2.4 (and Eclipse Mars (4.5.0)).

build.gradle:

buildscript {
    repositories.mavenCentral()
    dependencies.classpath 'org.springframework.boot:spring-boot-gradle-plugin:1.2.6.RELEASE'
}
apply plugin: 'spring-boot'
apply plugin: 'war'
apply plugin: 'eclipse-wtp'
sourceCompatibility = '1.8'
repositories.mavenCentral()
configurations.compile.exclude module : 'spring-boot-starter-logging'
dependencies {
    compile 'org.springframework.boot:spring-boot-starter-log4j2'
    compile 'org.springframework.boot:spring-boot-starter-web'
    compile 'org.apache.logging.log4j:log4j-api:2.4'
    compile 'org.apache.logging.log4j:log4j-core:2.4'
    compile 'org.apache.logging.log4j:log4j-slf4j-impl:2.4'
    compile 'org.apache.logging.log4j:log4j-web:2.4'
}
task wrapper(type: Wrapper) {
    gradleVersion = '2.7'
}
eclipse.classpath {
    containers.remove('org.eclipse.jdt.launching.JRE_CONTAINER')
    containers 'org.eclipse.jdt.launching.JRE_CONTAINER/org.eclipse.jdt.internal.debug.ui.launcher.StandardVMType/JavaSE-1.8'
}
eclipse.wtp.facet.file.withXml { n -> n.asNode().installed.find { it.@facet == 'jst.web' }.@version = '3.1' }

src\main\java\loggertest\Application.java:

package loggertest;

import java.net.URI;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LoggerContext;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.boot.context.embedded.ServletContextInitializer;
import org.springframework.boot.context.web.SpringBootServletInitializer;
import org.springframework.context.ApplicationEvent;
import org.springframework.context.ApplicationListener;
import org.springframework.web.context.WebApplicationContext;

@SpringBootApplication
public class Application {

    public static class Initializer extends SpringBootServletInitializer implements ServletContextInitializer {
        @Override
        protected SpringApplicationBuilder configure(final SpringApplicationBuilder application) {
            LogManager.getLogger(Application.class).debug("configure()");
            return application.sources(Application.class);
        }

        @Override
        protected WebApplicationContext run(final SpringApplication application) {
            application.addListeners(new LoggerContextInfo());
            return super.run(application);
        }
    }

    static class LoggerContextInfo implements ApplicationListener<ApplicationEvent> {
        @Override
        public void onApplicationEvent(final ApplicationEvent event) {
            final LoggerContext ctx = LoggerContext.getContext();
            final URI loc = ctx.getConfigLocation();
            System.err.println(String.format("\nevent = %s\nlogCtx.cfg@%X    = %s\nlogCtx.cfgLoc@%X = %s\n", event.getClass(),
                    ctx.getConfiguration().hashCode(), ctx.getConfiguration(), (loc != null ? loc.hashCode() : 0), loc));
        }
    }

    public static void main(final String[] args) {
        SpringApplication.run(new Class[] { Application.class, Initializer.class }, args);
    }
}

src\main\webapp\WEB-INF\web.xml (see: https://issues.apache.org/jira/browse/LOG4J2-873):

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/web-app_3_1.xsd"
         version="3.1" metadata-complete="false">
    <display-name>dummy</display-name>
</web-app>

src\main\resources\log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO" strict="true">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="MY_LOGGER %-5p %d [%t][%c{1}]: %m%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="org.springframework" level="WARN"/>
        <Logger name="loggertest" level="DEBUG"/>
        <Root level="DEBUG">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Based on the hashcodes, the LoggerContext has been reinitialized:

event = class org.springframework.boot.context.event.ApplicationStartedEvent
logCtx.cfg@2CF69F84    = XmlConfiguration[location=[...]\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\loggertest\WEB-INF\classes\log4j2.xml]

event = class org.springframework.boot.context.event.ApplicationEnvironmentPreparedEvent
logCtx.cfg@68BCA678    = XmlConfiguration[location=[...]\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\loggertest\WEB-INF\classes\log4j2.xml]

While in this example this is not a big issue, I've started the debugging after my log4j2.xml config was replaced with the one from spring-boot-1.2.6.RELEASE.jar:

event = class org.springframework.boot.context.event.ApplicationStartedEvent
logCtx.cfg@710A98B5    = XmlConfiguration[location=[...]\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\[...]\WEB-INF\log4j2.xml]
logCtx.cfgLoc@B88DB767 = file:/[...]/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/[...]/WEB-INF/log4j2.xml

event = class org.springframework.boot.context.event.ApplicationEnvironmentPreparedEvent
logCtx.cfg@4D6AD8AA    = XmlConfiguration[location=jar:file:/[...]/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/[...]/WEB-INF/lib/spring-boot-1.2.6.RELEASE.jar!/org/springframework/boot/logging/log4j2/log4j2.xml]
logCtx.cfgLoc@B88DB767 = file:/[...]/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/[...]/WEB-INF/log4j2.xml

[philwebb]

It sounds like you're hitting the issue described in #2558. There's a brief description of why in #2558 (comment).

Could you try the latest 1.3 milestone and rename your configuration to logback-spring.xml and let me know if that fixes it?

[ogmios-voice]

Obviously logback-spring.xml would not be very helpful as this is log4j2 (still I have tried it). log4j2-spring.xml does not help either: log4j2 initializes itself with org.apache.logging.log4j.core.config.DefaultConfiguration (log: StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.) then spring-boot overwrites this with the config from the renamed config file (WEB-INF\classes\log4j2-spring.xml).

But the reason behind this issue is indeed the same as in your aforementioned #2558 comment.

So if I understand you correctly you would like to achieve a behaviour similar to suspending the Log4jServletContainerInitializer and then initializing the logger from spring-boot. Is this correct?

[philwebb]

Apologies, I missed the fact that you were using log4j2 and a ServletContextInitializer. I guess we either need to stop Log4jServletContainerInitializer getting involved.

Are you directly using any features of log4j-web? Perhaps removing that dependency and using a log4j2-spring.xml will be enough?

[ogmios-voice]

My question on the other hand is whether does spring-boot really need to (re)initialize the logging? From a modularity point of view I would prefer letting the loggers initialize themselves.
(Of course I'm not familiar with the domain model and architectural decisions of spring-boot.)

[lanoxx]

I stumbled across this issue while searching for an answer to the question why spring-boot does not have a dependency management entry for log4j-web, your answers seem to imply, that it is not necessary to have this dependency. But the log4j manual explicitly states, that when running an application in a servlet container such as tomcat one should include the log4j-web dependency. I searched in the Spring boot documentation but could not find any reference to log4j-web. Could someone clarify this?

[philwebb]

@lanoxx I imagine the log4j manual is specifically talking about a classic war deployment inside a servlet container, rather than an embedded servlet container. Generally we prefer going the embedded route which should mean the logging system gets initialized by Spring Boot and the Log4jServletContainerInitializer isn't needed.

[philwebb]

Since #3571 not provides a way to disable our logging system entirely I'm going to close this one. Perhaps there's a better way we could deal with this but we've only got limited time and it seems like a corner case.

[lanoxx]

@philwebb Thanks for clarifying.