You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Michael Kloster (JIRA)" <ji...@apache.org> on 2013/07/28 07:37:49 UTC
[jira] [Commented] (LOG4J2-222) Async Logger threadpool not shut
down by Tomcat shutdown
[ 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org