Using shutdown hook to close the LoggingSystem stops it before the spring application context when SIGHUP or Ctrl-C

[brenuart]

Since SpringBoot 1.3.0, logging system implementations that need to be notified of the application close should register their own shutdown hook.

Spring framework also registers its own shutdown hook to capture SIGUP/Ctrl-C events and close the application context.

Since the jvm is likely to invoke shutdown hooks in parallel, the logging system may be closed before (or during) the application context - hence loosing all log messages generated during the shutdown sequence.

See #4026 for more information.

[philwebb]

I can't think a particularly easy way to fix this. Perhaps we can block for a short amount of time to see if cleanup is called.

[wilkinsona]

See also #4651. The logging system is now only cleaned up when a root context is closed. This may make clean up a more viable option for cleaning up your custom logging system without resorting to a shutdown hook.

[philwebb]

There doesn't seem to be many options that we can implement to solve this in a generic way. Perhaps one thing that you could do for your code is add your own shutdown hook to close things in the correct order. You can use SpringApplication.setRegisterShutdownHook(false) to disable our hook.

[philwebb]

@brenuart please let us know if any of the suggested workarounds solve your issue.

[brenuart]

The last proposition is actually what we have done.
First of all, we managed to make sure LoggingApplicationListener doesn't register the LoggingSystem`s shutdown hook itself. We then built another ApplicationListener configured to kick-in just after the original LoggingApplicationListener.

Our listener will register its own shutdown hook upon reception of the ApplicationEnvironmentPrepared. Since we are trigger after LoggingApplicationListener we know the LoggingSystem has been initialised. The hook actually delegates to LoggingSystem.getShutdownHandler() to perform the actual shutdown.

Our hook also takes a reference to the running application context and attempts to close it before invoking the handler of the logging system. Since applicationContext.close() is synchronised, we either initiate the close of the application context ourselves, or have to wait until it is completed if already initiated from another thread.

The reference to the running application context is obtained from the ApplicationReadyEvent. It could be grabbed earlier, but it would then force the context to be fully initialised before the close() method can proceed (reason why the SpringApplication registers his own hook only after ApplicationReadyEvent is sent).

If the application fails to start, the hook is invoked only when the VM terminates - there is no application context anyway (it could not start).

If interested, I could post a PR to illustrate what changes to actual code would be required.

[philwebb]

@brenuart Yes please for the PR with details.

[wilkinsona]

I think we're in danger of building a house of cards if we pursue the shutdown-hook-based approach. As I said in my comment above, the logging system is now only cleaned up as a result of the root context being closed. This is our preferred approach for shutting down the logging system and should be used in preference to a logging system shutdown hook.