LoggingSystem shutdown on application context stop (logback)

[brenuart]

As per Logback documentation (http://logback.qos.ch/manual/configuration.html#stopContext), one should properly stop the logger upon application shutdown.

A typical usage scenario is when using appenders that require proper flush before the virtual machine exists (like a file appender with buffering enabled, or a TCP network connector with a buffer).

It appears that LoggingApplicationListener calls loggingSystem.cleanUp() when the context is closed. But most LoggingSystem implementations provided by SpringBoot only performs some light cleanup tasks but don't actually shutdown the appenders.

My feeling is LogbackLoggingSystem.cleanUP() should properly shutdown the appenders as described in their documentation.

[wilkinsona]

@dsyer has pointed out that completely cleaning things up in cleanUp will be problematic as the logging configuration is scoped to a ClassLoader. For example, if a child context is created and then closed, it'll mess up the logging configuration for the parent. The safest bet is for us to use a shutdown hook, for example Logback's DelayingShutdownHook. This won't help for a long-running JVM where modules that use different ClassLoader's come and go so we may need something more sophisticated.

[brenuart]

The same reasoning applies to the initialisation phase of the LoggingSystem as well: it is bound to ApplicationStartedEvent and ApplicationEnvironmentPreparedEvent. However, these two events are sent only once per application during bootstrap, no matter how many child contexts are created.

Wouldn't it be possible for the LoggingSystem to remember the main application context and initiate the shutdown of the logging system only when that one is closed (instead of listening/reacting to any ContextClosedEvent) ?

[brenuart]

A shutdown hook is not acceptable solution when the application is deployed in a servlet container for instance. In that case, people are left without any decent solution to close the logging system.

The class loader issue you mentioned above appears only when Logback (or other logging implementation) is provided by the container itself. In this case, one should use the appropriate ContextSelector (see http://logback.qos.ch/manual/loggingSeparation.html). If properly configured, each application receives its own LoggerContext that can be safely stopped without impact on the other applications.

Finally, using a ShutdownHook doesn't guarantee the LoggingSystem is shutdown as late as possible - there is no ordering guarantee. The use of the ContextClosed or (better) a new ApplicationStoppedEvent seems to be a better idea.

[wilkinsona]

A shutdown hook is not acceptable solution when the application is deployed in a servlet container for instance. In that case, people are left without any decent solution to close the logging system.

This is the first time you've mentioned the use of a servlet container in this issue. It would have been very helpful to know about that requirement up front. We did consider container deployments and that is why we made the use of the hook opt-in as didn't want the hook to leak when a webapp was undeployed.

The class loader issue you mentioned above appears only when Logback (or other logging implementation) is provided by the container itself.

That's not the case. There are other environments, Spring XD for example, where multiple Spring Boot applications that share the same class loader may have wildly different lifecycles.

The use of the ContextClosed or (better) a new ApplicationStoppedEvent seems to be a better idea.

It's difficult to be certain that the logging system should be shut down just because an application context has been closed or a Spring Boot application has been stopped, particularly as we can't make any assumptions about the class loader model or any hierarchical relationship between application contexts and SpringApplications.

[brenuart]

It's difficult to be certain that the logging system should be shut down just because an application context has been closed or a Spring Boot application has been stopped, particularly as we can't make any assumptions about the class loader model or any hierarchical relationship between application contexts and SpringApplications.

I understand it is not easy to provide a solution applicable to every scenarios. The best approach is probably to make it configurable and/or extendable so people can customise it to their needs. Let me explain what we did and what problems we had:

(1) decide when to shutdown

There is no ApplicationStoppedEvent to would signal the end of life (similar but opposite to the ApplicationStartedEvent). Our solution was to register an ApplicationListener whose job is to keep track of the main application context and listen for its ContextClosedEvent.

(2) get reference to the LoggingSystem

There is no way to get a reference to the actual LoggingSystem instance.
Our (dirty) solution was to register an ApplicationListener just after the LoggingApplicationListener registered by SpringBoot. When ApplicationStartedEvent is received, we know the LoggingApplicationListener has already selected the LoggingSystem instance and has kept a reference to it. We cycle through the list of registered ApplicationListener (obtained from the event.getApplication().getListeners()), look for the LoggingApplicationListener and get the LoggingSystem via reflection.
That's pretty ugly but that's the only solution we found.

(3) shutdown the LoggingSystem

We built our own extension of LogbackLoggingSystem and added a stop() method. It's use is forced via the system property expected by LoggingSystem.get(). There again we had some problems to access the LoggerContext as described in #4096

As you can see, (2) is the hardest point. It would be very helpful if SpringBoot provides a cleaner approach to get reference to the LoggingSystem. Your latest commits have already provided a solution to (3). And (1) depends on the environment and should probably left to the user.

[philwebb]

I've raised #4159 for (2) on your list.

[brenuart]

Thanks

[brenuart]

Some additional feedback: as described in point (1) above, we decided to explicitly shutdown the logging system upon reception of ContextClosedEvent or ApplicationFailedEvent.

This turned out to be a bad idea. Although these two events are sent very close to shutdown, SpringApplication keeps logging things after the events are thrown. This is for instance the case when the application fails to start: the exception is logged after the ApplicationFailedEvent is sent...

So we decided to rely on the ShutdownHandler feature introduced in Brixton.M3 to properly close our LoggingSystem.

Hope this feedback will help others to find their way... ;-)

[dsyer]

Hope so too. Quick clarification though: "Brixton.M3" refers to a Spring Cloud release train which is incidental or irrelevant. I believe you are using a method getShutdownHandler() added to LoggingSystem in Spring Boot 1.3.0.

[brenuart]

Yes indeed: I was referring to SpringBoot 1.3.0 - sorry.