Spring Boot 2.1 starts the root logger in debug mode until the banner prints?

Question

Here's some output to give an example of what I'm talking about. The debug messages don't come solely from the Aspect4J logger, they come from several other classes as well. I've debugged the application and found that the Root logger is set to DEBUG, then later on set to INFO after the Spring Banner is printed (I don't think the banner specifically has anything to do with it).

I don't have any logging related files on my classpath unless they've been added by a dependency I'm unaware of.

I also tried setting.

# Logging
logging.level.root=INFO
logging.level.org.springframework.web=INFO
logging.level.org.hibernate=INFO

In my application.properties file but that did not help, Spring Boot 2.1 still output everything at DEBUG level until the banner printed. Any idea on how I might prevent the Root logger from coming up as DEBUG instead of INFO at the beginning would be great.

15:34:47.971 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.springframework.boot.logging.AbstractLoggingSystem'
15:34:47.974 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'ch.qos.logback.classic.joran.JoranConfigurator'
15:34:47.976 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'ch.qos.logback.core.joran.JoranConfiguratorBase'
15:34:47.979 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'ch.qos.logback.core.joran.GenericConfigurator'
15:34:47.980 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.springframework.boot.logging.logback.SpringBootJoranConfigurator'
15:34:47.982 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'ch.qos.logback.classic.spi.LoggerContextListener'
15:34:47.985 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'ch.qos.logback.classic.turbo.TurboFilter'
15:34:47.987 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.springframework.boot.logging.logback.LogbackLoggingSystem$1'
15:34:47.988 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.springframework.boot.logging.LoggerConfigurationComparator'
15:34:47.989 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.springframework.boot.logging.AbstractLoggingSystem$LogLevels'
15:34:48.009 [main] DEBUG AspectJ Weaver - [AspectJ] not weaving 'org.slf4j.bridge.SLF4JBridgeHandler'

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.0.1.RELEASE)

2018-11-21 15:34:50.094  INFO 1 --- [           main] c.s.technology.screening.SpringConfig    : Starting SpringConfig on 940e73166080 with PID 1 (/web.jar started by root in /)
2018-11-21 15:34:50.100  INFO 1 --- [           main] c.s.technology.screening.SpringConfig    : No active profile set, falling back to default profiles: default
2018-11-21 15:34:50.420  INFO 1 --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@4e0ae11f: startup date [Wed Nov 21 15:34:50 EST 2018]; root of context hierarchy
2018-11-21 15:34:53.506  INFO 1 --- [           main] AspectJ Weaver                           : [AspectJ] Join point 'method-execution(org.springframework.data.domain.Page com.sasquatch.technology.screening.api.JobController.listJobs(org.springframework.data.domain.Pageable))' in Type 'com.sasquatch.technology.screening.api.JobController' (JobController.java:48) advised by around advice from 'org.springframework.security.access.intercept.aspectj.aspect.AnnotationSecurityAspect' (AnnotationSecurityAspect.aj:70)
2018-11-21 15:34:53.525  INFO 1 --- [           main] AspectJ Weaver                           : [AspectJ] Join point 'method-execution(com.sasquatch.technology.screening.persistence.entities.Job com.sasquatch.technology.screening.api.JobController.addJob(com.sasquatch.technology.screening.persistence.entities.Job))' in Type 'com.sasquatch.technology.screening.api.JobController' (JobController.java:54) advised by around advice from 'org.springframework.security.access.intercept.aspectj.aspect.AnnotationSecurityAspect' (AnnotationSecurityAspect.aj:70)
2018-11-21 15:34:53.620  INFO 1 --- [           main] AspectJ Weaver                           : [AspectJ] Join point 'method-execution(org.springframework.http.ResponseEntity com.sasquatch.technology.screening.api.TestHelperController.resetDatabase())' in Type 'com.sasquatch.technology.screening.api.TestHelperController' (TestHelperController.java:45) advised by around advice from 'org.springframework.transaction.aspectj.AnnotationTransactionAspect' (AbstractTransactionAspect.aj:66)

Answer 1

I was able to trace the source of the problem back to the fact that Spring does not set the logging level until it initializes and runs the implementation class for org.springframework.boot.logging.LoggingSystem. And when Logback boots up it sets the Root logger to DEBUG by default in the ch.qos.logback.classic.LoggerContext class this.root.setLevel(Level.DEBUG).

I added the following code to a static initialization block inside of the class which contains the main() method that boots up the Spring application. The root logger gets fetched (which initializes it to DEBUG), and then cast to a Logback logger. Keep in mind this means this implementation of a fix is tied to the real logging implementation on the classpath. If I were doing all my logging through log4j or apache commons the logger I get from LoggerFactory.getLogger() would be a different type and therefore need a different cast. This cast is necessary because the SLF4J facade does not expose methods to programmatically change the logging level. Once I had a refrence to the root logger, then I just set the level. This level is eventually overridden by Spring, so I'll need to do some more plumbing if I want to automagically keep the Spring settings and my initialization block the same.

@SpringBootApplication
public class SpringConfig {

    static {
        ((ch.qos.logback.classic.Logger) org.slf4j.LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME)).setLevel(Level.INFO);
    }
}

Answer 2

For integration or unit tests, another solution that's perhaps less intrusive is to create a logback-test.xml in src/test/resources:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml" />
    <logger name="org.springframework" level="INFO"/>
</configuration>

Source: https://www.mkyong.com/spring-boot/spring-boot-test-how-to-stop-debug-logs/

This doesn't completely solve the problem asked in the question, but the search engines took me here when searching for a solution for my tests so I expect it might happen to others which is why I'm sharing this info.