Log4J:关闭挂钩上的致命异常,无法弄清楚原因

Log4J: FATAL exception on shutdown hook, can't figure out why

我刚刚将 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.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.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.run(AbstractApplicationContext.java:893)

如果您需要查看任何其他内容以确定此问题的原因,请告诉我。它并不总是发生,但当程序 运行 仅持续 10-20 秒时,它会经常发生。我只是不明白为什么会这样。

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

关闭挂钩是并行执行的,这就是异常不是系统性的原因。

关于这个问题bug report

您可以在配置文件中禁用关闭钩子:

<configuration shutdownHook="disable" ...>

另请参阅 log4j2 页面上的 link:

https://logging.apache.org/log4j/2.x/manual/webapp.html

如果包含此依赖项,它不会尝试添加关闭挂钩。

<dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-web</artifactId>
        <version>${log4j.version}</version>
 </dependency>

这是一个已知问题。 Log4j 现在将在关闭期间使用 SimpleLogger。请参阅 https://issues.apache.org/jira/browse/LOG4J2-1222

正如这里已经提到的,log4j-web 是解决这个问题的 jar。 jetty-9.2.1.v20140609 没有任何问题。

libraryDependencies += "org.apache.logging.log4j" % "log4j-web" % "2.5"

如果您检查 log4j-web (upto v2.9),它有 log4j.shutdownHookEnabled=false

但是对于 Servlet 3.0Tomcat 7.0.73,必须从 conf/catalina.propertiesjarsToSkip 键中删除 log4j。

可能会发生奇怪的事情。至于我,我正在部署两个 .wars,都使用 Non blocking Logger,为一项服务工作但不为另一个。 Tomcat 7/Websphere 8 重新启动清理它。

需要 clean up logging resource 的原因在 Using Log4j 2 in Web Applications -

中有所描述

when the Servlet Container shuts down or the web app is undeployed, It's important for logging resources to be properly cleaned up (database connections closed, files closed, etc.).

Because of the nature of ClassLoaders within web apps, Log4j resources cannot be cleaned up through normal means. Log4j must be "started" when the web app deploys and "shut down" when the web app undeploys.

请阅读这篇文章official doc - Using Log4j 2 in Web Containers,很有帮助。