Shutdown Hook 中的日志去哪了？log4j2 shutdown hook 机制探究

日志去哪了

把一个服务去掉 SpringBoot 依赖的时候，发现 shutdown hook 运行不正常了，有开始执行的日志，执行完成的却没有。

重现也很方便，新建一个 maven 工程，增长一个启动类，以下

@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() throws InterruptedException {
        log.info("stop working...");
        Thread.sleep(1000);
        log.info("working stopped...");
    }
}

log4j2 默认的日志输出级别是 error，须要调整为 info 。

运行结果

18:08:43.082 [main] INFO  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 0

能够看到日志输出是没问题，可是 shutdown hook 运行结束的日志却没有输出，是程序提早退出了吗

这里能够进行 debug ，或者更简单的，在最后使用 System.out 进行输出，无论使用哪一种方法，其实均可以证实程序执行完成，只是日志没有输出。

log4j2 shutdown hook

翻看 log4j2 的配置，能够发现，有一个 shutdownHook 的配置，默认是开启的

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"

若是开启，则会注册一个 shutdown hook ，具体能够参考 org.apache.logging.log4j.core.LoggerContext 的 start 方法

@Override
public void start() {
    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);
}

setUpShutdownHook 会向 ShutdownCallbackRegistry 中注册 shutdown hook，shutdownCallbackRegistry的实现类 DefaultShutdownCallbackRegistry 会在启动时会将本身注册到 shutdown hook。

@Override
public void start() {
    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 (final Exception e) {
            LOGGER.catching(e);
            state.set(State.STOPPED);
        }
    }
}

private void addShutdownHook(final Thread thread) {
    shutdownHookRef = new WeakReference<>(thread);
    Runtime.getRuntime().addShutdownHook(thread);
}

jvm 执行 shutdown hook 的时候会把注册的每一个 hook 进行执行

@Override
public void run() {
    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);
    }
}

解决方案

只须要把 shutdown hook 变为手动关闭便可：

1. 在配置文件中，设置 shutdownHook="disable"。
2. 在运行完全部 shutdown hook 后再经过 org.apache.logging.log4j.LogManager.shutdown()手动关闭。

这里有个点要注意，多个 shutdown hook 的执行顺序是没法保障的，在哪里关闭须要考虑好。

SpringBoot 为何没问题

最后再看一下为何使用 SpringBoot 的时候没问题。

把上面的程序改为 SpringBoot 的形式

@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() throws InterruptedException {
        log.info("stop working...");
        Thread.sleep(1000);
        log.info("working stopped...");
    }
}

运行结果

2021-04-04 19:35:14.084  INFO 3145 --- [           main] c.z.l.Log4jShutdownApplication           : 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...
2021-04-04 19:35:14.088  INFO 3145 --- [       Thread-2] c.z.l.Log4jShutdownApplication           : stop working...
2021-04-04 19:35:15.088  INFO 3145 --- [       Thread-2] c.z.l.Log4jShutdownApplication           : working stopped...

发现一切正常，跟了代码能够发现，SpringBoot 中提供的 SpringBootConfigurationFactory类实现了 ConfigurationFactory，而且把 shutdown hook 设置成了 false.

private static final class SpringBootConfiguration extends DefaultConfiguration {

    private SpringBootConfiguration() {
        this.isShutdownHookEnabled = false;
    }

}