Log4J：シャットダウンフックの致命的な例外はなぜ発生しないのですか？

Question

Log4jを自分のアプリケーションに統合しただけで、Log4jを使用するAspectJを設定しています。要するに、ログエントリを実行し、プログラムを短期間実行してテストするという側面を設定しています。時折

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を使用して、ログサービスを適切に終了してみてください。

シャットダウンフックは並行して実行されるため、例外が体系的ではありません。

この問題に関しては、bug reportがあります。

あなたの設定ファイルにシャットダウンフックを無効にすることができます

<configuration shutdownHook="disable" ...> 

Answer 2

またlog4j2のページにこのリンクを参照してください。

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> 

Answer 3

これは既知の問題です。 Log4jはシャットダウン時にSimpleLoggerを使用するようになりました。 https://issues.apache.org/jira/browse/LOG4J2-1222をご覧ください。

Answer 4

すでに言及したように、log4j-webはこの問題の瓶です。 jetty-9.2.1.v20140609については問題なく動作しました。

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

あなたがlog4j-webを確認した場合、それはlog4j.shutdownHookEnabled=false

を持っていますが、Servlet 3.0とTomcat 7.0.73で、conf/catalina.propertiesのjarsToSkipキーからのlog4jを削除する必要がありました。

奇妙なことが起こるかもしれません。私にとっては、Non blocking Loggerを使用して2つの.warをデプロイしていますが、1つのサービスでは動作しましたが、他のサービスでは動作しませんでした。 Tomcat 7/Websphere 8再起動しても再起動します。ログリソースが適切に （データベース接続を閉じ、ファイルをクリーンアップすることが重要です 、Servlet ContainerがシャットダウンまたはWebアプリケーションをアンデプロイするとき

からclean up logging resourceへの必要性のための

理由はUsing Log4j 2 in Web Applicationsに記述されています閉じられた、など）。

webアプリケーション内の性質がClassLoaderであるため、Log4jリソースは通常の手段で にクリーンアップすることはできません。ウェブ がデプロイされ、ウェブアプリケーションのデプロイ時に "シャットダウン"すると、Log4jが "開始"されている必要があります。

このofficial doc - Using Log4j 2 in Web Containersをお読みください。