Where did the log go

When removing the SpringBoot dependency from a service, the shutdown hook is not running properly. There is a log for starting execution, but no log for finishing execution.

It’s also easy to reproduce. Create a New Maven project and add a startup class like this

@Slf4j
public class Application {

    public static void main(String[] args) {
        log.info("start application...");
        Runtime.getRuntime().addShutdownHook(new Thread(() -> {
            try {
                destroy();
            } catch (InterruptedException e) {
                log.error("stop working failed",e); }})); }public static void destroy(a) throws InterruptedException {
        log.info("stop working...");
        Thread.sleep(1000);
        log.info("working stopped..."); }}Copy the code

The default log output level of log4j2 is Error and needs to be changed to INFO.

The results

18:08:43. [the main] INFO 082 com. Zworks. Log4jshutdown. Java Application - start Application... 18:08:43. [085] Thread - 1 INFO. Com zworks. Log4jshutdown. Java Application - stop working... Process finished with exit code 0Copy the code

It can be seen that there is no problem with the log output, but there is no output of the log after shutdown hook is run. Is the program quit in advance

You can debug it or, more simply, use system.out at the end. Either way, you can actually prove that the program executed, but the log is not printed.

log4j2 shutdown hook

If you look at the log4j2 configuration, you can see that there is a shutdownHook configuration, which is enabled by default

Specifies whether or not Log4j should automatically shutdown when the JVM shuts down. The shutdown hook is enabled by default but may be disabled by setting this attribute to “disable”

If open, can register a shutdown hook, specific can consult org. Apache. Logging. Log4j. Core. LoggerContext start method

@Override
public void start(a) {
    LOGGER.debug("Starting LoggerContext[name={}, {}]...", getName(), this);
    if (PropertiesUtil.getProperties().getBooleanProperty("log4j.LoggerContext.stacktrace.on.start".false)) {
        LOGGER.debug("Stack trace to locate invoker".new Exception("Not a real error, showing stack trace to locate invoker"));
    }
    if (configLock.tryLock()) {
        try {
            if (this.isInitialized() || this.isStopped()) {
                this.setStarting();
                reconfigure();
                if (this.configuration.isShutdownHookEnabled()) {
                    setUpShutdownHook();
                }
                this.setStarted(); }}finally {
            configLock.unlock();
        }
    }
    LOGGER.debug("LoggerContext[name={}, {}] started OK.", getName(), this);
}
Copy the code

SetUpShutdownHook registers the Shutdown hook with ShutdownCallbackRegistry, ShutdownCallbackRegistry implementation class DefaultShutdownCallbackRegistry when they start their registration to shutdown the hooks.

@Override
public void start(a) {
    if (state.compareAndSet(State.INITIALIZED, State.STARTING)) {
        try {
            addShutdownHook(threadFactory.newThread(this));
            state.set(State.STARTED);
        } catch (final IllegalStateException ex) {
            state.set(State.STOPPED);
            throw ex;
        } catch (finalException e) { LOGGER.catching(e); state.set(State.STOPPED); }}}private void addShutdownHook(final Thread thread) {
    shutdownHookRef = new WeakReference<>(thread);
    Runtime.getRuntime().addShutdownHook(thread);
}
Copy the code

The JVM executes shutdown hooks for each registered hook

@Override
public void run(a) {
    if (state.compareAndSet(State.STARTED, State.STOPPING)) {
        for (final Runnable hook : hooks) {
            try {
                hook.run();
            } catch (final Throwable t1) {
                try {
                    LOGGER.error(SHUTDOWN_HOOK_MARKER, "Caught exception executing shutdown hook {}", hook, t1);
                } catch (final Throwable t2) {
                    System.err.println("Caught exception " + t2.getClass() + " logging exception "+ t1.getClass()); t1.printStackTrace(); } } } state.set(State.STOPPED); }}Copy the code

The solution

Just change the shutdown hook to manual shutdown:

  1. In the configuration file, setshutdownHook="disable".
  2. Pass after running all shutdown hooksorg.apache.logging.log4j.LogManager.shutdown()Manually turn it off.

One thing to note here is that the order of execution of multiple shutdown hooks is not guaranteed, so you need to consider where to close them.

Why is SpringBoot ok

Finally, let’s see why SpringBoot works.

Change the above program to SpringBoot form

@Slf4j
@SpringBootApplication
public class Log4jShutdownApplication {

	public static void main(String[] args) {
		SpringApplication.run(Log4jShutdownApplication.class, args);
		log.info("start application...");
		Runtime.getRuntime().addShutdownHook(new Thread(() -> {
			try {
				destroy();
			} catch (InterruptedException e) {
				log.error("stop working failed",e); }})); }public static void destroy(a) throws InterruptedException {
		log.info("stop working...");
		Thread.sleep(1000);
		log.info("working stopped..."); }}Copy the code

The results

The 2021-04-04 19:35:14. 3145-084 the INFO [the main] C.Z.L.L og4jShutdownApplication: Started Log4jShutdownApplication in 0.682 seconds (JVM running for 1.254) 2021-04-04 19:35:14.087 INFO 3145 -- [main] c.z.l.Log4jShutdownApplication : start application... The 2021-04-04 19:35:14. 3145-088 the INFO/Thread - 2 C.Z.L.L og4jShutdownApplication: stop working... The 2021-04-04 19:35:15. 3145-088 the INFO/Thread - 2 C.Z.L.L og4jShutdownApplication: working stopped...Copy the code

Found that everything was normal, with the code can be found that SpringBoot provided in SpringBootConfigurationFactory class implements the ConfigurationFactory, and set the shutdown hooks is false.

private static final class SpringBootConfiguration extends DefaultConfiguration { private SpringBootConfiguration() { this.isShutdownHookEnabled = false; }}Copy the code