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

Question

I just integrated log4j into my application, and I'm setting up AspectJ to use log4j and ultimately transfer all logging out of my main code. So, in short, I'm setting up aspects that execute log entries, and then running my program for short periods of time to test them.

Frequently, during these short runs, I'm getting 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)

Occasionally, 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. It doesn't always happen, but it's happening quite frequently when the program is run for only 10-20 seconds. I just don't get why this is happening.

Answer 1

Log4j2 try to use shutdown hook to close the logging service properly.

Shutdown hooks are executed in parallel and that's why the exception is not systematic.

There is a bug report regarding this problem.

You can disable shutdown hook in your configuration file :

<configuration shutdownHook="disable" ...>

Answer 2

Also see this link on log4j2's page:

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

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

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

Answer 3

As already mentioned here log4j-web is the jar for this problem. It worked without any problem for jetty-9.2.1.v20140609.

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

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

But with Servlet 3.0 and Tomcat 7.0.73, had to remove log4j from jarsToSkip key of conf/catalina.properties.

Strange things might happen. As for me, I am deploying two .wars, both using Non blocking Logger, worked for one service but not for the other. Tomcat 7/Websphere 8 restart cleaned it up though.

Reason for need to clean up logging resource is described in 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.

Please read this official doc - Using Log4j 2 in Web Containers, its helpful.

Answer 4

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