Log4J: FATAL exception at shutdown, it is impossible to understand why

Question

I simply integrated log4j into my application and I configure AspectJ to use log4j and ultimately migrate all the entries from my main code. In short, I tweak the aspects that make log entries, and then run my program for short periods of time to test them.

Often during these short runs, I get the following exception:

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) 

Sometimes, but not always, this exception is preceded by:

 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) 

Let me know if you need to see anything else to determine the cause of this. This does not always happen, but it happens quite often when the program starts in only 10-20 seconds. I just don’t understand why this is happening.

Answer 1

Log4j2 will try to use the shutdown hook to shut down the logging service properly.

Shutdown hooks are executed in parallel and therefore the exception is not systematic.

There is an error report in this problem.

In the configuration file, you can disable the download:

 <configuration shutdownHook="disable" ...> 

Answer 2

Also see this link on the log4j2 page:

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

If you enable this dependency, it will not try to add a shutdown to it.

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

Answer 3

As mentioned here, log4j-web is the bank for this problem. This worked without any problems for jetty-9.2.1.v20140609 .

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

If you check log4j-web (before v2.9) , it has log4j.shutdownHookEnabled=false

But with Servlet 3.0 and Tomcat 7.0.73 I had to remove log4j from the jarsToSkip key in jarsToSkip conf/catalina.properties .

Strange things can happen. For me, I am deploying two .war , both using the Non blocking Logger , worked for one service, but not for the other. Restarting Tomcat 7 / Websphere 8 cleared it.

The reason for the need for a clean up logging resource is described in Using Log4j 2 in Web Applications.

when the Servlet Container is shutting down or the web application is disconnected, it is important to clean log resources correctly (database connections, files closed, etc.).

Due to the nature of ClassLoader in web applications, Log4j resources cannot be cleared by conventional means. Log4j must be "started" when you deploy the web application and "off" when you deploy it.

Please read this white paper - Using Log4j 2 in web containers , this is useful.

Answer 4

This is a known issue. Log4j will now use SimpleLogger during shutdown. See https://issues.apache.org/jira/browse/LOG4J2-1222 .