Spring is resetting my logging configuration - how

Question

I have a Spring Batch job that is responsible for processing incoming customer files. One of the requirements is that logging is done to separate log files per job run (by customer).

In my application's main, I process command line arguments and then dynamically create my FileAppender from there.

My logback.xml:

<configuration>
    <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="Console" />
    </root>
</configuration>

My code adding the appender:

    private static void setupFileAppender() {
        String logDir = fetchLogDir();
        LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
        String datePortion = LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyyMMddHHmmss"));

        FileAppender<ILoggingEvent> fileAppender = new FileAppender<>();
        fileAppender.setContext(loggerContext);
        fileAppender.setName("File");
        fileAppender.setFile(logDir + baseFileName + "-" + datePortion + ".log");
        fileAppender.setAppend(true);

        PatternLayoutEncoder encoder = new PatternLayoutEncoder();
        encoder.setContext(loggerContext);
        encoder.setPattern("%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n");
        encoder.start();

        fileAppender.setEncoder(encoder);
        fileAppender.start();

        Logger rootLogger = loggerContext.getLogger("root");
        rootLogger.addAppender(fileAppender);

        log.info("Logging configured.");
    }

Any log statements executed from my main (or calls from it) log to file as expected. I can drill down in debug mode and see that I have two appenders on the root logger - the "Console" and "File" appenders from the two configurations. However, once I run the SpringApplication.run command, the FileAppender disappears.

I stepped through the SpringApplicaton.run(...) method and what I've found is that Spring is resetting my logging configuration and reloading it from logback.xml.

From SpringApplication:

try {
    // Create and configure the environment
    ConfigurableEnvironment environment = getOrCreateEnvironment();
    configureEnvironment(environment, args);
    for (SpringApplicationRunListener runListener : runListeners) {
        runListener.environmentPrepared(environment);
    }

    ...

From EventPublishingRunListener:

@Override
public void environmentPrepared(ConfigurableEnvironment environment) {
    publishEvent(new ApplicationEnvironmentPreparedEvent(this.application, this.args,
        environment));
}

private void publishEvent(SpringApplicationEvent event) {
    this.multicaster.multicastEvent(event);
}

A couple of calls later, then LoggingApplicationListener:

@Override
public void onApplicationEvent(ApplicationEvent event) {
    if (event instanceof ApplicationStartedEvent) {
        onApplicationStartedEvent((ApplicationStartedEvent) event);
    }
    else if (event instanceof ApplicationEnvironmentPreparedEvent) {
        onApplicationPreparedEvent((ApplicationEnvironmentPreparedEvent) event);
    }
}

private void onApplicationPreparedEvent(ApplicationEnvironmentPreparedEvent event) {
    if (this.loggingSystem == null) {
        this.loggingSystem = LoggingSystem.get(event.getSpringApplication()
            .getClassLoader());
    }
    initialize(event.getEnvironment(), event.getSpringApplication().getClassLoader());
}

protected void initialize(ConfigurableEnvironment environment, ClassLoader classLoader) {
    if (System.getProperty(PID_KEY) == null) {
        System.setProperty(PID_KEY, new ApplicationPid().toString());
    }
    initializeEarlyLoggingLevel(environment);
    initializeSystem(environment, this.loggingSystem);
    initializeFinalLoggingLevels(environment, this.loggingSystem);
}

private void initializeSystem(ConfigurableEnvironment environment,
        LoggingSystem system) {
    LogFile logFile = LogFile.get(environment);
    String logConfig = environment.getProperty(CONFIG_PROPERTY);
    if (StringUtils.hasLength(logConfig)) {
        try {
            ResourceUtils.getURL(logConfig).openStream().close();
            system.initialize(logConfig, logFile);
        }
        catch (Exception ex) {
            this.logger.warn("Logging environment value '" + logConfig
                + "' cannot be opened and will be ignored "
                + "(using default location instead)");
            system.initialize(null, logFile);
        }
    }
    else {
        system.initialize(null, logFile);
    }
}

In LogbackLoggingSystem (and AbstractLoggingSystem):

@Override
public void initialize(String configLocation, LogFile logFile) {
    getLogger(null).getLoggerContext().getTurboFilterList().remove(FILTER);
    super.initialize(configLocation, logFile);
}

@Override
public void initialize(String configLocation, LogFile logFile) {
    if (StringUtils.hasLength(configLocation)) {
        // Load a specific configuration
        configLocation = SystemPropertyUtils.resolvePlaceholders(configLocation);
        loadConfiguration(configLocation, logFile);
    }
    else {
        String selfInitializationConfig = getSelfInitializationConfig();
        if (selfInitializationConfig == null) {
            // No self initialization has occurred, use defaults
            loadDefaults(logFile);
        }
        else if (logFile != null) {
            // Self initialization has occurred but the file has changed, reload
            loadConfiguration(selfInitializationConfig, logFile);
        }
        else {
            reinitialize();
        }
    }
}

The last else is hit above, and reinitialize() is called:

@Override
protected void reinitialize() {
    getLoggerContext().reset();
    loadConfiguration(getSelfInitializationConfig(), null);
}

The call to reset on the context is what resets everything. The thing is, that digging into the loadConfiguration method also calls the reset method the logging context.

Any ideas on how to get around Spring resetting my logging configuration?

FYI, I'm using 4.1.4.RELEASE version of Spring.

Answer 1

It sounds like deferring your customisation of the logging configuration until after LoggingApplicationListener has run should work.

LoggingApplicationListener performs its initialisation in response to an ApplicationEnvironmentPreparedEvent and has an order of Ordered.HIGHEST_PRECEDENCE + 11. To prevent your custom configuration from being overridden, you could encapsulate your customisation logic in a SmartApplicationListener that responds to the same event but with a lower order so it runs after LoggingApplicationListener:

public class CustomLoggingConfigurationApplicationListener implements
    SmartApplicationListener {

    @Override
    public void onApplicationEvent(ApplicationEvent event) {    
        // Customise the logging configuration
    }   

    @Override
    public int getOrder() {
        return Ordered.HIGHEST_PRECEDENCE + 12;
    }

    @Override
    public boolean supportsEventType(Class<? extends ApplicationEvent> eventType) {
        return ApplicationEnvironmentPreparedEvent.class.isAssignableFrom(eventType);
    }

    @Override
    public boolean supportsSourceType(Class<?> sourceType) {
        return true;
    }

}

You can create the listener and register it in your application's main method:

@SpringBootApplication
public class Application {

    public static void main(String[] args) {
        new SpringApplicationBuilder(Application.class)
                .listeners(new CustomLoggingConfigurationApplicationListener())
                .run(args);
    }
}