Hello,
We are using async loggers in our log4j2.xml, enabling
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContex
tSelector when we start tomcat.
When tomcat starts, we can see:
2018-08-07 21:03:56,535 localhost-startStop-1 TRACE Using default
SystemClock for timestamps.
2018-08-07 21:03:56,536 localhost-startStop-1 TRACE Using DummyNanoClock for
nanosecond timestamps.
2018-08-07 21:03:56,536 localhost-startStop-1 DEBUG Reconfiguration complete
for context[name=AsyncContext@4d8d549e] at URI
/home/ventusproxy/app/ROOT/WEB-INF/log4j.xml
(org.apache.logging.log4j.core.async.AsyncLoggerContext@2c9ae56e) with
optional ClassLoader: null
2018-08-07 21:03:56,536 localhost-startStop-1 DEBUG Shutdown hook enabled.
Registering a new one.
2018-08-07 21:03:56,537 localhost-startStop-1 DEBUG
LoggerContext[name=AsyncContext@4d8d549e,
org.apache.logging.log4j.core.async.AsyncLoggerContext@2c9ae56e] started OK.
2018-08-07 21:03:56,538 localhost-startStop-1 TRACE Using default
SystemClock for timestamps.
2018-08-07 21:03:56,539 localhost-startStop-1 DEBUG
AsyncLogger.ThreadNameStrategy=CACHED
2018-08-07 21:03:56,556 Log4j2-TF-1-AsyncLogger[AsyncContext@4d8d549e]-1
DEBUG Now writing to /home/ventusproxy/logs/vproxy_system.2018-08-07 at
2018-08-07T21:03:56.556-0400
2018-08-07 21:03:57,081 localhost-startStop-1 DEBUG PluginManager
'Converter' found 42 plugins
2018-08-07 21:03:57,082 localhost-startStop-1 DEBUG Starting
OutputStreamManager SYSTEM_OUT.false.false-2
2018-08-07 21:03:57,083 localhost-startStop-1 TRACE
[DefaultAsyncContext@localhost-startStop-1] AsyncLoggerDisruptor creating
new disruptor for this context.
2018-08-07 21:03:57,083 localhost-startStop-1 TRACE property
AsyncLogger.WaitStrategy=TIMEOUT
2018-08-07 21:03:57,092 localhost-startStop-1 DEBUG
[DefaultAsyncContext@localhost-startStop-1] Starting AsyncLogger disruptor
for this context with ringbufferSize=262144,
waitStrategy=TimeoutBlockingWaitStrategy,
exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerDefaultExcep
tionHandler@71fd86cb...
2018-08-07 21:03:57,093 localhost-startStop-1 TRACE
[DefaultAsyncContext@localhost-startStop-1] AsyncLoggers use a threadlocal
translator
2018-08-07 21:03:57,093 localhost-startStop-1 DEBUG Starting
LoggerContext[name=DefaultAsyncContext@localhost-startStop-1,
org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d]...
2018-08-07 21:03:57,094 localhost-startStop-1 DEBUG Reconfiguration started
for context[name=DefaultAsyncContext@localhost-startStop-1] at URI null
(org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d) with
optional ClassLoader: null
2018-08-07 21:03:57,094 localhost-startStop-1 DEBUG Using
configurationFactory
org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@4b6e6fdf
2018-08-07 21:03:57,133 localhost-startStop-1 DEBUG Initializing
configuration
XmlConfiguration[location=/home/ventusproxy/app/ROOT/WEB-INF/log4j.xml]
And finally (last debug line):
2018-08-07 21:03:57,200 localhost-startStop-1 DEBUG
LoggerContext[name=DefaultAsyncContext@localhost-startStop-1,
org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d] started OK.
When we perform a thread dump with JStack we see 2 threads:
"Log4j2-TF-7-AsyncLogger[DefaultAsyncContext@localhost-startStop-1]-2" #23
daemon prio=5 os_prio=0 tid=0x00007f1ee8ad9800 nid=0x625d runnable
[0x00007f1f05817000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000925d3ad8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
at
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
at
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
"Log4j2-TF-1-AsyncLogger[AsyncContext@4d8d549e]-1" #21 daemon prio=5
os_prio=0 tid=0x00007f1ee88d8800 nid=0x625c runnable [0x00007f1f06073000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000093099540> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
at
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
at
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
And when we stop tomcat, all these errors are logged:
07-Aug-2018 21:07:29.991 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The
web application [ROOT] appears to have started a thread named
[Log4j2-TF-7-AsyncLogger[DefaultAsyncContext@localhost-startStop-1]-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.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
java.lang.Thread.run(Thread.java:748)
07-Aug-2018 21:07:29.993 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@494a6bc6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@46d89786])
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.
07-Aug-2018 21:07:29.993 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@494a6bc6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@7fca5b63])
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.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@7d2c87bb]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@316c8d06])
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.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@74afa5d5]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@5913f960])
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.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@401baca6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@154a0d1e])
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.
07-Aug-2018 21:07:29.995 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1cc2936f]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@5a5ca16e])
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.
07-Aug-2018 21:07:29.995 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@473f581f]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@2d89f1b])
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.
So:
1. With these traces can I confirm I'm using full asynchronous
logging?
2. I've read that async logging starts just one thread, but here I see
2 (like when we mix sync and async logging). Is this true?
3. How can I remove these errors from the catalina.out? The
application stops correctly so these messages are not really a problem, but
I'd prefer to remove them if it's possible.
Thanks,
Joan.
