logging-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From rpo...@apache.org
Subject svn commit: r1555336 - in /logging/log4j/log4j2/trunk: log4j-core/src/main/java/org/apache/logging/log4j/core/async/ log4j-core/src/test/java/org/apache/logging/log4j/core/async/ src/changes/
Date Sat, 04 Jan 2014 08:56:15 GMT
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>



Mime
View raw message