Author: rpopma
Date: Sat Jan 4 08:56:15 2014
New Revision: 1555336
URL: http://svn.apache.org/r1555336
Log:
LOG4J2-471: Fixed issue where toString methods that perform logging could
deadlock AsyncLogger.
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerThreadNameStrategyTest.java
logging/log4j/log4j2/trunk/src/changes/changes.xml
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
URL:
http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1555336&r1=1555335&r2=1555336&view=diff
==============================================================================
---
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
(original)
+++
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
Sat Jan 4 08:56:15 2014
@@ -112,6 +112,7 @@ public class AsyncLogger extends Logger
private static ThreadLocal<Info> threadlocalInfo = new ThreadLocal<Info>();
static {
+ initInfoForExecutorThread();
LOGGER.debug("AsyncLogger.ThreadNameStrategy={}",
THREAD_NAME_STRATEGY);
final int ringBufferSize = calculateRingBufferSize();
@@ -146,6 +147,24 @@ public class AsyncLogger extends Logger
return Util.ceilingNextPowerOfTwo(ringBufferSize);
}
+ /**
+ * Initialize an {@code Info} object that is threadlocal to the
consumer/appender thread.
+ * This Info object uniquely has attribute {@code isAppenderThread} set to
{@code true}.
+ * All other Info objects will have this attribute set to {@code false}.
+ * This allows us to detect Logger.log() calls initiated from the appender
thread,
+ * which may cause deadlock when the RingBuffer is full. (LOG4J2-471)
+ */
+ private static void initInfoForExecutorThread() {
+ executor.submit(new Runnable(){
+ public void run() {
+ final boolean isAppenderThread = true;
+ final Info info = new Info(new RingBufferLogEventTranslator(),
//
+ Thread.currentThread().getName(), isAppenderThread);
+ threadlocalInfo.set(info);
+ }
+ });
+ }
+
private static WaitStrategy createWaitStrategy() {
final String strategy = System.getProperty("AsyncLogger.WaitStrategy");
LOGGER.debug("property AsyncLogger.WaitStrategy={}", strategy);
@@ -199,9 +218,11 @@ public class AsyncLogger extends Logger
static class Info {
private final RingBufferLogEventTranslator translator;
private final String cachedThreadName;
- public Info(RingBufferLogEventTranslator translator, String
threadName) {
+ private final boolean isAppenderThread;
+ public Info(RingBufferLogEventTranslator translator, String
threadName, boolean appenderThread) {
this.translator = translator;
this.cachedThreadName = threadName;
+ this.isAppenderThread = appenderThread;
}
}
@@ -209,10 +230,17 @@ public class AsyncLogger extends Logger
public void log(final Marker marker, final String fqcn, final Level level,
final Message data, final Throwable t) {
Info info = threadlocalInfo.get();
if (info == null) {
- info = new Info(new RingBufferLogEventTranslator(),
Thread.currentThread().getName());
+ info = new Info(new RingBufferLogEventTranslator(),
Thread.currentThread().getName(), false);
threadlocalInfo.set(info);
}
-
+
+ // LOG4J2-471: prevent deadlock when RingBuffer is full and object
+ // being logged calls Logger.log() from its toString() method
+ if (info.isAppenderThread &&
disruptor.getRingBuffer().remainingCapacity() == 0) {
+ // bypass RingBuffer and invoke Appender directly
+ config.loggerConfig.log(getName(), marker, fqcn, level, data, t);
+ return;
+ }
final boolean includeLocation =
config.loggerConfig.isIncludeLocation();
info.translator.setValues(this, getName(), marker, fqcn, level, data,
t, //
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
URL:
http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java?rev=1555336&r1=1555335&r2=1555336&view=diff
==============================================================================
---
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
(original)
+++
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
Sat Jan 4 08:56:15 2014
@@ -107,7 +107,9 @@ public class AsyncLoggerConfig extends L
event.getThreadName();
// pass on the event to a separate thread
- helper.callAppendersFromAnotherThread(event);
+ if (!helper.callAppendersFromAnotherThread(event)) {
+ super.callAppenders(event);
+ }
}
/** Called by AsyncLoggerConfigHelper.RingBufferLog4jEventHandler. */
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
URL:
http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1555336&r1=1555335&r2=1555336&view=diff
==============================================================================
---
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
(original)
+++
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
Sat Jan 4 08:56:15 2014
@@ -70,6 +70,7 @@ class AsyncLoggerConfigHelper {
private static ExecutorService executor;
private static volatile int count = 0;
+ private static ThreadLocal<Boolean> isAppenderThread = new
ThreadLocal<Boolean>();
/**
* Factory used to populate the RingBuffer with events. These event objects
@@ -112,6 +113,7 @@ class AsyncLoggerConfigHelper {
final int ringBufferSize = calculateRingBufferSize();
final WaitStrategy waitStrategy = createWaitStrategy();
executor = Executors.newSingleThreadExecutor(threadFactory);
+ initThreadLocalForExecutorThread();
disruptor = new Disruptor<Log4jEventWrapper>(FACTORY, ringBufferSize,
executor, ProducerType.MULTI, waitStrategy);
final EventHandler<Log4jEventWrapper>[] handlers = new
Log4jEventWrapperHandler[] {//
@@ -279,9 +281,45 @@ class AsyncLoggerConfigHelper {
executor.shutdown(); // finally, kill the processor thread
executor = null; // release reference to allow GC
}
-
- public void callAppendersFromAnotherThread(final LogEvent event) {
+
+ /**
+ * Initialize the threadlocal that allows us to detect Logger.log() calls
+ * initiated from the appender thread, which may cause deadlock when the
+ * RingBuffer is full. (LOG4J2-471)
+ */
+ private static void initThreadLocalForExecutorThread() {
+ executor.submit(new Runnable(){
+ public void run() {
+ isAppenderThread.set(Boolean.TRUE);
+ }
+ });
+ }
+
+ /**
+ * If possible, delegates the invocation to {@code callAppenders} to
another
+ * thread and returns {@code true}. If this is not possible (if it detects
+ * that delegating to another thread would cause deadlock because the
+ * current call to Logger.log() originated from the appender thread and the
+ * ringbuffer is full) then this method does nothing and returns {@code
false}.
+ * It is the responsibility of the caller to process the event when this
+ * method returns {@code false}.
+ *
+ * @param event the event to delegate to another thread
+ * @return {@code true} if delegation was successful, {@code false} if the
+ * calling thread needs to process the event itself
+ */
+ public boolean callAppendersFromAnotherThread(final LogEvent event) {
+
+ // LOG4J2-471: prevent deadlock when RingBuffer is full and object
+ // being logged calls Logger.log() from its toString() method
+ if (isAppenderThread.get() == Boolean.TRUE //
+ && disruptor.getRingBuffer().remainingCapacity() == 0) {
+
+ // bypass RingBuffer and invoke Appender directly
+ return false;
+ }
disruptor.getRingBuffer().publishEvent(translator, event,
asyncLoggerConfig);
+ return true;
}
/**
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerThreadNameStrategyTest.java
URL:
http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerThreadNameStrategyTest.java?rev=1555336&r1=1555335&r2=1555336&view=diff
==============================================================================
---
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerThreadNameStrategyTest.java
(original)
+++
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerThreadNameStrategyTest.java
Sat Jan 4 08:56:15 2014
@@ -44,7 +44,7 @@ public class AsyncLoggerThreadNameStrate
@Test
public void testUncachedThreadNameStrategyReturnsCurrentThreadName()
throws Exception {
- AsyncLogger.Info info = new AsyncLogger.Info(null, "original");
+ AsyncLogger.Info info = new AsyncLogger.Info(null, "original", false);
final String name1 = "MODIFIED-THREADNAME1";
Thread.currentThread().setName(name1);
assertEquals(name1,
AsyncLogger.ThreadNameStrategy.UNCACHED.getThreadName(info));
@@ -58,7 +58,7 @@ public class AsyncLoggerThreadNameStrate
public void testCachedThreadNameStrategyReturnsCachedThreadName() throws
Exception {
final String original = "Original-ThreadName";
Thread.currentThread().setName(original);
- AsyncLogger.Info info = new AsyncLogger.Info(null, original);
+ AsyncLogger.Info info = new AsyncLogger.Info(null, original, false);
assertEquals(original,
AsyncLogger.ThreadNameStrategy.CACHED.getThreadName(info));
final String name2 = "OTHER-THREADNAME2";
Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL:
http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1555336&r1=1555335&r2=1555336&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Sat Jan 4 08:56:15 2014
@@ -21,6 +21,9 @@
</properties>
<body>
<release version="2.0-RC1" date="2013-MM-DD" description="Bug fixes and
enhancements">
+ <action issue="LOG4J2-471" dev="rpopma" type="fix" due-to="Anthony
Baldocchi">
+ Fixed issue where toString methods that perform logging could deadlock
AsyncLogger.
+ </action>
<action issue="LOG4J2-482" dev="rpopma" type="add" due-to="Hongdi Ren">
Documentation fix: The attribute of Route to refer to an appender is
"ref" not "AppenderRef".
</action>
