[
https://issues.apache.org/jira/browse/LOG4J2-1259?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15940157#comment-15940157
]
Erko Hansar commented on LOG4J2-1259:
-------------------------------------
I had similar issues as Veit Guna and it took me a full day to figure out how
everything (log4j2 and spring mvc startup, tomcat jar scanning) works and to
come to a solution.
*Problem:* Tomcat production application server doesn't shutdown cleanly (it
tries, waits for 30 seconds and kills the process).
*Environment:* Linux, Java 1.8, Tomcat 8.0.23, Log4j 2.8.1, Spring MVC 4.2.6.
I have an empty web.xml file (nothing but the display-name and empty
welcome-file tags) with version="3.1". So all the Servlet 3.0 magic should work
out of the box.
I override the conf location with -Dlog4j.configurationFile=/etc/xxx/log4j2.xml.
*Symptoms:* Tomcat receives shutdown command, then Log4j completes a shutdown
BUT after 2 seconds Log4j "starts up again", Tomcat logs the running threads
warnings:
{noformat}
24-Mar-2017 09:10:13.842 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web
application [ROOT] appears to have started a thread named [pool-5-thread-1] but
has failed to stop it. This is very likely to create a memory leak. Stack trace
of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)
24-Mar-2017 09:10:13.842 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web
application [ROOT] appears to have started a thread named [pool-5-thread-2] but
has failed to stop it. This is very likely to create a memory leak. Stack trace
of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)
24-Mar-2017 09:10:13.843 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web
application [ROOT] appears to have started a thread named
[Log4j2-TF-10-Scheduled-11] but has failed to stop it. This is very likely to
create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)
24-Mar-2017 09:10:13.843 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web
application [ROOT] appears to have started a thread named
[AsyncAppender-AsyncMailer] but has failed to stop it. This is very likely to
create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.run(AsyncAppender.java:403)
{noformat}
Now shutdown script waits until 30 seconds is passed and then kills the process.
When I look at a web request exception stacktrace then I can see that the
filter order is incorrect: first CharacterEncodingFilter, then Spring Security
filters, *then Log4jServletFilter*, and then my own "non priority" filters.
NB1! The weird thing is, that the same tomcat version, conf and application on
my development Windows 10 machine boots up in correct order and Log4j is
initialized first, filter comes first and shutdown works.
*Cause:*
Tomcat 8.0.23 distribution comes with a conf/catalina.properties file where
*jarsToSkip* contains {code}log4j*.jar{code} but *jarsToScan* lists only
{code}log4j-core*.jar,log4j-taglib*.jar{code}, the log4j-web*.jar *is never
scanned* for TLD-s (doesn't matter) nor PLUGGABILITY (this matters). So the
web-fragment.xml with order tags is never processed. So the init order is not
correct and Spring happens to boot up first.
*Solution:*
I updated my catalina.properties to include log4j-web.jar in *jarsToScan*. So
now Tomcat reads both Log4j and Spring jars, and boots Log4j up first. This
results in a clean shutdown!
NB2! Tomcat 8.0.42 (latest in 8.0 branch) already has this fix in the
distribution.
*Log4j bug:* The http://logging.apache.org/log4j/2.x/manual/webapp.html manual
incorrectly states "This has been fixed in Tomcat 7.0.43, Tomcat 8, and
later.". Based on this statement I ignored the JAR scanning for quite a few
hours in my troubleshooting. It would help a lot if the manual describes how to
verify if your Servlet 3.0 magic works correctly (produce a web request stack
trace and see if the Log4j filter comes before Spring initialized filters) and
if not then you need to dig into your web.xml or JAR scanning.
> Log4j threads are leaking on Tomcat shutdown
> --------------------------------------------
>
> Key: LOG4J2-1259
> URL: https://issues.apache.org/jira/browse/LOG4J2-1259
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.5
> Reporter: Misagh Moayyed
>
> Running log4j2 v2.5 with disruptor 3.3.x. AsyncLoggers configured. log4j-web
> also included in the web application deployed in Tomcat 8. The context
> listener is correctly starting up and shutting down, catalina.properties does
> not include the log4j*.jar entry. Yet I see:
> {code}
> 20-Jan-2016 14:59:26.322 WARNING [localhost-startStop-2]
> org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The
> web application [cas-server-webapp-4.3.0-SNAPSHOT] appears to have started a
> thread named [Log4j2-Log4j2Scheduled-5] but has failed to stop it. This is
> very likely to create a memory leak. Stack trace of thread:
> sun.misc.Unsafe.park(Native Method)
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
>
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
>
> java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
>
> java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
> java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> java.lang.Thread.run(Thread.java:745)
> 20-Jan-2016 14:59:26.336 WARNING [localhost-startStop-2]
> org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The
> web application [cas-server-webapp-4.3.0-SNAPSHOT] appears to have started a
> thread named [Log4j2-AsyncLoggerConfig-6] but has failed to stop it. This is
> very likely to create a memory leak. Stack trace of thread:
> sun.misc.Unsafe.park(Native Method)
> java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
>
> com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> java.lang.Thread.run(Thread.java:745)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
