[LOG4J2-323] ThreadLocal-leak on tomcat shutdown when using async logging

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0-beta9
• Fix Version/s: 2.3, 2.5
• Labels: Async

Environment

Mac OS X 10.8.4, Tomcat 7.0.42, java version 1.6.0_51

• Assignee: Remko Popma
• Reporter: Michael Kloster
• Created: 28/Jul/13 16:46
• Updated: 12/Sep/20 16:00
• Resolved: 23/Oct/15 17:00

Description

When shutting down Tomcat 7.0.42, catalina.out displays the following warning indicating a memory leak:

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"]

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>

log4j2.xml

#!/bin/bash

CATALINA_OPTS=-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

Issue Links

• incorporates: LOG4J2-1172 ThreadLocal leak [AsyncLogger$Info] on Tomcat when using AsyncLoggerContextSelector
• is duplicated by: LOG4J2-425 Permgen leak in AsyncLoggerConfigHelper
• is part of: LOG4J2-493 Problem with AsyncLogger when web app is deployed/undeployed multiple times
• is related to: LOG4J2-2919 "AsyncAppender is not active" when logging with AsynAppender while the system is reconfigure concurrently
• is superceded by: LOG4J2-1159 ThreadLocal leaks in Tomcat8 (even if Async Loggers are not used)
• relates to: LOG4J2-1171 LoggerContext names in web apps are cryptic