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

Posted 2021-09-15 码农张思壮

日志去哪了

把一个服务去掉 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;
    }

}