Repository: logging-log4j2 Updated Branches: refs/heads/master 9662274e2 -> c81c118a2
LOG4J2-2031 improve async queue full handling: * Only log out of order if recursive logging was detected and the queue was full: bypass the queue to avoid deadlock * Otherwise delegate to the AsyncQueueFullPolicy * DefaultAsyncQueueFullPolicy is ENQUEUE, unless log event came from background thread. This could cause deadlock, so we bypass the queue and log out of order directly to the appender again. Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/b478b97e Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/b478b97e Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/b478b97e Branch: refs/heads/master Commit: b478b97ee724decc330f1425ba147aa40d39cbe8 Parents: 798e14d Author: rpopma <[email protected]> Authored: Mon Sep 18 22:52:35 2017 +0900 Committer: rpopma <[email protected]> Committed: Wed Sep 20 22:40:53 2017 +0900 ---------------------------------------------------------------------- .../logging/log4j/spi/AbstractLogger.java | 55 ++++++++- .../log4j/core/appender/AsyncAppender.java | 15 ++- .../logging/log4j/core/async/AsyncLogger.java | 58 ++++++++- .../log4j/core/async/AsyncLoggerConfig.java | 14 +++ .../log4j/core/async/AsyncLoggerDisruptor.java | 4 +- .../core/async/AsyncQueueFullMessageUtil.java | 45 +++++++ .../core/async/DefaultAsyncQueueFullPolicy.java | 14 ++- .../log4j/core/async/BlockingAppender.java | 94 ++++++++++++++ .../async/DefaultAsyncQueueFullPolicyTest.java | 6 +- .../DiscardingAsyncQueueFullPolicyTest.java | 8 +- .../log4j/core/async/QueueFullAbstractTest.java | 121 +++++++++++++++++++ ...syncLoggerConfigLoggingFromToStringTest.java | 97 +++++++++++++++ .../async/QueueFullAsyncLoggerConfigTest.java | 91 ++++++++++++++ ...eFullAsyncLoggerLoggingFromToStringTest.java | 102 ++++++++++++++++ .../core/async/QueueFullAsyncLoggerTest.java | 97 +++++++++++++++ .../src/test/resources/log4j2-queueFull.xml | 28 +++++ .../log4j2-queueFullAsyncLoggerConfig.xml | 28 +++++ 17 files changed, 851 insertions(+), 26 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java b/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java index 69664f7..0a3d81c 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java @@ -49,8 +49,8 @@ import org.apache.logging.log4j.util.Supplier; public abstract class AbstractLogger implements ExtendedLogger, Serializable { // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE! // Specifically, try to keep the hot methods to 35 bytecodes or less: - // this is within the MaxInlineSize threshold and makes these methods candidates for - // immediate inlining instead of waiting until they are designated "hot enough". + // this is within the MaxInlineSize threshold on Java 7 and Java 8 Hotspot and makes these methods + // candidates for immediate inlining instead of waiting until they are designated "hot enough". /** * Marker for flow tracing. @@ -104,6 +104,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected final String name; private final MessageFactory2 messageFactory; private final FlowMessageFactory flowMessageFactory; + private static ThreadLocal<int[]> recursionDepthHolder = new ThreadLocal<>(); // LOG4J2-1518, LOG4J2-2031 /** * Creates a new logger named after this class (or subclass). @@ -2097,7 +2098,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { private void logMessageSafely(final String fqcn, final Level level, final Marker marker, final Message msg, final Throwable throwable) { try { - tryLogMessage(fqcn, level, marker, msg, throwable); + logMessageTrackRecursion(fqcn, level, marker, msg, throwable); } finally { // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString()) ReusableMessageFactory.release(msg); @@ -2105,8 +2106,54 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { } @PerformanceSensitive + // NOTE: This is a hot method. Current implementation compiles to 29 bytes of byte code. + // This is within the 35 byte MaxInlineSize threshold. Modify with care! + private void logMessageTrackRecursion(final String fqcn, + final Level level, + final Marker marker, + final Message msg, + final Throwable throwable) { + try { + incrementRecursionDepth(); // LOG4J2-1518, LOG4J2-2031 + tryLogMessage(fqcn, level, marker, msg, throwable); + } finally { + decrementRecursionDepth(); + } + } + + private static int[] getRecursionDepthHolder() { + int[] result = recursionDepthHolder.get(); + if (result == null) { + result = new int[1]; + recursionDepthHolder.set(result); + } + return result; + } + + private static void incrementRecursionDepth() { + getRecursionDepthHolder()[0]++; + } + private static void decrementRecursionDepth() { + int[] depth = getRecursionDepthHolder(); + depth[0]--; + if (depth[0] < 0) { + throw new IllegalStateException("Recursion depth became negative: " + depth[0]); + } + } + + /** + * Returns the depth of nested logging calls in the current Thread: zero if no logging call has been made, + * one if a single logging call without nested logging calls has been made, or more depending on the level of + * nesting. + * @return the depth of the nested logging calls in the current Thread + */ + public static int getRecursionDepth() { + return getRecursionDepthHolder()[0]; + } + + @PerformanceSensitive // NOTE: This is a hot method. Current implementation compiles to 26 bytes of byte code. - // This is within the 35 byte MaxInlineSize threshold (on which JMV and version?). Modify with care! + // This is within the 35 byte MaxInlineSize threshold. Modify with care! private void tryLogMessage(final String fqcn, final Level level, final Marker marker, http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 b104083..bc2be90 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 @@ -29,7 +29,9 @@ import org.apache.logging.log4j.core.Appender; import org.apache.logging.log4j.core.Core; import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.async.ArrayBlockingQueueFactory; +import org.apache.logging.log4j.core.async.AsyncQueueFullMessageUtil; import org.apache.logging.log4j.core.async.AsyncQueueFullPolicy; import org.apache.logging.log4j.core.async.AsyncQueueFullPolicyFactory; import org.apache.logging.log4j.core.async.BlockingQueueFactory; @@ -49,6 +51,7 @@ 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; /** * Appends to one or more Appenders asynchronously. You can configure an AsyncAppender with one or more Appenders and an @@ -158,9 +161,15 @@ public final class AsyncAppender extends AbstractAppender { InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage()); if (!transfer(memento)) { if (blocking) { - // 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()); - route.logMessage(this, memento); + if (Logger.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()); + } 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()); + route.logMessage(this, memento); + } } else { error("Appender " + getName() + " is unable to write primary appenders. queue is full"); logToErrorAppenderIfNecessary(false, memento); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 b6e4c53..84d66dd 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 @@ -22,13 +22,13 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.Marker; import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.ThreadContext.ContextStack; +import org.apache.logging.log4j.core.ContextDataInjector; import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.Property; import org.apache.logging.log4j.core.config.ReliabilityStrategy; import org.apache.logging.log4j.core.impl.ContextDataFactory; -import org.apache.logging.log4j.core.ContextDataInjector; import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory; import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.ClockFactory; @@ -36,9 +36,9 @@ import org.apache.logging.log4j.core.util.NanoClock; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.message.ReusableMessage; +import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.StackLocatorUtil; import org.apache.logging.log4j.util.StringMap; -import org.apache.logging.log4j.status.StatusLogger; import com.lmax.disruptor.EventTranslatorVararg; import com.lmax.disruptor.dsl.Disruptor; @@ -167,6 +167,13 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf } private void handleRingBufferFull(final RingBufferLogEventTranslator translator) { + if (Logger.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, + translator.thrown); + return; + } final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level); switch (eventRoute) { case ENQUEUE: @@ -245,9 +252,18 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf if (!isReused(message)) { InternalAsyncUtil.makeMessageImmutable(message); } + StackTraceElement location = null; // calls the translateTo method on this AsyncLogger - disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message, - thrown); + if (!disruptor.getRingBuffer().tryPublishEvent(this, + this, // asyncLogger: 0 + (location = calcLocationIfRequested(fqcn)), // location: 1 + fqcn, // 2 + level, // 3 + marker, // 4 + message, // 5 + thrown)) { // 6 + handleRingBufferFull(location, fqcn, level, marker, message, thrown); + } } /* @@ -296,6 +312,40 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf strategy.log(this, getName(), fqcn, marker, level, message, thrown); } + private void handleRingBufferFull(final StackTraceElement location, + final String fqcn, + final Level level, + final Marker marker, + final Message msg, + final Throwable thrown) { + if (Logger.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); + return; + } + final EventRoute eventRoute = loggerDisruptor.getEventRoute(level); + switch (eventRoute) { + case ENQUEUE: + loggerDisruptor.getDisruptor().getRingBuffer().publishEvent(this, + this, // asyncLogger: 0 + location, // location: 1 + fqcn, // 2 + level, // 3 + marker, // 4 + msg, // 5 + thrown); // 6 + break; + case SYNCHRONOUS: + logMessageInCurrentThread(fqcn, level, marker, msg, thrown); + break; + case DISCARD: + break; + default: + throw new IllegalStateException("Unknown EventRoute " + eventRoute); + } + } + /** * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread. * Merges the contents of the configuration map into the contextData, after replacing any variables in the property http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 f15dcad..d6e46b5 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 @@ -25,6 +25,7 @@ import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.core.Core; import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.config.AppenderRef; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.LoggerConfig; @@ -35,8 +36,10 @@ import org.apache.logging.log4j.core.config.plugins.PluginAttribute; import org.apache.logging.log4j.core.config.plugins.PluginConfiguration; import org.apache.logging.log4j.core.config.plugins.PluginElement; import org.apache.logging.log4j.core.config.plugins.PluginFactory; +import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.core.jmx.RingBufferAdmin; import org.apache.logging.log4j.core.util.Booleans; +import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.util.Strings; /** @@ -92,6 +95,17 @@ public class AsyncLoggerConfig extends LoggerConfig { populateLazilyInitializedFields(event); if (!delegate.tryEnqueue(event, this)) { + handleQueueFull(event); + } + } + + private void handleQueueFull(final LogEvent event) { + if (Logger.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()); + } else { + // otherwise, we leave it to the user preference final EventRoute eventRoute = delegate.getEventRoute(event.getLevel()); eventRoute.logMessage(this, event); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java ---------------------------------------------------------------------- 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 ab21111..7a7e546 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 @@ -203,10 +203,10 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { } public boolean tryPublish(final RingBufferLogEventTranslator translator) { - // LOG4J2-639: catch NPE if disruptor field was set to null in stop() try { return disruptor.getRingBuffer().tryPublishEvent(translator); } catch (final NullPointerException npe) { + // LOG4J2-639: catch NPE if disruptor field was set to null in stop() LOGGER.warn("[{}] Ignoring log event after log4j was shut down: {} [{}] {}", contextName, translator.level, translator.loggerName, translator.message.getFormattedMessage() + (translator.thrown == null ? "" : Throwables.toStringList(translator.thrown))); @@ -215,13 +215,13 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { } void enqueueLogMessageInfo(final RingBufferLogEventTranslator translator) { - // LOG4J2-639: catch NPE if disruptor field was set to null in stop() try { // Note: we deliberately access the volatile disruptor field afresh here. // Avoiding this and using an older reference could result in adding a log event to the disruptor after it // was shut down, which could cause the publishEvent method to hang and never return. disruptor.publishEvent(translator); } catch (final NullPointerException npe) { + // LOG4J2-639: catch NPE if disruptor field was set to null in stop() LOGGER.warn("[{}] Ignoring log event after log4j was shut down: {} [{}] {}", contextName, translator.level, translator.loggerName, translator.message.getFormattedMessage() + (translator.thrown == null ? "" : Throwables.toStringList(translator.thrown))); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 new file mode 100644 index 0000000..9609bbd --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncQueueFullMessageUtil.java @@ -0,0 +1,45 @@ +/* + * 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 org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.message.SimpleMessage; + +/** + * <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. + * </p> + */ +public class AsyncQueueFullMessageUtil { + /** + * 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 + */ + 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; + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.java ---------------------------------------------------------------------- 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 26f9bb6..1d48113 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 @@ -19,17 +19,19 @@ package org.apache.logging.log4j.core.async; import org.apache.logging.log4j.Level; /** - * Default: any logging done when queue is full bypasses the queue and logs synchronously: send the event directly to + * Default router: enqueue the event for asynchronous logging in the background thread, unless the current thread is the + * background thread and the queue is full (enqueueing would cause a deadlock). In that case send the event directly to * the appender (in the current thread). */ public class DefaultAsyncQueueFullPolicy implements AsyncQueueFullPolicy { @Override public EventRoute getRoute(final long backgroundThreadId, final Level level) { - // LOG4J2-1518: prevent deadlock when RingBuffer is full and object being logged calls - // Logger.log in application thread - // See also LOG4J2-471: prevent deadlock when RingBuffer is full and object - // being logged calls Logger.log() from its toString() method in background thread - return EventRoute.SYNCHRONOUS; + // LOG4J2-471: prevent deadlock when RingBuffer is full and object + // being logged calls Logger.log() from its toString() method + if (Thread.currentThread().getId() == backgroundThreadId) { + return EventRoute.SYNCHRONOUS; + } + return EventRoute.ENQUEUE; } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/BlockingAppender.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/BlockingAppender.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/BlockingAppender.java new file mode 100644 index 0000000..e8ef050 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/BlockingAppender.java @@ -0,0 +1,94 @@ +/* + * 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 java.io.Serializable; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; + +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Core; +import org.apache.logging.log4j.core.Filter; +import org.apache.logging.log4j.core.Layout; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.config.plugins.PluginAttribute; +import org.apache.logging.log4j.core.config.plugins.PluginElement; +import org.apache.logging.log4j.core.config.plugins.PluginFactory; +import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required; +import org.apache.logging.log4j.core.impl.Log4jLogEvent; + +/** + * Appender that can be halted and resumed, for testing queue-full scenarios. + */ +@Plugin(name = "Blocking", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE, printObject = true) +public class BlockingAppender extends AbstractAppender { + private static final long serialVersionUID = 1L; + public List<LogEvent> logEvents = new CopyOnWriteArrayList<>(); + public CountDownLatch countDownLatch = null; + + public BlockingAppender(final String name) { + super(name, null, null); + } + + @Override + public void append(final LogEvent event) { + + // for scenarios where domain objects log from their toString method in the background thread + event.getMessage().getFormattedMessage(); + + // may be a reusable event, make a copy, don't keep a reference to the original event + logEvents.add(Log4jLogEvent.createMemento(event)); + + if (countDownLatch == null) { + return; + } + // block until the test class tells us to continue + try { + countDownLatch.await(); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + } + + @PluginFactory + public static BlockingAppender createAppender( + @PluginAttribute("name") + @Required(message = "No name provided for HangingAppender") + final String name, + @PluginElement("Layout") final Layout<? extends Serializable> layout, + @PluginElement("Filter") final Filter filter) { + return new BlockingAppender(name); + } + + @Override + public void start() { + super.start(); + } + + @Override + public boolean stop(final long timeout, final TimeUnit timeUnit) { + setStopping(); + super.stop(timeout, timeUnit, false); + setStopped(); + return true; + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicyTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicyTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicyTest.java index 28fe41a..d6d2b56 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicyTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicyTest.java @@ -38,10 +38,10 @@ public class DefaultAsyncQueueFullPolicyTest { } @Test - public void testGetRouteSynchronousIfQueueFullAndCalledFromDifferentThread() throws Exception { + public void testGetRouteEnqueuesIfQueueFullAndCalledFromDifferentThread() throws Exception { final DefaultAsyncQueueFullPolicy router = new DefaultAsyncQueueFullPolicy(); - assertEquals(EventRoute.SYNCHRONOUS, router.getRoute(otherThreadId(), Level.ALL)); - assertEquals(EventRoute.SYNCHRONOUS, router.getRoute(otherThreadId(), Level.OFF)); + assertEquals(EventRoute.ENQUEUE, router.getRoute(otherThreadId(), Level.ALL)); + assertEquals(EventRoute.ENQUEUE, router.getRoute(otherThreadId(), Level.OFF)); } @Test http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DiscardingAsyncQueueFullPolicyTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DiscardingAsyncQueueFullPolicyTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DiscardingAsyncQueueFullPolicyTest.java index c30ef6d..8c5ef5a 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DiscardingAsyncQueueFullPolicyTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/DiscardingAsyncQueueFullPolicyTest.java @@ -79,18 +79,18 @@ public class DiscardingAsyncQueueFullPolicyTest { for (final Level level : new Level[] {Level.ERROR, Level.FATAL, Level.OFF}) { assertEquals(level.name(), EventRoute.SYNCHRONOUS, router.getRoute(currentThreadId(), level)); - assertEquals(level.name(), EventRoute.SYNCHRONOUS, router.getRoute(otherThreadId(), level)); + assertEquals(level.name(), EventRoute.ENQUEUE, router.getRoute(otherThreadId(), level)); assertEquals(level.name(), EventRoute.SYNCHRONOUS, router.getRoute(currentThreadId(), level)); - assertEquals(level.name(), EventRoute.SYNCHRONOUS, router.getRoute(otherThreadId(), level)); + assertEquals(level.name(), EventRoute.ENQUEUE, router.getRoute(otherThreadId(), level)); } } @Test - public void testGetRouteSynchronousIfOtherThreadQueueFullAndLevelMoreSpecificThanThreshold() throws Exception { + public void testGetRouteEnqueueIfOtherThreadQueueFullAndLevelMoreSpecificThanThreshold() throws Exception { final DiscardingAsyncQueueFullPolicy router = new DiscardingAsyncQueueFullPolicy(Level.WARN); for (final Level level : new Level[] {Level.ERROR, Level.FATAL, Level.OFF}) { - assertEquals(level.name(), EventRoute.SYNCHRONOUS, router.getRoute(otherThreadId(), level)); + assertEquals(level.name(), EventRoute.ENQUEUE, router.getRoute(otherThreadId(), level)); } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java new file mode 100644 index 0000000..cbf6e06 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java @@ -0,0 +1,121 @@ +/* + * 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 java.lang.reflect.Field; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.Stack; +import java.util.concurrent.CountDownLatch; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.config.LoggerConfig; + +import com.lmax.disruptor.dsl.Disruptor; + +/** + * Tests queue full scenarios abstract superclass. + */ +public abstract class QueueFullAbstractTest { + protected static boolean TRACE = false; + protected BlockingAppender blockingAppender; + protected Unlocker unlocker; + + protected static void TRACE(Object msg) { + if (TRACE) { + System.out.println(msg); + } + } + + class Unlocker extends Thread { + final CountDownLatch countDownLatch; + Unlocker(CountDownLatch countDownLatch) { + this.countDownLatch = countDownLatch; + } + public void run() { + try { + countDownLatch.await(); + TRACE("Unlocker activated. Sleeping 500 millis before taking action..."); + Thread.sleep(500); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + TRACE("Unlocker signalling BlockingAppender to proceed..."); + blockingAppender.countDownLatch.countDown(); + } + } + + class DomainObject { + private Logger innerLogger = LogManager.getLogger(DomainObject.class); + final int count; + DomainObject(int loggingCount) { + this.count = loggingCount; + } + + @Override + public String toString() { + for (int i = 0; i < count; i++) { + TRACE("DomainObject decrementing unlocker countdown latch before logging. Count was " + unlocker.countDownLatch.getCount()); + unlocker.countDownLatch.countDown(); + TRACE("DomainObject logging message " + i + ". Remaining capacity=" + getDisruptor(innerLogger).getRingBuffer().remainingCapacity()); + innerLogger.info("Logging in toString() #" + i); + } + return "Who's bad?!"; + } + } + + static Stack transform(final List<LogEvent> logEvents) { + final List<String> filtered = new ArrayList<>(logEvents.size()); + for (LogEvent event : logEvents) { + filtered.add(event.getMessage().getFormattedMessage()); + } + Collections.reverse(filtered); + Stack<String> result = new Stack<>(); + result.addAll(filtered); + return result; + } + + static Disruptor getDisruptor(Logger logger) { + if (logger instanceof AsyncLogger) { + try { + Field f = field(AsyncLogger.class, "loggerDisruptor"); + return ((AsyncLoggerDisruptor) f.get(logger)).getDisruptor(); + } catch (Exception ex) { + throw new RuntimeException(ex); + } + } else { + LoggerConfig loggerConfig = ((org.apache.logging.log4j.core.Logger) logger).get(); + if (loggerConfig instanceof AsyncLoggerConfig) { + try { + Object delegate = field(AsyncLoggerConfig.class, "delegate").get(loggerConfig); + return (Disruptor) field(AsyncLoggerConfigDisruptor.class, "disruptor").get(delegate); + } catch (Exception ex) { + throw new RuntimeException(ex); + } + } + } + throw new IllegalStateException("Async Loggers are not configured"); + } + private static Field field(Class<?> c, String name) throws NoSuchFieldException { + Field f = c.getDeclaredField(name); + f.setAccessible(true); + return f; + } +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 new file mode 100644 index 0000000..a3140ae --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigLoggingFromToStringTest.java @@ -0,0 +1,97 @@ +/* + * 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 java.util.Stack; +import java.util.concurrent.CountDownLatch; + +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.junit.Before; +import org.junit.BeforeClass; +import org.junit.Rule; +import org.junit.Test; +import org.junit.experimental.categories.Category; +import org.junit.runner.RunWith; +import org.junit.runners.BlockJUnit4ClassRunner; + +import static org.junit.Assert.*; + +/** + * Tests queue full scenarios with pure AsyncLoggers (all loggers async). + */ +@RunWith(BlockJUnit4ClassRunner.class) +@Category(AsyncLoggers.class) +public class QueueFullAsyncLoggerConfigLoggingFromToStringTest extends QueueFullAbstractTest { + + @BeforeClass + public static void beforeClass() { + System.setProperty("log4j2.enable.threadlocals", "true"); + System.setProperty("log4j2.is.webapp", "false"); +// System.setProperty("AsyncLogger.RingBufferSize", "128"); // minimum ringbuffer size + System.setProperty("AsyncLoggerConfig.RingBufferSize", "128"); + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, + "log4j2-queueFullAsyncLoggerConfig.xml"); + } + + @Rule + public LoggerContextRule context = new LoggerContextRule( + "log4j2-queueFullAsyncLoggerConfig.xml"); + + @Before + public void before() throws Exception { + blockingAppender = context.getRequiredAppender("Blocking", BlockingAppender.class); + } + + @Test(timeout = 5000) + public void testLoggingFromToStringCausesOutOfOrderMessages() throws InterruptedException { + //TRACE = true; + final Logger logger = LogManager.getLogger(this.getClass()); + + blockingAppender.countDownLatch = new CountDownLatch(1); + unlocker = new Unlocker(new CountDownLatch(129)); // count slightly different from "pure" async loggers + unlocker.start(); + + for (int i = 0; i < 1; i++) { + TRACE("Test logging message " + i + ". Remaining capacity=" + getDisruptor(logger).getRingBuffer().remainingCapacity()); + TRACE("Test decrementing unlocker countdown latch. Count=" + unlocker.countDownLatch.getCount()); + unlocker.countDownLatch.countDown(); + final DomainObject obj = new DomainObject(129); + logger.info("logging naughty object #{} {}", i, obj); + } + TRACE("Before stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + //CoreLoggerContexts.stopLoggerContext(false); // stop async thread + while (blockingAppender.logEvents.size() < 130) { Thread.yield(); } + TRACE("After stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + + final Stack<String> actual = transform(blockingAppender.logEvents); + assertEquals("Logging in toString() #0", actual.pop()); + 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()); + + for (int i = 1; i < 128; i++) { + assertEquals("First batch", "Logging in toString() #" + i, actual.pop()); + } + assertEquals("logging naughty object #0 Who's bad?!", actual.pop()); + assertTrue(actual.isEmpty()); + } +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigTest.java new file mode 100644 index 0000000..ea39d34 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerConfigTest.java @@ -0,0 +1,91 @@ +/* + * 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 java.util.Stack; +import java.util.concurrent.CountDownLatch; + +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.core.util.Constants; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.apache.logging.log4j.util.Strings; +import org.junit.AfterClass; +import org.junit.Before; +import org.junit.BeforeClass; +import org.junit.Rule; +import org.junit.Test; +import org.junit.experimental.categories.Category; +import org.junit.runner.RunWith; +import org.junit.runners.BlockJUnit4ClassRunner; + +import static org.junit.Assert.*; + +/** + * Tests queue full scenarios with pure AsyncLoggers (all loggers async). + */ +@RunWith(BlockJUnit4ClassRunner.class) +@Category(AsyncLoggers.class) +public class QueueFullAsyncLoggerConfigTest extends QueueFullAbstractTest { + + @BeforeClass + public static void beforeClass() { + System.setProperty("AsyncLoggerConfig.RingBufferSize", "128"); // minimum ringbuffer size + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, + "log4j2-queueFullAsyncLoggerConfig.xml"); + } + + @Rule + public LoggerContextRule context = new LoggerContextRule( + "log4j2-queueFullAsyncLoggerConfig.xml"); + + @Before + public void before() throws Exception { + blockingAppender = context.getRequiredAppender("Blocking", BlockingAppender.class); + } + + + @Test(timeout = 5000) + public void testNormalQueueFullKeepsMessagesInOrder() throws InterruptedException { + final Logger logger = LogManager.getLogger(this.getClass()); + + blockingAppender.countDownLatch = new CountDownLatch(1); + unlocker = new Unlocker(new CountDownLatch(129)); + unlocker.start(); + + for (int i = 0; i < 130; i++) { + TRACE("Test logging message " + i + ". Remaining capacity=" + getDisruptor(logger).getRingBuffer().remainingCapacity()); + TRACE("Test decrementing unlocker countdown latch. Count=" + unlocker.countDownLatch.getCount()); + unlocker.countDownLatch.countDown(); + final String param = "I'm innocent"; + logger.info(new ParameterizedMessage("logging innocent object #{} {}", i, param)); + } + TRACE("Before stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + //CoreLoggerContexts.stopLoggerContext(false); // stop async thread + while (blockingAppender.logEvents.size() < 130) { Thread.yield(); } + TRACE("After stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + + final Stack<String> actual = transform(blockingAppender.logEvents); + for (int i = 0; i < 130; i++) { + assertEquals("logging innocent object #" + i + " I'm innocent", actual.pop()); + } + assertTrue(actual.isEmpty()); + } +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/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 new file mode 100644 index 0000000..2e8e7e8 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerLoggingFromToStringTest.java @@ -0,0 +1,102 @@ +/* + * 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 java.util.Stack; +import java.util.concurrent.CountDownLatch; + +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.CoreLoggerContexts; +import org.apache.logging.log4j.core.config.ConfigurationFactory; +import org.apache.logging.log4j.core.util.Constants; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.apache.logging.log4j.util.Strings; +import org.junit.AfterClass; +import org.junit.Before; +import org.junit.BeforeClass; +import org.junit.Rule; +import org.junit.Test; +import org.junit.experimental.categories.Category; +import org.junit.runner.RunWith; +import org.junit.runners.BlockJUnit4ClassRunner; + +import static org.junit.Assert.*; + +/** + * Tests queue full scenarios with pure AsyncLoggers (all loggers async). + */ +@RunWith(BlockJUnit4ClassRunner.class) +@Category(AsyncLoggers.class) +public class QueueFullAsyncLoggerLoggingFromToStringTest extends QueueFullAbstractTest { + + @BeforeClass + public static void beforeClass() { + System.setProperty("AsyncLogger.RingBufferSize", "128"); // minimum ringbuffer size +// System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName()); + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, + "log4j2-queueFull.xml"); + } + + @AfterClass + public static void afterClass() { + System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR, Strings.EMPTY); + } + + @Rule + public LoggerContextRule context = new LoggerContextRule( + "log4j2-queueFull.xml", AsyncLoggerContextSelector.class); + + @Before + public void before() throws Exception { + blockingAppender = context.getRequiredAppender("Blocking", BlockingAppender.class); + } + + @Test(timeout = 5000) + public void testLoggingFromToStringCausesOutOfOrderMessages() throws InterruptedException { + final Logger logger = LogManager.getLogger(this.getClass()); + + blockingAppender.countDownLatch = new CountDownLatch(1); + unlocker = new Unlocker(new CountDownLatch(129)); + unlocker.start(); + + for (int i = 0; i < 1; i++) { + TRACE("Test logging message " + i + ". Remaining capacity=" + getDisruptor(logger).getRingBuffer().remainingCapacity()); + TRACE("Test decrementing unlocker countdown latch. Count=" + unlocker.countDownLatch.getCount()); + unlocker.countDownLatch.countDown(); + final DomainObject obj = new DomainObject(129); + logger.info(new ParameterizedMessage("logging naughty object #{} {}", i, obj)); + } + TRACE("Before stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + CoreLoggerContexts.stopLoggerContext(false); // stop async thread + while (blockingAppender.logEvents.size() < 129) { Thread.yield(); } + TRACE("After stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + + 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()); + assertEquals("logging naughty object #0 Who's bad?!", actual.pop()); + + for (int i = 0; i < 127; i++) { + assertEquals("First batch", "Logging in toString() #" + i, actual.pop()); + } + assertTrue(actual.isEmpty()); + } +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerTest.java new file mode 100644 index 0000000..77d411a --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/QueueFullAsyncLoggerTest.java @@ -0,0 +1,97 @@ +/* + * 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 java.util.Stack; +import java.util.concurrent.CountDownLatch; + +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.core.util.Constants; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.apache.logging.log4j.util.Strings; +import org.junit.AfterClass; +import org.junit.Before; +import org.junit.BeforeClass; +import org.junit.Rule; +import org.junit.Test; +import org.junit.experimental.categories.Category; +import org.junit.runner.RunWith; +import org.junit.runners.BlockJUnit4ClassRunner; + +import static org.junit.Assert.*; + +/** + * Tests queue full scenarios with pure AsyncLoggers (all loggers async). + */ +@RunWith(BlockJUnit4ClassRunner.class) +@Category(AsyncLoggers.class) +public class QueueFullAsyncLoggerTest extends QueueFullAbstractTest { + + @BeforeClass + public static void beforeClass() { + System.setProperty("AsyncLogger.RingBufferSize", "128"); // minimum ringbuffer size +// System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName()); + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, + "log4j2-queueFull.xml"); + } + + @AfterClass + public static void afterClass() { + System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR, Strings.EMPTY); + } + + @Rule + public LoggerContextRule context = new LoggerContextRule( + "log4j2-queueFull.xml", AsyncLoggerContextSelector.class); + + @Before + public void before() throws Exception { + blockingAppender = context.getRequiredAppender("Blocking", BlockingAppender.class); + } + + + @Test(timeout = 5000) + public void testNormalQueueFullKeepsMessagesInOrder() throws InterruptedException { + final Logger logger = LogManager.getLogger(this.getClass()); + + blockingAppender.countDownLatch = new CountDownLatch(1); + unlocker = new Unlocker(new CountDownLatch(129)); + unlocker.start(); + + for (int i = 0; i < 130; i++) { + TRACE("Test logging message " + i + ". Remaining capacity=" + getDisruptor(logger).getRingBuffer().remainingCapacity()); + TRACE("Test decrementing unlocker countdown latch. Count=" + unlocker.countDownLatch.getCount()); + unlocker.countDownLatch.countDown(); + final String param = "I'm innocent"; + logger.info(new ParameterizedMessage("logging innocent object #{} {}", i, param)); + } + TRACE("Before stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + //CoreLoggerContexts.stopLoggerContext(false); // stop async thread + while (blockingAppender.logEvents.size() < 130) { Thread.yield(); } + TRACE("After stop() blockingAppender.logEvents.count=" + blockingAppender.logEvents.size()); + + final Stack<String> actual = transform(blockingAppender.logEvents); + for (int i = 0; i < 130; i++) { + assertEquals("logging innocent object #" + i + " I'm innocent", actual.pop()); + } + assertTrue(actual.isEmpty()); + } +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/resources/log4j2-queueFull.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/log4j2-queueFull.xml b/log4j-core/src/test/resources/log4j2-queueFull.xml new file mode 100644 index 0000000..c75e3a9 --- /dev/null +++ b/log4j-core/src/test/resources/log4j2-queueFull.xml @@ -0,0 +1,28 @@ +<?xml version="1.0" encoding="UTF-8"?> +<!-- + ~ 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. + --> +<Configuration status="WARN"> + <Appenders> + <Blocking name="Blocking"> + </Blocking> + </Appenders> + <Loggers> + <Root level="debug"> + <AppenderRef ref="Blocking" /> + </Root> + </Loggers> +</Configuration> \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b478b97e/log4j-core/src/test/resources/log4j2-queueFullAsyncLoggerConfig.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/log4j2-queueFullAsyncLoggerConfig.xml b/log4j-core/src/test/resources/log4j2-queueFullAsyncLoggerConfig.xml new file mode 100644 index 0000000..127a88c --- /dev/null +++ b/log4j-core/src/test/resources/log4j2-queueFullAsyncLoggerConfig.xml @@ -0,0 +1,28 @@ +<?xml version="1.0" encoding="UTF-8"?> +<!-- + ~ 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. + --> +<Configuration status="WARN"> + <Appenders> + <Blocking name="Blocking"> + </Blocking> + </Appenders> + <Loggers> + <AsyncRoot level="debug"> + <AppenderRef ref="Blocking" /> + </AsyncRoot> + </Loggers> +</Configuration> \ No newline at end of file
