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;
    }

}