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 2018/04/17 02:57:58 UTC
logging-log4j2 git commit: LOG4J2-2318: AsyncQueueFullMessageUtil
logs to StatusLogger
Repository: logging-log4j2
Updated Branches:
refs/heads/master 7379ec33e -> d175b2b2e
LOG4J2-2318: AsyncQueueFullMessageUtil logs to StatusLogger
We no longer mutate messages when logging them out of order.
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/d175b2b2
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/d175b2b2
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/d175b2b2
Branch: refs/heads/master
Commit: d175b2b2ee7748bff5456a6f339556cbb3a5e275
Parents: 7379ec3
Author: Carter Kozak <ck...@apache.org>
Authored: Mon Apr 16 12:06:39 2018 -0400
Committer: Carter Kozak <ck...@apache.org>
Committed: Mon Apr 16 22:57:50 2018 -0400
----------------------------------------------------------------------
.../log4j/core/appender/AsyncAppender.java | 5 ++--
.../logging/log4j/core/async/AsyncLogger.java | 8 +++---
.../log4j/core/async/AsyncLoggerConfig.java | 4 +--
.../core/async/AsyncQueueFullMessageUtil.java | 29 ++++++++------------
...syncLoggerConfigLoggingFromToStringTest.java | 15 ++++++++--
...eFullAsyncLoggerLoggingFromToStringTest.java | 4 +--
src/changes/changes.xml | 3 ++
7 files changed, 37 insertions(+), 31 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
index 92e6738..ba51f49 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
@@ -50,7 +50,6 @@ import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.util.Log4jThread;
-import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.spi.AbstractLogger;
/**
@@ -163,8 +162,8 @@ public final class AsyncAppender extends AbstractAppender {
if (blocking) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
- final Message message = AsyncQueueFullMessageUtil.transform(logEvent.getMessage());
- logMessageInCurrentThread(new Log4jLogEvent.Builder(logEvent).setMessage(message).build());
+ AsyncQueueFullMessageUtil.logWarningToStatusLogger();
+ logMessageInCurrentThread(logEvent);
} else {
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
index 8f86588..c278316 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
@@ -170,8 +170,8 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf
private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
- final Message message = AsyncQueueFullMessageUtil.transform(translator.message);
- logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, message,
+ AsyncQueueFullMessageUtil.logWarningToStatusLogger();
+ logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
translator.thrown);
return;
}
@@ -321,8 +321,8 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf
final Throwable thrown) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
- final Message message = AsyncQueueFullMessageUtil.transform(msg);
- logMessageInCurrentThread(fqcn, level, marker, message, thrown);
+ AsyncQueueFullMessageUtil.logWarningToStatusLogger();
+ logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
return;
}
final EventRoute eventRoute = loggerDisruptor.getEventRoute(level);
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
index 56744ce..84ef572 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java
@@ -102,8 +102,8 @@ public class AsyncLoggerConfig extends LoggerConfig {
private void handleQueueFull(final LogEvent event) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
- final Message message = AsyncQueueFullMessageUtil.transform(event.getMessage());
- callAppendersInCurrentThread(new Log4jLogEvent.Builder(event).setMessage(message).build());
+ AsyncQueueFullMessageUtil.logWarningToStatusLogger();
+ callAppendersInCurrentThread(event);
} else {
// otherwise, we leave it to the user preference
final EventRoute eventRoute = delegate.getEventRoute(event.getLevel());
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java
index 9609bbd..9c0956b 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java
@@ -16,30 +16,25 @@
*/
package org.apache.logging.log4j.core.async;
-import org.apache.logging.log4j.message.Message;
-import org.apache.logging.log4j.message.SimpleMessage;
+import org.apache.logging.log4j.status.StatusLogger;
/**
* <b>Consider this class private.</b>
* <p>
- * Transforms the specified user message to append an internal Log4j2 message explaining why this message appears out
- * of order in the appender.
+ * Logs a warning to the {@link StatusLogger} when events are logged out of order to avoid deadlocks.
* </p>
*/
-public class AsyncQueueFullMessageUtil {
+public final class AsyncQueueFullMessageUtil {
+ private AsyncQueueFullMessageUtil() {
+ // Utility Class
+ }
+
/**
- * Returns a new {@code Message} based on the original message that appends an internal Log4j2 message
- * explaining why this message appears out of order in the appender.
- * <p>
- * Any parameter objects present in the original message are not included in the returned message.
- * </p>
- * @param message the message to replace
- * @return a new {@code Message} object
+ * Logs a warning to the {@link StatusLogger} explaining why a message appears out of order in the appender.
*/
- public static Message transform(Message message) {
- SimpleMessage result = new SimpleMessage(message.getFormattedMessage() +
- " (Log4j2 logged this message out of order to prevent deadlock caused by domain " +
- "objects logging from their toString method when the async queue is full - LOG4J2-2031)");
- return result;
+ public static void logWarningToStatusLogger() {
+ StatusLogger.getLogger()
+ .warn("LOG4J2-2031: Log4j2 logged an event out of order to prevent deadlock caused by domain " +
+ "objects logging from their toString method when the async queue is full");
}
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java
index 8aef3e9..307a93d 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java
@@ -16,14 +16,18 @@
*/
package org.apache.logging.log4j.core.async;
+import java.util.List;
import java.util.Stack;
import java.util.concurrent.CountDownLatch;
+import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.categories.AsyncLoggers;
import org.apache.logging.log4j.core.config.ConfigurationFactory;
import org.apache.logging.log4j.junit.LoggerContextRule;
+import org.apache.logging.log4j.status.StatusData;
+import org.apache.logging.log4j.status.StatusLogger;
import org.junit.Before;
import org.junit.BeforeClass;
import org.junit.Rule;
@@ -32,6 +36,7 @@ import org.junit.experimental.categories.Category;
import org.junit.runner.RunWith;
import org.junit.runners.BlockJUnit4ClassRunner;
+import static org.hamcrest.core.StringContains.containsString;
import static org.junit.Assert.*;
/**
@@ -89,10 +94,14 @@ public class QueueFullAsyncLoggerConfigLoggingFromToStringTest extends QueueFull
final Stack<String> actual = transform(blockingAppender.logEvents);
assertEquals("Logging in toString() #0", actual.pop());
+ List<StatusData> statusDataList = StatusLogger.getLogger().getStatusData();
assertEquals("Jumped the queue: queue full",
- "Logging in toString() #128 (Log4j2 logged this message out of order " +
- "to prevent deadlock caused by domain objects logging from their toString " +
- "method when the async queue is full - LOG4J2-2031)", actual.pop());
+ "Logging in toString() #128", actual.pop());
+ StatusData mostRecentStatusData = statusDataList.get(statusDataList.size() - 1);
+ assertEquals("Expected warn level status message", Level.WARN, mostRecentStatusData.getLevel());
+ assertThat(mostRecentStatusData.getFormattedStatus(), containsString(
+ "Log4j2 logged an event out of order to prevent deadlock caused by domain " +
+ "objects logging from their toString method when the async queue is full"));
for (int i = 1; i < 128; i++) {
assertEquals("First batch", "Logging in toString() #" + i, actual.pop());
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java
index 7039bca..5c12502 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java
@@ -96,8 +96,8 @@ public class QueueFullAsyncLoggerLoggingFromToStringTest extends QueueFullAbstra
final Stack<String> actual = transform(blockingAppender.logEvents);
assertEquals("Jumped the queue: test(2)+domain1(65)+domain2(61)=128: queue full",
- "Logging in toString() #127 (Log4j2 logged this message out of order to prevent deadlock caused by domain objects logging from their toString method when the async queue is full - LOG4J2-2031)", actual.pop());
- assertEquals("Logging in toString() #128 (Log4j2 logged this message out of order to prevent deadlock caused by domain objects logging from their toString method when the async queue is full - LOG4J2-2031)", actual.pop());
+ "Logging in toString() #127", actual.pop());
+ assertEquals("Logging in toString() #128", actual.pop());
assertEquals("logging naughty object #0 Who's bad?!", actual.pop());
for (int i = 0; i < 127; i++) {
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d175b2b2/src/changes/changes.xml
----------------------------------------------------------------------
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index ccee2ce..1020d08 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -139,6 +139,9 @@
<action issue="LOG4J2-2317" dev="ckozak" type="fix">
MutableLogEvent.getNonNullImmutableMessage and Log4jLogEvent.makeMessageImmutable retain format and parameters.
</action>
+ <action issue="LOG4J2-2318" dev="ckozak" type="fix">
+ Messages are no longer mutated when the asynchronous queue is full. A warning is logged to the status logger instead.
+ </action>
</release>
<release version="2.11.1" date="2018-MM-DD" description="GA Release 2.11.1">
<action issue="LOG4J2-2268" dev="rgoers" type="fix" due-to="Tilman Hausherr">