[
https://issues.apache.org/jira/browse/LOG4J2-222?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13721882#comment-13721882
]
Michael Kloster commented on LOG4J2-222:
----------------------------------------
This is marked as fixed. However, when I build the trunk as of July-27-2013
23:00 CDT, I can still generate the shutdown errors using a very simple example
on Tomcat 7.0.42.
Steps to reproduce:
1) create minimal web app with following structure:
{code}
WEB-INF/lib/disruptor-3.1.1.jar
WEB-INF/lib/log4j-core-2.0-beta9-SNAPSHOT.jar
WEB-INF/lib/log4j-api-2.0-beta9-SNAPSHOT.jar
WEB-INF/classes/log4j.xml
WEB-INF/web.xml
asynclog.jsp
{code}
{code:xml|title=log4j2.xml|borderStyle=solid}
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="WARN">
<appenders>
<FastRollingFile name="MyFileLog" filename="logs/my.log"
filePattern="logs/my-%d{COMPACT}.log">
<PatternLayout pattern="%d %p %c{1.} [%t] %m%n" />
<Policies>
<SizeBasedTriggeringPolicy size="5MB" />
</Policies>
</FastRollingFile>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d %p %c{1.} [%t] %m%n" />
</Console>
</appenders>
<loggers>
<logger name="mylogger" level="INFO" additivity="false">
<appender-ref ref="MyFileLog" />
</logger>
<root level="TRACE">
<appender-ref ref="Console" />
</root>
</loggers>
</configuration>
{code}
{code:title=asynclog.jsp|borderStyle=solid}
<%@ page import="org.apache.logging.log4j.*"%>
<%
String log = request.getParameter("log");
Logger logger = LogManager.getLogger("mylogger");
logger.info("log: '"+log+"'");
%>
{code}
{code:xml|title=web.xml|borderStyle=solid}
<?xml version="1.0" encoding="ISO-8859-1"?>
<web-app xmlns="http://java.sun.com/xml/ns/javaee";
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance";
xsi:schemaLocation="http://java.sun.com/xml/ns/javaee
http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd";
version="2.5">
<description>
Async Log Server Example
</description>
<display-name>Async Log Server Example</display-name>
</web-app>
{code}
2. setenv.sh on tomcat to indicate async logging:
{code:title=setenv.sh|borderStyle=solid}
#!/bin/bash
CATALINA_OPTS=-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
{code}
3. start tomcat with webapp and hit asynclog.jsp?log=example
4. stop tomcat
5. cat logs:
{code}
Jul 28, 2013 12:27:37 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Jul 28, 2013 12:27:37 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Jul 28, 2013 12:27:37 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 684 ms
Jul 28, 2013 12:28:00 AM org.apache.catalina.core.StandardServer await
INFO: A valid shutdown command was received via the shutdown port. Stopping the
Server instance.
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-bio-8080"]
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
Jul 28, 2013 12:28:00 AM org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service Catalina
Jul 28, 2013 12:28:00 AM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/asynclog] appears to have started a thread named
[AsyncLogger-1] but has failed to stop it. This is very likely to create a
memory leak.
Jul 28, 2013 12:28:00 AM org.apache.catalina.loader.WebappClassLoader
checkThreadLocalMapForLeaks
SEVERE: The web application [/asynclog] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@61bd427]) and a value of
type [org.apache.logging.log4j.core.async.AsyncLogger.Info] (value
[org.apache.logging.log4j.core.async.AsyncLogger$Info@57ab4292]) but failed to
remove it when the web application was stopped. Threads are going to be renewed
over time to try and avoid a probable memory leak.
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-bio-8080"]
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["ajp-bio-8009"]
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-bio-8080"]
Jul 28, 2013 12:28:00 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["ajp-bio-8009"]
Jul 28, 2013 12:28:01 AM org.apache.catalina.loader.WebappClassLoader loadClass
INFO: Illegal access: this web application instance has been stopped already.
Could not load java.util.concurrent.TimeUnit. The eventual following stack
trace is caused by an error thrown for debugging purposes as well as to attempt
to terminate the thread which caused the illegal access, and has no functional
impact.
java.lang.IllegalStateException
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1600)
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1559)
at com.lmax.disruptor.dsl.Disruptor.shutdown(Disruptor.java:292)
at
org.apache.logging.log4j.core.async.AsyncLogger.stop(AsyncLogger.java:249)
at
org.apache.logging.log4j.core.async.AsyncLoggerContext.stop(AsyncLoggerContext.java:56)
at
org.apache.logging.log4j.core.LoggerContext$ShutdownThread.run(LoggerContext.java:437)
Exception in thread "Thread-9" java.lang.NoClassDefFoundError:
org/apache/logging/log4j/core/config/NullConfiguration
at
org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:210)
at
org.apache.logging.log4j.core.async.AsyncLoggerContext.stop(AsyncLoggerContext.java:57)
at
org.apache.logging.log4j.core.LoggerContext$ShutdownThread.run(LoggerContext.java:437)
Caused by: java.lang.ClassNotFoundException:
org.apache.logging.log4j.core.config.NullConfiguration
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1714)
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1559)
... 3 more
{code}
Scroll down through the catalina.out. The errors / exception on shutdown are
still present.
Should I submit this as a new bug report, or should the bug report be reopened?
> Async Logger threadpool not shut down by Tomcat shutdown
> --------------------------------------------------------
>
> Key: LOG4J2-222
> URL: https://issues.apache.org/jira/browse/LOG4J2-222
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0-beta5
> Reporter: Remko Popma
> Fix For: 2.0-beta6
>
>
> 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...
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
