java - Log4J:关闭 Hook 上的致命异常，无法弄清楚原因

Question

我刚刚将 log4j 集成到我的应用程序中，并且我正在设置 AspectJ 以使用 log4j 并最终将所有登录转移出我的主代码。所以，简而言之，我正在设置执行日志条目的方面，然后在短时间内运行我的程序来测试它们。

在这些短期运行期间，我经常遇到以下异常:

2015-09-28 15:21:48,222 Thread-4 FATAL Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED
at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:271)
at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:240)
at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:201)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:233)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:162)
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:507)
at org.jboss.logging.Log4j2Logger.<init>(Log4j2Logger.java:36)
at org.jboss.logging.Log4j2LoggerProvider.getLogger(Log4j2LoggerProvider.java:30)
at org.jboss.logging.Log4j2LoggerProvider.getLogger(Log4j2LoggerProvider.java:26)
at org.jboss.logging.Logger.getLogger(Logger.java:2465)
at org.jboss.logging.Logger$1.run(Logger.java:2565)
at java.security.AccessController.doPrivileged(Native Method)
at org.jboss.logging.Logger.getMessageLogger(Logger.java:2529)
at org.jboss.logging.Logger.getMessageLogger(Logger.java:2516)
at org.hibernate.internal.CoreLogging.messageLogger(CoreLogging.java:28)
at org.hibernate.internal.CoreLogging.messageLogger(CoreLogging.java:24)
at org.hibernate.event.internal.ReattachVisitor.<clinit>(ReattachVisitor.java:27)
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performUpdate(DefaultSaveOrUpdateEventListener.java:293)
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:227)
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:92)
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:73)
at org.hibernate.internal.SessionImpl.fireSaveOrUpdate(SessionImpl.java:647)
at org.hibernate.internal.SessionImpl.saveOrUpdate(SessionImpl.java:639)
at org.hibernate.internal.SessionImpl.saveOrUpdate(SessionImpl.java:634)
at io.craigmiller160.stockmarket.controller.HibernatePortfolioDAO.savePortfolio(HibernatePortfolioDAO.java:225)
at io.craigmiller160.stockmarket.controller.StockMarketController.savePortfolio(StockMarketController.java:1441)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:353)
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:276)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:925)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:932)
at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:997)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:973)
at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:893)

有时，但并非总是，此异常之前有:

2015-09-28 15:21:48,152 Thread-4 ERROR An exception occurred processing Appender asyncAppender java.lang.IllegalStateException: AsyncAppender asyncAppender is not active
at org.apache.logging.log4j.core.appender.AsyncAppender.append(AsyncAppender.java:136)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:148)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:121)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:112)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:80)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:352)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:59)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:138)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:999)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:954)
at org.apache.logging.log4j.jcl.Log4jLog.debug(Log4jLog.java:81)
at org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDriver(DriverManagerDataSource.java:142)
at org.springframework.jdbc.datasource.AbstractDriverBasedDataSource.getConnectionFromDriver(AbstractDriverBasedDataSource.java:155)
at org.springframework.jdbc.datasource.AbstractDriverBasedDataSource.getConnection(AbstractDriverBasedDataSource.java:120)
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:382)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:230)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:237)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:213)
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:52)
at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1443)
at io.craigmiller160.stockmarket.controller.HibernatePortfolioDAO.savePortfolio(HibernatePortfolioDAO.java:224)
at io.craigmiller160.stockmarket.controller.StockMarketController.savePortfolio(StockMarketController.java:1441)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:353)
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:276)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:925)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:932)
at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:997)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:973)
at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:893)

如果您需要查看其他内容来确定原因，请告诉我。它并不总是发生，但当程序仅运行 10 到 20 秒时，它会非常频繁地发生。我只是不明白为什么会这样。

Answer 1

Log4j2 尝试使用 shutdown hook正确关闭日志记录服务。

关闭 Hook 是并行执行的，这就是异常不是系统性的原因。

有一个bug report关于这个问题。

您可以在配置文件中禁用关机钩子(Hook):

<configuration shutdownHook="disable" ...>