You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2013/08/14 14:19:35 UTC
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...
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>