logging-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From rpo...@apache.org
Subject svn commit: r1513832 - in /logging/log4j/log4j2/trunk: core/src/main/java/org/apache/logging/log4j/core/async/ core/src/main/java/org/apache/logging/log4j/core/config/ core/src/test/java/org/apache/logging/log4j/core/async/ core/src/test/resources/ src...
Date Wed, 14 Aug 2013 12:19:35 GMT
Author: rpopma
Date: Wed Aug 14 12:19:35 2013
New Revision: 1513832

URL: http://svn.apache.org/r1513832
Log:
LOG4J2-336 AsyncLogger errors after multiple calls to LoggerContext.reconfigure()

Added:
    logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java
  (with props)
    logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml   (with
props)
Modified:
    logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
    logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
    logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/BaseConfiguration.java
    logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java
    logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest.xml
    logging/log4j/log4j2/trunk/src/changes/changes.xml

Modified: logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
(original)
+++ logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
Wed Aug 14 12:19:35 2013
@@ -121,19 +121,15 @@ public class AsyncLoggerConfig extends L
     public void startFilter() {
         if (helper == null) {
             helper = new AsyncLoggerConfigHelper(this);
+        } else {
+            AsyncLoggerConfigHelper.claim(); // LOG4J2-336
         }
         super.startFilter();
     }
 
     @Override
     public void stopFilter() {
-        /* only stop disruptor if shutting down logging subsystem
-        if (LogManager.getContext() instanceof LoggerContext) {
-            if (((LoggerContext) LogManager.getContext()).getStatus() != Status.STOPPING)
{
-                return;
-            }
-        } */
-        helper.shutdown();
+        AsyncLoggerConfigHelper.release();
         super.stopFilter();
     }
 

Modified: logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
(original)
+++ logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
Wed Aug 14 12:19:35 2013
@@ -18,6 +18,7 @@ package org.apache.logging.log4j.core.as
 
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+import java.util.concurrent.ThreadFactory;
 
 import org.apache.logging.log4j.Logger;
 import org.apache.logging.log4j.core.LogEvent;
@@ -62,10 +63,10 @@ class AsyncLoggerConfigHelper {
     private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
     private static final Logger LOGGER = StatusLogger.getLogger();
 
+    private static ThreadFactory threadFactory = new DaemonThreadFactory(
+            "AsyncLoggerConfig-");
     private static volatile Disruptor<Log4jEventWrapper> disruptor;
-    private static ExecutorService executor = Executors
-            .newSingleThreadExecutor(new DaemonThreadFactory(
-                    "AsyncLoggerConfig-"));
+    private static ExecutorService executor;
 
     private static volatile int count = 0;
 
@@ -97,26 +98,29 @@ class AsyncLoggerConfigHelper {
 
     public AsyncLoggerConfigHelper(final AsyncLoggerConfig asyncLoggerConfig) {
         this.asyncLoggerConfig = asyncLoggerConfig;
-        initDisruptor();
+        claim();
     }
 
     private static synchronized void initDisruptor() {
-        ++count;
         if (disruptor != null) {
+            LOGGER.trace("AsyncLoggerConfigHelper not starting new disruptor, using existing
object. Ref count is {}.", count);
             return;
         }
+        LOGGER.trace("AsyncLoggerConfigHelper creating new disruptor. Ref count is {}.",
count);
         final int ringBufferSize = calculateRingBufferSize();
         final WaitStrategy waitStrategy = createWaitStrategy();
+        executor = Executors.newSingleThreadExecutor(threadFactory);
         disruptor = new Disruptor<Log4jEventWrapper>(FACTORY, ringBufferSize,
                 executor, ProducerType.MULTI, waitStrategy);
         final EventHandler<Log4jEventWrapper>[] handlers = new Log4jEventWrapperHandler[]
{//
         new Log4jEventWrapperHandler() };
-        disruptor.handleExceptionsWith(getExceptionHandler());
+        final ExceptionHandler errorHandler = getExceptionHandler();
+        disruptor.handleExceptionsWith(errorHandler);
         disruptor.handleEventsWith(handlers);
 
         LOGGER.debug(
-                "Starting AsyncLoggerConfig disruptor with ringbuffer size {}...",
-                disruptor.getRingBuffer().getBufferSize());
+                "Starting AsyncLoggerConfig disruptor with ringbuffer size={}, waitStrategy={},
exceptionHandler={}...",
+                disruptor.getRingBuffer().getBufferSize(), waitStrategy.getClass().getSimpleName(),
errorHandler);
         disruptor.start();
     }
 
@@ -125,16 +129,12 @@ class AsyncLoggerConfigHelper {
                 .getProperty("AsyncLoggerConfig.WaitStrategy");
         LOGGER.debug("property AsyncLoggerConfig.WaitStrategy={}", strategy);
         if ("Sleep".equals(strategy)) {
-            LOGGER.debug("disruptor event handler uses SleepingWaitStrategy");
             return new SleepingWaitStrategy();
         } else if ("Yield".equals(strategy)) {
-            LOGGER.debug("disruptor event handler uses YieldingWaitStrategy");
             return new YieldingWaitStrategy();
         } else if ("Block".equals(strategy)) {
-            LOGGER.debug("disruptor event handler uses BlockingWaitStrategy");
             return new BlockingWaitStrategy();
         }
-        LOGGER.debug("disruptor event handler uses SleepingWaitStrategy");
         return new SleepingWaitStrategy();
     }
 
@@ -163,7 +163,6 @@ class AsyncLoggerConfigHelper {
         final String cls = System
                 .getProperty("AsyncLoggerConfig.ExceptionHandler");
         if (cls == null) {
-            LOGGER.debug("No AsyncLoggerConfig.ExceptionHandler specified");
             return null;
         }
         try {
@@ -171,7 +170,6 @@ class AsyncLoggerConfigHelper {
             final Class<? extends ExceptionHandler> klass = (Class<? extends ExceptionHandler>)
Class
                     .forName(cls);
             final ExceptionHandler result = klass.newInstance();
-            LOGGER.debug("AsyncLoggerConfig.ExceptionHandler=" + result);
             return result;
         } catch (final Exception ignored) {
             LOGGER.debug(
@@ -230,14 +228,33 @@ class AsyncLoggerConfigHelper {
         }
     }
 
-    public synchronized void shutdown() {
+    /**
+     * Increases the reference count and creates and starts a new Disruptor and
+     * associated thread if none currently exists.
+     * 
+     * @see #release()
+     */
+    synchronized static void claim() {
+        count++;
+        initDisruptor();
+    }
+
+    /**
+     * Decreases the reference count. If the reference count reached zero, the
+     * Disruptor and its associated thread are shut down and their references
+     * set to {@code null}.
+     */
+    synchronized static void release() {
         if (--count > 0) {
+            LOGGER.trace("AsyncLoggerConfigHelper: not shutting down disruptor: ref count
is {}.", count);
             return;
         }
         final Disruptor<Log4jEventWrapper> temp = disruptor;
         if (temp == null) {
+            LOGGER.trace("AsyncLoggerConfigHelper: disruptor already shut down: ref count
is {}.", count);
             return; // disruptor was already shut down by another thread
         }
+        LOGGER.trace("AsyncLoggerConfigHelper: shutting down disruptor: ref count is {}.",
count);
 
         // Must guarantee that publishing to the RingBuffer has stopped
         // before we call disruptor.shutdown()
@@ -258,6 +275,7 @@ class AsyncLoggerConfigHelper {
             }
         }
         executor.shutdown(); // finally, kill the processor thread
+        executor = null; // release reference to allow GC
     }
 
     public void callAppendersFromAnotherThread(final LogEvent event) {

Modified: logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/BaseConfiguration.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/BaseConfiguration.java?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/BaseConfiguration.java
(original)
+++ logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/config/BaseConfiguration.java
Wed Aug 14 12:19:35 2013
@@ -133,7 +133,7 @@ public class BaseConfiguration extends A
         for (final Appender appender : appenders.values()) {
             appender.start();
         }
-
+        root.startFilter(); // LOG4J2-336
         startFilter();
     }
 

Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java
(original)
+++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java
Wed Aug 14 12:19:35 2013
@@ -40,8 +40,8 @@ public class AsyncLoggerConfigTest {
     @Test
     public void testAdditivity() throws Exception {
         final File f = new File("target", "AsyncLoggerConfigTest.log");
-        // System.out.println(f.getAbsolutePath());
-        f.delete();
+        assertTrue("Deleted old file before test", !f.exists() || f.delete());
+        
         final Logger log = LogManager.getLogger("com.foo.Bar");
         final String msg = "Additive logging: 2 for the price of 1!";
         log.info(msg);
@@ -61,5 +61,4 @@ public class AsyncLoggerConfigTest {
         assertTrue("location",
                 line1.contains(location) || line2.contains(location));
     }
-
 }

Added: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java?rev=1513832&view=auto
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java
(added)
+++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java
Wed Aug 14 12:19:35 2013
@@ -0,0 +1,69 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core.async;
+
+import static org.junit.Assert.*;
+
+import java.io.BufferedReader;
+import java.io.File;
+import java.io.FileReader;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.LifeCycle;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.config.XMLConfigurationFactory;
+import org.junit.BeforeClass;
+import org.junit.Test;
+
+public class AsyncLoggerConfigTest2 {
+
+    @BeforeClass
+    public static void beforeClass() {
+    }
+
+    @Test
+    public void testConsecutiveReconfigure() throws Exception {
+        System.setProperty(XMLConfigurationFactory.CONFIGURATION_FILE_PROPERTY,
+                "AsyncLoggerConfigTest2.xml");
+        final File f = new File("target", "AsyncLoggerConfigTest2.log");
+        assertTrue("Deleted old file before test", !f.exists() || f.delete());
+        
+        final Logger log = LogManager.getLogger("com.foo.Bar");
+        final String msg = "Message before reconfig";
+        log.info(msg);
+
+        final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
+        ctx.reconfigure();
+        ctx.reconfigure();
+        
+        final String msg2 = "Message after reconfig";
+        log.info(msg2);
+        ((LifeCycle) LogManager.getContext()).stop(); // stop async thread
+
+        final BufferedReader reader = new BufferedReader(new FileReader(f));
+        final String line1 = reader.readLine();
+        final String line2 = reader.readLine();
+        reader.close();
+        f.delete();
+        assertNotNull("line1", line1);
+        assertNotNull("line2", line2);
+        assertTrue("line1 " + line1, line1.contains(msg));
+        assertTrue("line2 " + line2, line2.contains(msg2));
+    }
+
+}

Propchange: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest2.java
------------------------------------------------------------------------------
    svn:eol-style = native

Modified: logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest.xml?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest.xml (original)
+++ logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest.xml Wed Aug 14
12:19:35 2013
@@ -1,7 +1,11 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <configuration status="OFF">
   <appenders>
-    <File name="File" fileName="target/AsyncLoggerConfigTest.log" bufferedIO="false" immediateFlush="true"
append="false">
+    <File name="File" 
+          fileName="target/AsyncLoggerConfigTest.log" 
+          bufferedIO="false" 
+          immediateFlush="true" 
+          append="false">
       <PatternLayout>
         <pattern>%d %p %c{1.} [%t] %X{aKey} %m %location %ex%n</pattern>
       </PatternLayout>

Added: logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml?rev=1513832&view=auto
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml (added)
+++ logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml Wed Aug
14 12:19:35 2013
@@ -0,0 +1,20 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration status="TRACE">
+  <appenders>
+    <File name="File" 
+          fileName="target/AsyncLoggerConfigTest2.log" 
+          bufferedIO="false" 
+          immediateFlush="true" 
+          append="true">
+      <PatternLayout>
+        <pattern>%d %p %c{1.} [%t] %X{aKey} %m %location %ex%n</pattern>
+      </PatternLayout>
+    </File>
+  </appenders>
+  
+  <loggers>
+    <asyncRoot level="info">
+      <appender-ref ref="File"/>
+    </asyncRoot>
+  </loggers>
+</configuration>
\ No newline at end of file

Propchange: logging/log4j/log4j2/trunk/core/src/test/resources/AsyncLoggerConfigTest2.xml
------------------------------------------------------------------------------
    svn:eol-style = native

Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1513832&r1=1513831&r2=1513832&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Wed Aug 14 12:19:35 2013
@@ -21,6 +21,9 @@
   </properties>
   <body>
     <release version="2.0-beta9" date="soon, very soon" description="Bug fixes and enhancements">
+      <action issue="LOG4J2-336" dev="rpopma" type="fix" due-to="Andre Bogus">
+        AsyncLogger errors after multiple calls to LoggerContext.reconfigure().
+      </action>
       <action issue="LOG4J2-347" dev="rpopma" type="fix" due-to="David Phillips">
         Give the AsyncAppender thread a more descriptive name for easier debugging/profiling.
       </action>



Mime
View raw message