Merge pull request #385 from Thihup/fix-log4j1-msg
Replace {}} with {}diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java
index be34e09..a506619 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java
@@ -27,6 +27,7 @@
import org.apache.logging.log4j.core.impl.MutableLogEvent;
import org.apache.logging.log4j.core.impl.ReusableLogEventFactory;
import org.apache.logging.log4j.core.jmx.RingBufferAdmin;
+import org.apache.logging.log4j.core.util.Log4jThread;
import org.apache.logging.log4j.core.util.Log4jThreadFactory;
import org.apache.logging.log4j.core.util.Throwables;
import org.apache.logging.log4j.message.ReusableMessage;
@@ -383,7 +384,12 @@
private boolean synchronizeEnqueueWhenQueueFull() {
return DisruptorUtil.ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
// Background thread must never block
- && backgroundThreadId != Thread.currentThread().getId();
+ && backgroundThreadId != Thread.currentThread().getId()
+ // Threads owned by log4j are most likely to result in
+ // deadlocks because they generally consume events.
+ // This prevents deadlocks between AsyncLoggerContext
+ // disruptors.
+ && !(Thread.currentThread() instanceof Log4jThread);
}
@Override
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
index e8c0121..377100e 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
@@ -25,6 +25,7 @@
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.AbstractLifeCycle;
import org.apache.logging.log4j.core.jmx.RingBufferAdmin;
+import org.apache.logging.log4j.core.util.Log4jThread;
import org.apache.logging.log4j.core.util.Log4jThreadFactory;
import org.apache.logging.log4j.core.util.Throwables;
@@ -85,6 +86,11 @@
contextName);
return;
}
+ if (isStarting()) {
+ LOGGER.trace("[{}] AsyncLoggerDisruptor is already starting.", contextName);
+ return;
+ }
+ setStarting();
LOGGER.trace("[{}] AsyncLoggerDisruptor creating new disruptor for this context.", contextName);
ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLogger.RingBufferSize");
final WaitStrategy waitStrategy = DisruptorUtil.createWaitStrategy("AsyncLogger.WaitStrategy");
@@ -281,7 +287,12 @@
private boolean synchronizeEnqueueWhenQueueFull() {
return DisruptorUtil.ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
// Background thread must never block
- && backgroundThreadId != Thread.currentThread().getId();
+ && backgroundThreadId != Thread.currentThread().getId()
+ // Threads owned by log4j are most likely to result in
+ // deadlocks because they generally consume events.
+ // This prevents deadlocks between AsyncLoggerContext
+ // disruptors.
+ && !(Thread.currentThread() instanceof Log4jThread);
}
private void logWarningOnNpeFromDisruptorPublish(final RingBufferLogEventTranslator translator) {
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java
index 1d48113..d3d53e1 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java
@@ -17,6 +17,7 @@
package org.apache.logging.log4j.core.async;
import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.util.Log4jThread;
/**
* Default router: enqueue the event for asynchronous logging in the background thread, unless the current thread is the
@@ -29,7 +30,13 @@
// LOG4J2-471: prevent deadlock when RingBuffer is full and object
// being logged calls Logger.log() from its toString() method
- if (Thread.currentThread().getId() == backgroundThreadId) {
+ Thread currentThread = Thread.currentThread();
+ if (currentThread.getId() == backgroundThreadId
+ // Threads owned by log4j are most likely to result in
+ // deadlocks because they generally consume events.
+ // This prevents deadlocks between AsyncLoggerContext
+ // disruptors.
+ || currentThread instanceof Log4jThread) {
return EventRoute.SYNCHRONOUS;
}
return EventRoute.ENQUEUE;
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java
index 0299541..5925187 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java
@@ -17,7 +17,6 @@
package org.apache.logging.log4j.core.async;
-import java.util.Locale;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Future;
@@ -36,6 +35,7 @@
import org.apache.logging.log4j.core.util.Loader;
import org.apache.logging.log4j.status.StatusLogger;
import org.apache.logging.log4j.util.PropertiesUtil;
+import org.apache.logging.log4j.util.Strings;
/**
* Utility methods for getting Disruptor related configuration.
@@ -60,36 +60,46 @@
private DisruptorUtil() {
}
- static long getTimeout(final String propertyName, final long defaultTimeout) {
- return PropertiesUtil.getProperties().getLongProperty(propertyName, defaultTimeout);
- }
-
static WaitStrategy createWaitStrategy(final String propertyName) {
- final String key = propertyName.startsWith("AsyncLogger.")
- ? "AsyncLogger.Timeout"
- : "AsyncLoggerConfig.Timeout";
- final long timeoutMillis = DisruptorUtil.getTimeout(key, 10L);
- return createWaitStrategy(propertyName, timeoutMillis);
+ final String strategy = PropertiesUtil.getProperties().getStringProperty(propertyName, "Timeout");
+ LOGGER.trace("property {}={}", propertyName, strategy);
+ final String strategyUp = Strings.toRootUpperCase(strategy);
+ final long timeoutMillis = parseAdditionalLongProperty(propertyName, "Timeout", 10L);
+ // String (not enum) is deliberately used here to avoid IllegalArgumentException being thrown. In case of
+ // incorrect property value, default WaitStrategy is created.
+ switch (strategyUp) {
+ case "SLEEP":
+ final long sleepTimeNs =
+ parseAdditionalLongProperty(propertyName, "SleepTimeNs", 100L);
+ final String key = getFullPropertyKey(propertyName, "Retries");
+ final int retries =
+ PropertiesUtil.getProperties().getIntegerProperty(key, 200);
+ return new SleepingWaitStrategy(retries, sleepTimeNs);
+ case "YIELD":
+ return new YieldingWaitStrategy();
+ case "BLOCK":
+ return new BlockingWaitStrategy();
+ case "BUSYSPIN":
+ return new BusySpinWaitStrategy();
+ case "TIMEOUT":
+ return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
+ default:
+ return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
+ }
}
- static WaitStrategy createWaitStrategy(final String propertyName, final long timeoutMillis) {
- final String strategy = PropertiesUtil.getProperties().getStringProperty(propertyName, "TIMEOUT");
- LOGGER.trace("property {}={}", propertyName, strategy);
- final String strategyUp = strategy.toUpperCase(Locale.ROOT); // TODO Refactor into Strings.toRootUpperCase(String)
- switch (strategyUp) { // TODO Define a DisruptorWaitStrategy enum?
- case "SLEEP":
- return new SleepingWaitStrategy();
- case "YIELD":
- return new YieldingWaitStrategy();
- case "BLOCK":
- return new BlockingWaitStrategy();
- case "BUSYSPIN":
- return new BusySpinWaitStrategy();
- case "TIMEOUT":
- return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
- default:
- return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
- }
+ private static String getFullPropertyKey(final String strategyKey, final String additionalKey) {
+ return strategyKey.startsWith("AsyncLogger.")
+ ? "AsyncLogger." + additionalKey
+ : "AsyncLoggerConfig." + additionalKey;
+ }
+
+ private static long parseAdditionalLongProperty(
+ final String propertyName,
+ final String additionalKey,
+ long defaultValue) {
+ final String key = getFullPropertyKey(propertyName, additionalKey);
+ return PropertiesUtil.getProperties().getLongProperty(key, defaultValue);
}
static int calculateRingBufferSize(final String propertyName) {
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
index c777cae..c536c04 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java
@@ -37,7 +37,7 @@
public class RingBufferLogEventTranslator implements
EventTranslator<RingBufferLogEvent> {
- private final ContextDataInjector injector = ContextDataInjectorFactory.createInjector();
+ private static final ContextDataInjector INJECTOR = ContextDataInjectorFactory.createInjector();
private AsyncLogger asyncLogger;
String loggerName;
protected Marker marker;
@@ -60,7 +60,7 @@
event.setValues(asyncLogger, loggerName, marker, fqcn, level, message, thrown,
// config properties are taken care of in the EventHandler thread
// in the AsyncLogger#actualAsyncLog method
- injector.injectContextData(null, (StringMap) event.getContextData()), contextStack,
+ INJECTOR.injectContextData(null, (StringMap) event.getContextData()), contextStack,
threadId, threadName, threadPriority, location, clock, nanoClock);
clear(); // clear the translator
diff --git a/log4j-jul/pom.xml b/log4j-jul/pom.xml
index 3fa00b9..64d7040 100644
--- a/log4j-jul/pom.xml
+++ b/log4j-jul/pom.xml
@@ -60,6 +60,12 @@
<artifactId>junit</artifactId>
<scope>test</scope>
</dependency>
+ <!-- Required for AsyncLogger testing -->
+ <dependency>
+ <groupId>com.lmax</groupId>
+ <artifactId>disruptor</artifactId>
+ <scope>test</scope>
+ </dependency>
</dependencies>
<build>
diff --git a/log4j-jul/src/test/java/org/apache/logging/log4j/jul/AsyncLoggerThreadsTest.java b/log4j-jul/src/test/java/org/apache/logging/log4j/jul/AsyncLoggerThreadsTest.java
new file mode 100644
index 0000000..3ca72e6
--- /dev/null
+++ b/log4j-jul/src/test/java/org/apache/logging/log4j/jul/AsyncLoggerThreadsTest.java
@@ -0,0 +1,64 @@
+/*
+ * 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.jul;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.categories.AsyncLoggers;
+import org.apache.logging.log4j.core.CoreLoggerContexts;
+import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector;
+import org.apache.logging.log4j.core.config.ConfigurationFactory;
+import org.apache.logging.log4j.core.util.Constants;
+import org.junit.AfterClass;
+import org.junit.BeforeClass;
+import org.junit.Test;
+import org.junit.experimental.categories.Category;
+
+import java.io.BufferedReader;
+import java.io.File;
+import java.io.FileReader;
+import java.util.List;
+import java.util.stream.Collectors;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertTrue;
+
+@Category(AsyncLoggers.class)
+public class AsyncLoggerThreadsTest {
+
+ @BeforeClass
+ public static void beforeClass() {
+ System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR,
+ AsyncLoggerContextSelector.class.getName());
+ System.setProperty("java.util.logging.manager", org.apache.logging.log4j.jul.LogManager.class.getName());
+ }
+
+ @AfterClass
+ public static void afterClass() {
+ System.clearProperty(Constants.LOG4J_CONTEXT_SELECTOR);
+ System.clearProperty("java.util.logging.manager");
+ }
+
+ @Test
+ public void testAsyncLoggerThreads() {
+ LogManager.getLogger("com.foo.Bar").info("log");
+ List<Thread> asyncLoggerThreads = Thread.getAllStackTraces().keySet().stream()
+ .filter(thread -> thread.getName().matches("Log4j2-TF.*AsyncLogger.*"))
+ .collect(Collectors.toList());
+ assertEquals(asyncLoggerThreads.toString(), 1, asyncLoggerThreads.size());
+ }
+}
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index 23d7619..517b2a3 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -190,6 +190,20 @@
<action issue="LOG4J2-2851" dev="ggregory" type="remove">
Drop log4j-mongodb2 module.
</action>
+ <action issue="LOG4J2-2895" dev="ckozak" type="fix">
+ Fix potential deadlock in asynchronous logging by avoiding blocking for queue space on Log4jThreads
+ </action>
+ <action issue="LOG4J2-2837" dev="ckozak" type="fix">
+ Disruptor and JUL no longer recursively start the AsyncLoggerDisruptor
+ resulting in an extra disruptor background thread constantly waiting.
+ </action>
+ <action issue="LOG4J2-2867" dev="ckozak" type="fix">
+ RingBufferLogEventTranslator uses a static ContextDataInjector instead of initializing a new object
+ on each thread.
+ </action>
+ <action issue="LOG4J2-2858" dev="ckozak" type="add" due-to="Stepan Gorban">
+ More flexible configuration of the Disruptor WaitStrategy.
+ </action>
</release>
<release version="2.13.3" date="2020-05-10" description="GA Release 2.13.3">
<action issue="LOG4J2-2838" dev="rgoers" type="fix">
diff --git a/src/site/asciidoc/manual/async.adoc b/src/site/asciidoc/manual/async.adoc
index 3b63d62..c89921b 100644
--- a/src/site/asciidoc/manual/async.adoc
+++ b/src/site/asciidoc/manual/async.adoc
@@ -209,7 +209,7 @@
is determined by the
link:../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html[AsyncQueueFullPolicy].
-|log4j2.asyncLoggerWaitStrategy
+|[[asyncLoggerWaitStrategy]]log4j2.asyncLoggerWaitStrategy
|`Timeout`
|Valid values: Block,
Timeout, Sleep, Yield.
@@ -232,6 +232,23 @@
performance and CPU resource, but may use more CPU than Sleep in order
to get the message logged to disk sooner.
+|log4j2.asyncLoggerTimeout
+|`10`
+|Timeout in milliseconds of `TimeoutBlockingWaitStrategy`. See
+link:#asyncLoggerWaitStrategy[WaitStrategy System Property] for details.
+
+|log4j2.asyncLoggerSleepTimeNs
+|`100`
+|Sleep time (in nanoseconds) of `SleepingWaitStrategy`. See
+link:#asyncLoggerWaitStrategy[WaitStrategy System Property] for details.
+
+|log4j2.asyncLoggerRetries
+|`200`
+|Total number of spin cycles and `Thread.yield()` cycles of `SleepingWaitStrategy`. See
+link:#asyncLoggerWaitStrategy[WaitStrategy System Property] for details.
+
+
+
|AsyncLogger.SynchronizeEnqueueWhenQueueFull
|`true`
|Synchronizes access to the Disruptor ring buffer for blocking enqueue operations when the queue is full.
@@ -375,7 +392,7 @@
is determined by the
link:../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html[AsyncQueueFullPolicy].
-|log4j2.asyncLoggerConfigWaitStrategy
+|[[asyncLoggerConfigWaitStrategy]]log4j2.asyncLoggerConfigWaitStrategy
|`Timeout`
|Valid values: Block,
Timeout, Sleep, Yield. +
@@ -398,6 +415,21 @@
performance and CPU resource, but may use more CPU than Sleep in order
to get the message logged to disk sooner.
+|log4j2.asyncLoggerConfigTimeout
+|`10`
+|Timeout in milliseconds of `TimeoutBlockingWaitStrategy`. See
+link:#asyncLoggerConfigWaitStrategy[WaitStrategy System Property] for details.
+
+|log4j2.asyncLoggerConfigSleepTimeNs
+|`100`
+|Sleep time (in nanoseconds) of `SleepingWaitStrategy`. See
+link:#asyncLoggerConfigWaitStrategy[WaitStrategy System Property] for details.
+
+|log4j2.asyncLoggerConfigRetries
+|`200`
+|Total number of spin cycles and `Thread.yield()` cycles of `SleepingWaitStrategy`. See
+link:#asyncLoggerConfigWaitStrategy[WaitStrategy System Property] for details.
+
|AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull
|`true`
|Synchronizes access to the Disruptor ring buffer for blocking enqueue operations when the queue is full.
diff --git a/src/site/asciidoc/manual/configuration.adoc b/src/site/asciidoc/manual/configuration.adoc
index 21bb180..1ff74b1 100644
--- a/src/site/asciidoc/manual/configuration.adoc
+++ b/src/site/asciidoc/manual/configuration.adoc
@@ -2056,6 +2056,30 @@
link:async.html#SysPropsAllAsync[Async Logger System Properties] for
details.
+|[[asyncLoggerTimeout]]log4j2.asyncLoggerTimeout +
+([[AsyncLogger.Timeout]]AsyncLogger.Timeout)
+|LOG4J_ASYNC_LOGGER_TIMEOUT
+|10
+|See
+link:async.html#SysPropsAllAsync[Async Logger System Properties] for
+details.
+
+|[[asyncLoggerSleepTimeNs]]log4j2.asyncLoggerSleepTimeNs +
+([[AsyncLogger.SleepTimeNs]]AsyncLogger.SleepTimeNs)
+|LOG4J_ASYNC_LOGGER_SLEEP_TIME_NS
+|100
+|See
+link:async.html#SysPropsAllAsync[Async Logger System Properties] for
+details.
+
+|[[asyncLoggerRetries]]log4j2.asyncLoggerRetries +
+([[AsyncLogger.Retries]]AsyncLogger.Retries)
+|LOG4J_ASYNC_LOGGER_RETRIES
+|200
+|See
+link:async.html#SysPropsAllAsync[Async Logger System Properties] for
+details.
+
|[[AsyncLogger.SynchronizeEnqueueWhenQueueFull]]AsyncLogger.SynchronizeEnqueueWhenQueueFull
|ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
|true
@@ -2095,6 +2119,31 @@
link:async.html#SysPropsMixedSync-Async[Mixed Async/Synchronous Logger
System Properties] for details.
+|[[asyncLoggerConfigTimeout]]log4j2.asyncLoggerConfigTimeout +
+([[AsyncLoggerConfig.Timeout]]AsyncLoggerConfig.Timeout)
+|LOG4J_ASYNC_LOGGER_CONFIG_TIMEOUT
+|10
+|See
+link:async.html#SysPropsMixedSync-Async[Mixed Async/Synchronous Logger
+System Properties] for details.
+
+|[[asyncLoggerConfigSleepTimeNs]]log4j2.asyncLoggerConfigSleepTimeNs +
+([[AsyncLoggerConfig.SleepTimeNs]]AsyncLoggerConfig.SleepTimeNs)
+|LOG4J_ASYNC_LOGGER_CONFIG_SLEEP_TIME_NS
+|100
+|See
+link:async.html#SysPropsMixedSync-Async[Mixed Async/Synchronous Logger
+System Properties] for details.
+
+|[[asyncLoggerConfigRetries]]log4j2.asyncLoggerConfigRetries +
+([[AsyncLoggerConfig.Retries]]AsyncLoggerConfig.Retries)
+|LOG4J_ASYNC_LOGGER_CONFIG_RETRIES
+|200
+|See
+link:async.html#SysPropsMixedSync-Async[Mixed Async/Synchronous Logger
+System Properties] for details.
+
+
|[[AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull]]AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull
|ASYNC_LOGGER_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
|true
