Log4J: Eccezione FATAL sul gancio di arresto, impossibile capire perché

Question

Ho appena integrato log4j nella mia applicazione e sto configurando AspectJ per utilizzare log4j e in definitiva trasferisco tutto il logout dal mio codice principale. Quindi, in breve, sto impostando aspetti che eseguono le voci del registro e quindi eseguo il mio programma per brevi periodi di tempo per testarle.

Spesso, nel corso di questi brevi tirature, sto ottenendo la seguente eccezione:

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) 

Di tanto in tanto, ma non sempre, questa eccezione è preceduto da:

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) 

Fatemi sapere se si bisogno di vedere qualcos'altro per determinare la causa di questo. Non succede sempre, ma succede abbastanza spesso quando il programma viene eseguito per soli 10-20 secondi. Non capisco perché questo sta accadendo.

Answer 1

Log4j2 tenta di utilizzare shutdown hook per chiudere correttamente il servizio di registrazione.

I ganci di arresto vengono eseguiti in parallelo ed è per questo che l'eccezione non è sistematica.

C'è un bug report per quanto riguarda questo problema.

È possibile disattivare il gancio di arresto nel file di configurazione:

<configuration shutdownHook="disable" ...> 

Answer 2

vedere anche questo link nella pagina di log4j2:

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

Se si include questa dipendenza, non cercherà di aggiungere un gancio di arresto.

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

Answer 3

Questo è un problema noto. Log4j ora utilizzerà SimpleLogger durante l'arresto. Si prega di vedere https://issues.apache.org/jira/browse/LOG4J2-1222.

Answer 4

Come già accennato qui log4j-web è il jar per questo problema. Ha funzionato senza problemi per jetty-9.2.1.v20140609.

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

Se si seleziona la log4j-web, ha log4j.shutdownHookEnabled=false

Ma con Servlet 3.0 e Tomcat 7.0.73, dovuto rimuovere log4j da jarsToSkip chiave di conf/catalina.properties.

Strane cose potrebbero accadere. Per quanto mi riguarda, sto distribuendo due .war s, entrambi usando Non blocking Logger, ha funzionato per un servizio ma non per l'altro. Tomcat 7/Websphere 8 riavviato però.

Motivo della necessità di clean up logging resource è descritta in Using Log4j 2 in Web Applications -

quando il Servlet Container si spegne o l'applicazione web è dispiegato, E 'importante per le risorse di registrazione per essere puliti fino (connessioni al database chiusi, file chiuso, ecc.).

A causa della natura di ClassLoader s nelle app Web, le risorse di Log4j non possono essere pulite da tramite i normali metodi. Log4j deve essere "avviato" quando l'app web viene distribuita e "spenta" quando l'app Web viene disattivata.

Si prega di leggere questo official doc - Using Log4j 2 in Web Containers, è utile.