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 <cko...@apache.org> Authored: Mon Apr 16 12:06:39 2018 -0400 Committer: Carter Kozak <cko...@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">