日志去哪了

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

}