behavior

  • code show as below
public class CostTimeSpringApplicationRunListener implements SpringApplicationRunListener {
    private static final Logger log = LoggerFactory.getLogger(CostTimeSpringApplicationRunListener.class);

    public CostTimeSpringApplicationRunListener(SpringApplication sa, String[] args) {
    }

    @Override
    public void starting(ConfigurableBootstrapContext bootstrapContext) {
        System.out.println("1==");
        log.info("11==");
        log.info("cost time -> starting {}", LocalDateTime.now());
        log.info("22==");
        System.out.println("2==");
    }

    @Override
    public void environmentPrepared(ConfigurableBootstrapContext bootstrapContext, ConfigurableEnvironment environment) {
        log.info("cost time -> environmentPrepared {}", LocalDateTime.now());
    }

    ...
}
  • console:
17:53:48.407 [main] INFO com.dou.log.demo2.LogDemo2Application - before run 
1==
2==
2023-01-05T17:56:14.635+08:00  INFO 11080 --- [           main] d.c.CostTimeSpringApplicationRunListener : cost time -> environmentPrepared 2023-01-05T17:56:14.635750900

after debugging

  • the log in starting is created by LogbackLoggingSystem.beforeInitialize() ( loggerContext.getTurboFilterList().add(FILTER) )
  • the log in environmentPrepared is re-processed by LogbackLoggingSystem.initialize() (loggerContext.getTurboFilterList().remove(FILTER) )
  • FILTER:
private static final TurboFilter FILTER = new TurboFilter() {
    @Override
    public FilterReply decide(Marker marker, ch.qos.logback.classic.Logger logger, Level level, String format,
            Object[] params, Throwable t) {
        return FilterReply.DENY;
    }
}

So is it by design? Log output is not supported in starting, because the log is not fully initialized at this time? but:

@SpringBootApplication
public class LogDemo2Application {
    private static final Logger log = LoggerFactory.getLogger(LogDemo2Application.class);
    public static void main(String[] args) {
        log.info("before run ");
        SpringApplication.run(LogDemo2Application.class, args);
        log.info("after run ");
    }
}

The log before the SpringApplication.run method here can be output .... This makes springboot's logging behavior weird。。。

Comment From: wilkinsona

Yes, this is the expected behavior. Logging performed in the main method before any Spring Boot code has been run will use Logback's defaults. During initialization of the logging system, logging is prevented to limit inconsistencies. If you must perform logging during this phase of startup, you can use org.springframework.boot.logging.DeferredLog to do so. Spring Boot does this itself in several places.

Comment From: dousp

Thank you very much for answering my doubts.

Comment From: yiang231

How to use the org.springframework.boot.logging.DeferredLog class to output logs from the SpringApplicationRunListeners.starting ? Can you provide an example?

Comment From: wilkinsona

As suggested above there are many examples in Spring Boot's code. A code search for DeferredLog will find them.

Comment From: yiang231

Thank you for your suggestion! There are indeed many examples in Spring Boot's code that demonstrate the usage of DeferredLog.