Log4j 2
  1. Log4j 2
  2. LOG4J2-222

Async Logger threadpool not shut down by Tomcat shutdown

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta5
    • Fix Version/s: 2.0-beta6
    • Component/s: Core
    • Labels:
      None

      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...

        Issue Links

          Activity

          Remko Popma created issue -
          Remko Popma made changes -
          Field Original Value New Value
          Link This issue is related to LOG4J2-223 [ LOG4J2-223 ]
          Hide
          Remko Popma added a comment -

          It may make sense to look at these together.

          Show
          Remko Popma added a comment - It may make sense to look at these together.
          Hide
          Ralph Goers added a comment -

          Fixed in revision 1477462. Please verify and close.

          Show
          Ralph Goers added a comment - Fixed in revision 1477462. Please verify and close.
          Ralph Goers made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 2.0-beta6 [ 12324340 ]
          Resolution Fixed [ 1 ]
          Hide
          Remko Popma added a comment -

          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...)

          Show
          Remko Popma added a comment - 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...)
          Hide
          Ralph Goers added a comment -

          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.

          Show
          Ralph Goers added a comment - 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.
          Hide
          Remko Popma added a comment -

          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)

          Show
          Remko Popma added a comment - 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)
          Hide
          Remko Popma added a comment -

          Tested revision 1478040 with Archiva and looks good. See comments in LOG4J2-223.

          Tomcat now shuts down cleanly when using mixed sync and async loggers.
          Superficial testing of the "all loggers async" scenario ( -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector ) also looked good.

          Show
          Remko Popma added a comment - Tested revision 1478040 with Archiva and looks good. See comments in LOG4J2-223 . Tomcat now shuts down cleanly when using mixed sync and async loggers. Superficial testing of the "all loggers async" scenario ( -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector ) also looked good.
          Hide
          Michael Kloster added a comment -

          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:

          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
          
          log4j2.xml
          <?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>
          
          asynclog.jsp
          <%@ page import="org.apache.logging.log4j.*"%>
          <%
            String log = request.getParameter("log");
            Logger logger = LogManager.getLogger("mylogger");
            logger.info("log: '"+log+"'"); 
          %>
          
          web.xml
          <?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>
          

          2. setenv.sh on tomcat to indicate async logging:

          setenv.sh
          #!/bin/bash
          
          CATALINA_OPTS=-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
          

          3. start tomcat with webapp and hit asynclog.jsp?log=example

          4. stop tomcat

          5. cat logs:

          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
          
          

          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?

          Show
          Michael Kloster added a comment - 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: 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 log4j2.xml <?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> asynclog.jsp <%@ page import = "org.apache.logging.log4j.*" %> <% String log = request.getParameter( "log" ); Logger logger = LogManager.getLogger( "mylogger" ); logger.info( "log: '" +log+ "'" ); %> web.xml <?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> 2. setenv.sh on tomcat to indicate async logging: setenv.sh #!/bin/bash CATALINA_OPTS=-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 3. start tomcat with webapp and hit asynclog.jsp?log=example 4. stop tomcat 5. cat logs: 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 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?
          Hide
          Nick Williams added a comment -

          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.

          Show
          Nick Williams added a comment - 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.
          Hide
          Michael Kloster added a comment -

          I've retested using 3.0 as the version property in web.xml and removing log4j*.jar in the jarsToSkip of catalina.properties on tomcat 7.0.42 and I get the following output on shutdown:

          Jul 28, 2013 9:55:59 AM org.apache.coyote.AbstractProtocol start
          INFO: Starting ProtocolHandler ["http-bio-8080"]
          Jul 28, 2013 9:55:59 AM org.apache.coyote.AbstractProtocol start
          INFO: Starting ProtocolHandler ["ajp-bio-8009"]
          Jul 28, 2013 9:55:59 AM org.apache.catalina.startup.Catalina start
          INFO: Server startup in 841 ms
          Jul 28, 2013 9:56:09 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 9:56:09 AM org.apache.coyote.AbstractProtocol pause
          INFO: Pausing ProtocolHandler ["http-bio-8080"]
          Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol pause
          INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
          Jul 28, 2013 9:56:09 AM org.apache.catalina.core.StandardService stopInternal
          INFO: Stopping service Catalina
          Jul 28, 2013 9:56:09 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@648bfdea]) and a value of type [org.apache.logging.log4j.core.async.AsyncLogger.Info] (value [org.apache.logging.log4j.core.async.AsyncLogger$Info@4e26d560]) 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 9:56:09 AM org.apache.coyote.AbstractProtocol stop
          INFO: Stopping ProtocolHandler ["http-bio-8080"]
          Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol stop
          INFO: Stopping ProtocolHandler ["ajp-bio-8009"]
          Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol destroy
          INFO: Destroying ProtocolHandler ["http-bio-8080"]
          Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol destroy
          INFO: Destroying ProtocolHandler ["ajp-bio-8009"]
          
          web.xml
          <?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_3_0.xsd"
            version="3.0"
            metadata-complete="true">
          
              <description>
                Async Log Server Example
              </description>
              <display-name>Async Log Server Example</display-name>
          
          </web-app>
          
          catalina.properties
          tomcat.util.scan.DefaultJarScanner.jarsToSkip=\
          bootstrap.jar,commons-daemon.jar,tomcat-juli.jar,\
          annotations-api.jar,el-api.jar,jsp-api.jar,servlet-api.jar,\
          catalina.jar,catalina-ant.jar,catalina-ha.jar,catalina-tribes.jar,\
          jasper.jar,jasper-el.jar,ecj-*.jar,\
          tomcat-api.jar,tomcat-util.jar,tomcat-coyote.jar,tomcat-dbcp.jar,\
          tomcat-jni.jar,tomcat-spdy.jar,\
          tomcat-i18n-en.jar,tomcat-i18n-es.jar,tomcat-i18n-fr.jar,tomcat-i18n-ja.jar,\
          tomcat-juli-adapters.jar,catalina-jmx-remote.jar,catalina-ws.jar,\
          tomcat-jdbc.jar,\
          tools.jar,\
          commons-beanutils*.jar,commons-codec*.jar,commons-collections*.jar,\
          commons-dbcp*.jar,commons-digester*.jar,commons-fileupload*.jar,\
          commons-httpclient*.jar,commons-io*.jar,commons-lang*.jar,commons-logging*.jar,\
          commons-math*.jar,commons-pool*.jar,\
          jstl.jar,\
          geronimo-spec-jaxrpc*.jar,wsdl4j*.jar,\
          ant.jar,ant-junit*.jar,aspectj*.jar,jmx.jar,h2*.jar,hibernate*.jar,httpclient*.jar,\
          jmx-tools.jar,jta*.jar,mail*.jar,slf4j*.jar,\
          xercesImpl.jar,xmlParserAPIs.jar,xml-apis.jar,\
          junit.jar,junit-*.jar,ant-launcher.jar
          

          I don't mean for you to debug my code. I apologize in advance if I've missed anything obvious (again!).

          Show
          Michael Kloster added a comment - I've retested using 3.0 as the version property in web.xml and removing log4j*.jar in the jarsToSkip of catalina.properties on tomcat 7.0.42 and I get the following output on shutdown: Jul 28, 2013 9:55:59 AM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler [ "http-bio-8080" ] Jul 28, 2013 9:55:59 AM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler [ "ajp-bio-8009" ] Jul 28, 2013 9:55:59 AM org.apache.catalina.startup.Catalina start INFO: Server startup in 841 ms Jul 28, 2013 9:56:09 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 9:56:09 AM org.apache.coyote.AbstractProtocol pause INFO: Pausing ProtocolHandler [ "http-bio-8080" ] Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol pause INFO: Pausing ProtocolHandler [ "ajp-bio-8009" ] Jul 28, 2013 9:56:09 AM org.apache.catalina.core.StandardService stopInternal INFO: Stopping service Catalina Jul 28, 2013 9:56:09 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@648bfdea]) and a value of type [org.apache.logging.log4j.core.async.AsyncLogger.Info] (value [org.apache.logging.log4j.core.async.AsyncLogger$Info@4e26d560]) 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 9:56:09 AM org.apache.coyote.AbstractProtocol stop INFO: Stopping ProtocolHandler [ "http-bio-8080" ] Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol stop INFO: Stopping ProtocolHandler [ "ajp-bio-8009" ] Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol destroy INFO: Destroying ProtocolHandler [ "http-bio-8080" ] Jul 28, 2013 9:56:09 AM org.apache.coyote.AbstractProtocol destroy INFO: Destroying ProtocolHandler [ "ajp-bio-8009" ] web.xml <?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_3_0.xsd" version= "3.0" metadata-complete= "true" > <description> Async Log Server Example </description> <display-name> Async Log Server Example </display-name> </web-app> catalina.properties tomcat.util.scan.DefaultJarScanner.jarsToSkip=\ bootstrap.jar,commons-daemon.jar,tomcat-juli.jar,\ annotations-api.jar,el-api.jar,jsp-api.jar,servlet-api.jar,\ catalina.jar,catalina-ant.jar,catalina-ha.jar,catalina-tribes.jar,\ jasper.jar,jasper-el.jar,ecj-*.jar,\ tomcat-api.jar,tomcat-util.jar,tomcat-coyote.jar,tomcat-dbcp.jar,\ tomcat-jni.jar,tomcat-spdy.jar,\ tomcat-i18n-en.jar,tomcat-i18n-es.jar,tomcat-i18n-fr.jar,tomcat-i18n-ja.jar,\ tomcat-juli-adapters.jar,catalina-jmx-remote.jar,catalina-ws.jar,\ tomcat-jdbc.jar,\ tools.jar,\ commons-beanutils*.jar,commons-codec*.jar,commons-collections*.jar,\ commons-dbcp*.jar,commons-digester*.jar,commons-fileupload*.jar,\ commons-httpclient*.jar,commons-io*.jar,commons-lang*.jar,commons-logging*.jar,\ commons-math*.jar,commons-pool*.jar,\ jstl.jar,\ geronimo-spec-jaxrpc*.jar,wsdl4j*.jar,\ ant.jar,ant-junit*.jar,aspectj*.jar,jmx.jar,h2*.jar,hibernate*.jar,httpclient*.jar,\ jmx-tools.jar,jta*.jar,mail*.jar,slf4j*.jar,\ xercesImpl.jar,xmlParserAPIs.jar,xml-apis.jar,\ junit.jar,junit-*.jar,ant-launcher.jar I don't mean for you to debug my code. I apologize in advance if I've missed anything obvious (again!).
          Hide
          Nick Williams added a comment -

          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.

          Show
          Nick Williams added a comment - 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 .
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Resolved Resolved
          2d 2h 22m 1 Ralph Goers 30/Apr/13 04:48

            People

            • Assignee:
              Unassigned
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development