You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by ck...@apache.org on 2020/07/16 20:36:26 UTC
[logging-log4j2] branch release-2.x updated (a2b91b2 -> cb3ee2b)
This is an automated email from the ASF dual-hosted git repository.
ckozak pushed a change to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git.
from a2b91b2 Merge pull request #386 from Thihup/fix-log4j1-msg-2
new 2a5665e LOG4J2-2895: Async logging avoids blocking on Log4jThreads
new 3134044 LOG4J2-2837: Disruptor and JUL no longer recursively start the AsyncLoggerDisruptor
new cb3ee2b LOG4J2-2867: RingBufferLogEventTranslator uses a static ContextDataInjector
The 3 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
Summary of changes:
.../core/async/AsyncLoggerConfigDisruptor.java | 8 +++-
.../log4j/core/async/AsyncLoggerDisruptor.java | 13 ++++++-
.../core/async/DefaultAsyncQueueFullPolicy.java | 9 ++++-
.../core/async/RingBufferLogEventTranslator.java | 4 +-
log4j-jul/pom.xml | 6 +++
.../logging/log4j/jul/AsyncLoggerThreadsTest.java | 45 +++++++++++-----------
src/changes/changes.xml | 11 ++++++
7 files changed, 69 insertions(+), 27 deletions(-)
copy log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerUseAfterShutdownTest.java => log4j-jul/src/test/java/org/apache/logging/log4j/jul/AsyncLoggerThreadsTest.java (58%)
[logging-log4j2] 03/03: LOG4J2-2867: RingBufferLogEventTranslator
uses a static ContextDataInjector
Posted by ck...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
ckozak pushed a commit to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit cb3ee2b6ef9d888c3b269b3fa8c0d1d9345ecc5c
Author: Carter Kozak <ck...@apache.org>
AuthorDate: Thu Jul 16 16:35:38 2020 -0400
LOG4J2-2867: RingBufferLogEventTranslator uses a static ContextDataInjector
Previously a new instance was created for each translator, which
occurred on every thread.
---
.../apache/logging/log4j/core/async/RingBufferLogEventTranslator.java | 4 ++--
src/changes/changes.xml | 4 ++++
2 files changed, 6 insertions(+), 2 deletions(-)
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 a6f5caf..417394b 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 @@ import com.lmax.disruptor.EventTranslator;
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 @@ public class RingBufferLogEventTranslator implements
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/src/changes/changes.xml b/src/changes/changes.xml
index c2c41ad..87470ec 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -82,6 +82,10 @@
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>
</release>
<release version="2.13.3" date="2020-05-10" description="GA Release 2.13.3">
<action issue="LOG4J2-2838" dev="rgoers" type="fix">
[logging-log4j2] 01/03: LOG4J2-2895: Async logging avoids blocking
on Log4jThreads
Posted by ck...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
ckozak pushed a commit to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 2a5665ef8216e753ae9cb4b6c40c8cb1342e6a04
Author: Carter Kozak <ck...@apache.org>
AuthorDate: Thu Jul 16 16:12:35 2020 -0400
LOG4J2-2895: Async logging avoids blocking on Log4jThreads
---
.../logging/log4j/core/async/AsyncLoggerConfigDisruptor.java | 8 +++++++-
.../apache/logging/log4j/core/async/AsyncLoggerDisruptor.java | 8 +++++++-
.../logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java | 9 ++++++++-
src/changes/changes.xml | 3 +++
4 files changed, 25 insertions(+), 3 deletions(-)
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.LogEventFactory;
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 @@ public class AsyncLoggerConfigDisruptor extends AbstractLifeCycle implements Asy
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..c51defa 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.Level;
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;
@@ -281,7 +282,12 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle {
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 @@ public class DefaultAsyncQueueFullPolicy implements AsyncQueueFullPolicy {
// 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/src/changes/changes.xml b/src/changes/changes.xml
index 9def922..51d10a3 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -75,6 +75,9 @@
<action dev="ggregory" type="update">
Update tests commons-io:commons-io 2.6 -> 2.7.
</action>
+ <action issue="LOG4J2-2895" dev="ckozak" type="fix">
+ Fix potential deadlock in asynchronous logging by avoiding blocking for queue space on Log4jThreads
+ </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">
[logging-log4j2] 02/03: LOG4J2-2837: Disruptor and JUL no longer
recursively start the AsyncLoggerDisruptor
Posted by ck...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
ckozak pushed a commit to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 31340441e844383efe640e051a3d747a3ef9cd00
Author: Carter Kozak <ck...@apache.org>
AuthorDate: Thu Jul 16 16:17:20 2020 -0400
LOG4J2-2837: Disruptor and JUL no longer recursively start the AsyncLoggerDisruptor
Previously logging initialization would result in an AsyncLoggerContext
initializing an AsyncLoggerDisruptor, which would access a logger from
JUL, starting the process again. This change avoids recursive calls with
a state check.
---
.../log4j/core/async/AsyncLoggerDisruptor.java | 5 ++
log4j-jul/pom.xml | 6 ++
.../logging/log4j/jul/AsyncLoggerThreadsTest.java | 66 ++++++++++++++++++++++
src/changes/changes.xml | 4 ++
4 files changed, 81 insertions(+)
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 c51defa..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
@@ -86,6 +86,11 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle {
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");
diff --git a/log4j-jul/pom.xml b/log4j-jul/pom.xml
index d29f12a..11d1c5c 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..0ef1585
--- /dev/null
+++ b/log4j-jul/src/test/java/org/apache/logging/log4j/jul/AsyncLoggerThreadsTest.java
@@ -0,0 +1,66 @@
+/*
+ * 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.apache.logging.log4j.core.util.DummyNanoClock;
+import org.apache.logging.log4j.util.Strings;
+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 51d10a3..c2c41ad 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -78,6 +78,10 @@
<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>
</release>
<release version="2.13.3" date="2020-05-10" description="GA Release 2.13.3">
<action issue="LOG4J2-2838" dev="rgoers" type="fix">