register custom log appender in spring boot starter

Question

I'm using Spring Boot 1.5.4 and I'm trying to write a starter that would include a custom log appender for any application using it. This is how I register it :

@Override
synchronized public void onApplicationEvent(ContextRefreshedEvent contextRefreshedEvent) {
    if (!addedCustomAppender && metricProperties.isEnabled()) {
        //Add log appender for Monitoring
        EventsPublisher eventsPublisher = contextRefreshedEvent.getApplicationContext().getBean(EventsPublisher.class);
        final Appender<ILoggingEvent> newAppender = new CustomLogbackAppender(eventsPublisher);
        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        final Logger root = context.getLogger("ROOT");
        newAppender.setName("Custom Appender");
        newAppender.setContext(context);
        newAppender.start();
        root.addAppender(newAppender);
        addedCustomAppender = true;
    }
}

This gets called, and I can see ROOT logger having the appender. It's actually working for a couple of seconds during application startup.

But very quickly, later during the application startup, an ApplicationEnvironmentPreparedEvent gets fired, which triggers a kind of re-initialization in LoggingApplicationListener.

This happens right after I see in the logs :

INFO 15888 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase -2147482648

in LogbackLoggingSystem, I can see a call to stopAndReset method, which calls recursiveReset method on Loggers. After that, Spring default config gets loaded, and my custom appender is not there anymore.

How can I avoid this to happen, so that my custom appender gets some logs as early as possible and stays attached to ROOT logger ?

or at least how can I register my appender after everything has been initialized ? (in that case, I guess I would miss some logs, so it's not my target solution)

Thanks !

Answer 1

Spring's LoggingApplicationListener is ....

• Configured with Ordered.HIGHEST_PRECEDENCE + 20
• Bound to the following event types: ApplicationStartingEvent.class, ApplicationEnvironmentPreparedEvent.class, ApplicationPreparedEvent.class, ContextClosedEvent.class, ApplicationFailedEvent.class

So, LoggingApplicationListener is binding to (i.e. responding to) the same application event as your listener (ContextRefreshedEvent) and since it is running with such a high precedence (Ordered.HIGHEST_PRECEDENCE + 20) it is superceding your listener by running after it.

You'll need to change the precedence of your listener in order to "stay attached to ROOT logger" and bind to a different event in order to "get some logs as early as possible".

Here's an example implementation:

public class LoggingConfigurationApplicationListener implements GenericApplicationListener {
    private static final Logger logger = LoggerFactory.getLogger(LoggingConfigurer.class);

    private boolean addedCustomAppender;

    @Override
    public void onApplicationEvent(ApplicationEvent event) {
        if (!addedCustomAppender && metricProperties.isEnabled()) {
            ApplicationPreparedEvent applicationEvent = (ApplicationPreparedEvent) event;
            EventsPublisher eventPublisher = applicationEvent.getApplicationContext().getBean(EventsPublisher.class);
            //Add log appender for Monitoring
            final Appender<ILoggingEvent> newAppender = new CustomLogbackAppender(eventPublisher);
            LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
            final ch.qos.logback.classic.Logger root = context.getLogger("ROOT");
            newAppender.setName("Custom Appender");
            newAppender.setContext(context);
            newAppender.start();
            root.addAppender(newAppender);
            logger.info("Added custom log appender");
            addedCustomAppender = true;
        }
    }

    @Override
    public int getOrder() {
        // this must be higher than LoggingApplicationListener.DEFAULT_ORDER
        return Ordered.HIGHEST_PRECEDENCE + 21;
    }

    @Override
    public boolean supportsEventType(ResolvableType eventType) {
        // this is the earliest 'event type' which is capable of exposing the application context
        return ApplicationPreparedEvent.class.isAssignableFrom(eventType.getRawClass());
    }

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

You associate this listener with your Spring Boot application as follows:

@SpringBootApplication
public class Application {

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

With this implementation you'll reconfigure the LoggerContext early (when the SpringApplication is starting up and all bean definitions have been loaded) and your changes will not be overriden by Spring's LoggingApplicationListener.

Here are some example logs with the above listener in place, these show (a) the custom appender being added and (b) that the custom appender is still present after the applicaiotn has started:

2017-08-22 09:25:01|restartedMain|INFO |c.s.s.logging.LoggingConfigurer|Added custom log appender
2017-08-22 09:25:01|restartedMain|INFO |c.s.springboot.Application|Starting Application on ... with PID 92710 ...
2017-08-22 09:25:01|restartedMain|INFO |c.s.springboot.Application|No active profile set, falling back to default profiles: default
2017-08-22 09:25:07|restartedMain|INFO |o.a.catalina.core.StandardService|Starting service [Tomcat]
2017-08-22 09:25:07|restartedMain|INFO |o.a.catalina.core.StandardEngine|Starting Servlet Engine: Apache Tomcat/8.5.16
2017-08-22 09:25:07|localhost-startStop-1|INFO |o.a.c.c.C.[.[.[/spring-boot]|Initializing Spring embedded WebApplicationContext
2017-08-22 09:25:09|Thread-6|INFO |c.s.s.logging.LoggingVerifier|Custom appender is present
2017-08-22 09:25:10|Thread-6|INFO |c.s.s.logging.LoggingVerifier|Custom appender is present