Spring-boot: Support alternative logging config file to prevent double configuration

[cemo]

I have noticed that Logback is configured twice. One for default configuration and later Boot is resetting configuration and configuring again. I do not know how this can be achieved without configuring twice but It would be better to configure just once. I know that there are some necessary things have to be done before logging configuration. But this still looks like debatable on my side.

[philwebb]

Which method should I breakpoint to test?

[cemo]

I have logback.xml including a custom appender and seen that it is triggered twice. It is including

<configuration>
   <include resource="org/springframework/boot/logging/logback/base.xml"/>
   <include resource="myconfiguration.xml"/>
</configuration>

I have seen that appender inside my myconfiguration is constructed twice. Is this enough for you? I can provide additional information and a simple example in case of not reproducing behaviour.

[lldata]

I also have this issue. In my setup I have a logback.xml on the classpath, that holds a barebones configuration for bootstrapping spring boot.

My real logback configuration is pointed out in application.properties like this:

logging.config=${config.path}logback-${spring.application.name}.xml

I deploy multiple spring boot applications in a WAS and the logback configuration must be externalized, so I need to pull a couple of tricks.

It works, but I also get a double logback initialization.
When slf4j loads it scans for logback.xml (I think)
Then later when Spring Boot loads it reads the application.properties eventually hits org.springframework.boot.logging.LoggingApplicationListener.initializeSystem(ConfigurableEnvironment, LoggingSystem) which resets and reconfigures logback.

It works, but I have a couple of really annoying quirks:
1) logback scanning seems like it is only picked up on the first logback initialization, so putting scan="true" in my "real" logback-application.xml has no effect.
2) possibly related: it appears that loggers that are started before the logback reload, is not reconfigured to the new log level. I suspect that is because logbacks ReconfigureOnChangeFilter never discovers the change.

[philwebb]

I've dug into this a bit and I think it's going to be very difficult to prevent reinitialization if you use the default logback.xml config file. The first time any logger is accessed logback tries to initialize itself and load the config. I can't see any way to get in before logback and defer initialization until we're ready. We need to trigger reinitialization because system properties (such as PID) might have changed.

I think the easiest fix might be to provide an alternative convention for Spring Boot based applications. Something like logback-spring.xml. That way we can be entirely in control of loading things.

[philwebb]

@cemo @lldata I've updated master to now load logback-spring.xml configurations. Could you try the latest 1.3 SNAPSHOT and let me know if it solves the issues. You'll need to rename your logback.xml file to logback-spring.xml.

[sourcedelica]

Does this also work for Groovy-based logback configurations? I upgraded to Spring 1.3 today after seeing this Github issue, but it still initializes twice. Would I need to rename to logback-spring.groovy? Renaming the file to logback-spring.groovy is not that great of an option because we use this logging module in all of our apps, Spring Boot-based or not. One of the side effects is that, because I have log rolling enabled, when the logging is re-initializes it rolls the logs again, so I get one log file up to the point that Spring Boot kicks in, then it rolls to another log file. That is a drag especially because we limit the number of rolled files to a small number.

What I really want is a way to disable Spring Boot's reinitialization of the logging.

[philwebb]

@sourcedelica I don't think there's an easy way to prevent re-initialization of the logging system if you want to use Spring Boot's logging features (e.g. logging.level properties), however, if you're happy to loose those it should be possible to disable it completely. This probably isn't very easy at the moment but you should be able to remove LoggingApplicationListener from SpringApplication.getListeners() before calling run().

Please open a new issue if you think we need to make it easier to completely disable logging.

[sourcedelica]

That worked great - thanks! I guessing I'm an outlier and most people will want to let Boot configure their logging. I'll keep an eye on this thread and if more people chime in I'll log a bug.

[lldata]

Renaming to logback-spring.xml seems to do the trick.
Reloading logback configuration with the scan property now works.

[fmarot]

For the record, as I stumbled on this problem today, my comment may help others: I also wanted to prevent Spring from initializing the logging (Logback) once again and simply use Logback default to rely on a VM parameter -Dlogback.configurationFile=.omds-logback.xml (because I added Spring boot into an existing application that still has many parts non springified).
In the end I subclassed SpringApplication and removed the listener responsible for (re-)initializing the logging:

@Slf4j
public class OleaSpringApplication extends SpringApplication implements DoNotObfuscate {

    /** Just call the following method but remove any logging configuration done automatically by Spring
     * @see org.springframework.boot.SpringApplication#SpringApplication(Object...) */
    public OleaSpringApplication(Object... sources) {
        super(sources);
        hackToRemoveDoubleLoggingInitialisationDueToSpringBoot();
    }

    private void hackToRemoveDoubleLoggingInitialisationDueToSpringBoot() {
        Set<ApplicationListener<?>> listeners = getListeners();
        Iterator<ApplicationListener<?>> it = listeners.iterator();
        while (it.hasNext()) {
            ApplicationListener<?> listener = it.next();
            if (listener instanceof LoggingApplicationListener) {
                log.info("Removing Spring boot log listener to avoid logging reconfiguration #hack");
                it.remove();
            }
        }
        setListeners(listeners);
    }
}

[wilkinsona]

In the latest 1.4 snapshots, you can run with -Dorg.springframework.boot.logging.LoggingSystem=none to disable Spring Boot's logging system. See https://github.com/spring-projects/spring-boot/commit/bbd7840785747eb89a03d854228d6cb727a40db1 for details.

[JetForMe]

Related to this, once SpringApplication.run() is invoked, logging stops writing my messages. Everything from Spring (and friends) is still written, but my own messages are not (only messages logged before run() is called are output). Also, the formatting is different for my messages vs. Spring’s:

23:03:21.380 [http-nio-2222-exec-2] DEBUG org.springframework.orm.jpa.support.OpenEntityManagerInViewInterceptor - Opening JPA EntityManager in OpenEntityManagerInViewInterceptor

vs.

Dec 29, 2016 11:03:21 PM com.latencyzero.toolcrib.tools.ToolsController allUsers
INFO: tools-service allUsers() invoked: 

[philwebb]

@JetForMe Could you please open a new issue for that one and provide a small sample that shows the problem?

[JetForMe]

I can certainly open a new issue. Giving you a small sample will be challenging.