Async Logger threadpool not shut down by Tomcat shutdown

Details

Description

From the user mailing list - conversation with Steven Yang:

Looks like Tomcat shutdown checks for memory leaks and notices that the Disruptor threadpool used by async loggers has not been shut down.
Is there any way to pick up a Tomcat shutdown signal and use that to trigger log subsystem shutdown?

-------------------------
QUOTING STEVEN:
Thanks, I tried using asyncRoot and everything seems to log fine and I do see a lot of logs.
And logs do seem to be flushed immediately so I do not know if the hook on shutdown is been called correctly or not.

I am using struts and spring so I see a lot of logs (log level at DEBUG) just by starting up tomcat, so I am wondering when I use <root> how come I dont see any log at all? how much log do I have to write before it starts to flush out?

and one thing I found is that when I use asyncRoot and when I shutdown tomcat I see the following message regarding to clearing references and thread local.
The last one is related to log4j.
I am trying this on tomcat 6.0.29.

四月 28, 2013 8:34:46 上午 org.apache.catalina.loader.WebappClassLoader clearReferencesJdbc
SEVERE: The web application [/test] registered the JBDC driver [org.h2.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
四月 28, 2013 8:34:46 上午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/test] appears to have started a thread named [pool-2-thread-1] but has failed to stop it. This is very likely to create a memory leak.
四月 28, 2013 8:34:46 上午 org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: The web application [/test] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@454e119d]) and a value of type [com.opensymphony.xwork2.inject.ContainerImpl] (value [com.opensymphony.xwork2.inject.ContainerImpl@8667df7]) but failed to remove it when the web application was stopped. This is very likely to create a memory leak.
四月 28, 2013 8:34:46 上午 org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: The web application [/test] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@d7e770]) and a value of type [org.apache.logging.log4j.core.impl.Log4jLogEvent] (value [Logger=org.springframework.beans.factory.support.DefaultListableBeanFactory Level=INFO Message=Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@61e118f9: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframewo...

Ralph, just eyeballing the changes you made it looks good, but I'd like to step through it in a debugger to make sure.

I noticed you made changes to AsyncLoggerConfig and *Helper, but not to AsyncLogger.
Is that because the problem did not exist in that class, or because
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
cannot be used in a web application?

(If the latter is the case maybe I should note this in the Async Logger docs...)

Remko Popma
added a comment - 30/Apr/13 04:17 Ralph, just eyeballing the changes you made it looks good, but I'd like to step through it in a debugger to make sure.
I noticed you made changes to AsyncLoggerConfig and *Helper, but not to AsyncLogger.
Is that because the problem did not exist in that class, or because
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
cannot be used in a web application?
(If the latter is the case maybe I should note this in the Async Logger docs...)

The problems were:
a) The disruptor was only being stopped during a shutdown. However, a reconfiguration from an async logger to a synchronous logger would cause it to never shutdown.
b) The disruptor is a singleton and could be shared by multiple things. A counter was added to keep track of them and only allow shutdown when everything is complete.
c) The disruptor was shutting down before the managers using it were stopped. It now stops after them so they can successfully complete.

Ralph Goers
added a comment - 30/Apr/13 06:36 The problems were:
a) The disruptor was only being stopped during a shutdown. However, a reconfiguration from an async logger to a synchronous logger would cause it to never shutdown.
b) The disruptor is a singleton and could be shared by multiple things. A counter was added to keep track of them and only allow shutdown when everything is complete.
c) The disruptor was shutting down before the managers using it were stopped. It now stops after them so they can successfully complete.

Remko Popma
added a comment - 01/May/13 15:03 Added small fix (revision 1478040) to prevent NPE in ShutdownHook thread if disruptor was already shut down in app thread. (Details are in the comments of LOG4J-223)

Nick Williams
added a comment - 28/Jul/13 06:33 Please see the documentation on using Log4j 2 in Web Applications: http://logging.apache.org/log4j/2.x/manual/webapp.html .
You either need to change your web-app version to 3.0, or you need to declare the Log4j listener and filter.

Nope, I don't think you've missed anything obvious this time. The change you made to catalina.properties and web.xml resolved the issue with Log4j not shutting down properly. Now you've found a completely unrelated ThreadLocal-leak. Please file a separate issue for that. You won't need catalina.properties or your web.xml, as they have nothing to do with this problem. Just include the new Tomcat console output you just showed me, log4j2.xml, and setenv.sh.

By the way, I noticed you're using Java code to log in your asynclog.jsp. This isn't causing any problems, but it's not the easiest way to log in JSPs. You might want to take a look at the Log4j 2 Tag Library.

Nick Williams
added a comment - 28/Jul/13 16:17 Nope, I don't think you've missed anything obvious this time. The change you made to catalina.properties and web.xml resolved the issue with Log4j not shutting down properly. Now you've found a completely unrelated ThreadLocal-leak. Please file a separate issue for that. You won't need catalina.properties or your web.xml , as they have nothing to do with this problem. Just include the new Tomcat console output you just showed me, log4j2.xml , and setenv.sh .
By the way, I noticed you're using Java code to log in your asynclog.jsp . This isn't causing any problems, but it's not the easiest way to log in JSPs. You might want to take a look at the Log4j 2 Tag Library .