Repository: logging-log4j2 Updated Branches: refs/heads/master d0bc42955 -> b5ba8b788
LOG4J2-1988, LOG4J2-1914 prevent ConcurrentModificationException with AsyncLoggerConfig Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/95dedcff Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/95dedcff Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/95dedcff Branch: refs/heads/master Commit: 95dedcff70687c1782a36cb6177272dddd64cab1 Parents: a0e946d Author: rpopma <[email protected]> Authored: Sat Sep 16 00:49:31 2017 +0900 Committer: rpopma <[email protected]> Committed: Sat Sep 16 00:49:31 2017 +0900 ---------------------------------------------------------------------- .../log4j/core/appender/AsyncAppender.java | 13 +--- .../logging/log4j/core/async/AsyncLogger.java | 11 +-- .../core/async/AsyncLoggerConfigDisruptor.java | 32 ++++++++- .../log4j/core/async/InternalAsyncUtil.java | 50 ++++++++++++++ .../log4j/core/async/RingBufferLogEvent.java | 12 +--- .../log4j/core/impl/MutableLogEvent.java | 13 +--- .../core/async/AsyncLoggerConfigTest3.java | 72 ++++++++++++++++++++ .../test/resources/AsyncLoggerConfigTest2.xml | 12 ++-- src/changes/changes.xml | 6 ++ 9 files changed, 170 insertions(+), 51 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/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 1e3626c..b104083 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 @@ -35,6 +35,7 @@ import org.apache.logging.log4j.core.async.AsyncQueueFullPolicyFactory; import org.apache.logging.log4j.core.async.BlockingQueueFactory; import org.apache.logging.log4j.core.async.DiscardingAsyncQueueFullPolicy; import org.apache.logging.log4j.core.async.EventRoute; +import org.apache.logging.log4j.core.async.InternalAsyncUtil; import org.apache.logging.log4j.core.config.AppenderControl; import org.apache.logging.log4j.core.config.AppenderRef; import org.apache.logging.log4j.core.config.Configuration; @@ -47,10 +48,7 @@ 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.validation.constraints.Required; import org.apache.logging.log4j.core.impl.Log4jLogEvent; -import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.Log4jThread; -import org.apache.logging.log4j.message.AsynchronouslyFormattable; -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 @@ -156,10 +154,8 @@ public final class AsyncAppender extends AbstractAppender { if (!isStarted()) { throw new IllegalStateException("AsyncAppender " + getName() + " is not active"); } - if (!canFormatMessageInBackground(logEvent.getMessage())) { - logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters - } final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation); + 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) @@ -172,11 +168,6 @@ public final class AsyncAppender extends AbstractAppender { } } - private boolean canFormatMessageInBackground(final Message message) { - return Constants.FORMAT_MESSAGES_IN_BACKGROUND // LOG4J2-898: user wants to format all msgs in background - || message.getClass().isAnnotationPresent(AsynchronouslyFormattable.class); // LOG4J2-1718 - } - private boolean transfer(final LogEvent memento) { return queue instanceof TransferQueue ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento) http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/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 2fe2276..b6e4c53 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 @@ -32,9 +32,7 @@ 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; -import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.NanoClock; -import org.apache.logging.log4j.message.AsynchronouslyFormattable; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.message.ReusableMessage; @@ -244,19 +242,14 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf return; } // if the Message instance is reused, there is no point in freezing its message here - if (!canFormatMessageInBackground(message) && !isReused(message)) { - message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters + if (!isReused(message)) { + InternalAsyncUtil.makeMessageImmutable(message); } // calls the translateTo method on this AsyncLogger disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message, thrown); } - private boolean canFormatMessageInBackground(final Message message) { - return Constants.FORMAT_MESSAGES_IN_BACKGROUND // LOG4J2-898: user wants to format all msgs in background - || message.getClass().isAnnotationPresent(AsynchronouslyFormattable.class); // LOG4J2-1718 - } - /* * (non-Javadoc) * http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java ---------------------------------------------------------------------- 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 9dbd4b1..cc3e77b 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 @@ -184,6 +184,7 @@ public class AsyncLoggerConfigDisruptor extends AbstractLifeCycle implements Asy private long backgroundThreadId; // LOG4J2-471 private EventFactory<Log4jEventWrapper> factory; private EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig> translator; + private volatile boolean alreadyLoggedWarning = false; public AsyncLoggerConfigDisruptor() { } @@ -335,13 +336,38 @@ public class AsyncLoggerConfigDisruptor extends AbstractLifeCycle implements Asy } private LogEvent prepareEvent(final LogEvent event) { - final LogEvent logEvent = ensureImmutable(event); - if (logEvent instanceof Log4jLogEvent && logEvent.getMessage() instanceof ReusableMessage) { - ((Log4jLogEvent) logEvent).makeMessageImmutable(); + LogEvent logEvent = ensureImmutable(event); + if (logEvent.getMessage() instanceof ReusableMessage) { + if (logEvent instanceof Log4jLogEvent) { + ((Log4jLogEvent) logEvent).makeMessageImmutable(); + } else if (logEvent instanceof MutableLogEvent) { + // MutableLogEvents need to be translated into the RingBuffer by the MUTABLE_TRANSLATOR. + // That translator calls MutableLogEvent.initFrom to copy the event, which will makeMessageImmutable the message. + if (translator != MUTABLE_TRANSLATOR) { // should not happen... + // TRANSLATOR expects an immutable LogEvent + logEvent = ((MutableLogEvent) logEvent).createMemento(); + } + } else { // custom log event, with a ReusableMessage + showWarningAboutCustomLogEventWithReusableMessage(logEvent); + } + } else { // message is not a ReusableMessage; makeMessageImmutable it to prevent ConcurrentModificationExceptions + InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage()); // LOG4J2-1988, LOG4J2-1914 } return logEvent; } + private void showWarningAboutCustomLogEventWithReusableMessage(final LogEvent logEvent) { + if (!alreadyLoggedWarning) { + LOGGER.warn("Custom log event of type {} contains a mutable message of type {}." + + " AsyncLoggerConfig does not know how to make an immutable copy of this message." + + " This may result in ConcurrentModificationExceptions or incorrect log messages" + + " if the application modifies objects in the message while" + + " the background thread is writing it to the appenders.", + logEvent.getClass().getName(), logEvent.getMessage().getClass().getName()); + alreadyLoggedWarning = true; + } + } + private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) { disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java new file mode 100644 index 0000000..4959733 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java @@ -0,0 +1,50 @@ +/* + * 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.core.util.Constants; +import org.apache.logging.log4j.message.AsynchronouslyFormattable; +import org.apache.logging.log4j.message.Message; + +/** + * Helper class providing some async logging-related functionality. + * <p> + * Consider this class private. + * </p> + */ +public class InternalAsyncUtil { + /** + * Returns the specified message, with its content frozen unless system property + * {@code log4j.format.msg.async} is true or the message class is annotated with + * {@link AsynchronouslyFormattable}. + * + * @param msg the message object to inspect, modify and return + * @return Returns the specified message, with its content frozen + */ + public static Message makeMessageImmutable(final Message msg) { + // if the Message instance is reused, there is no point in freezing its message here + if (msg != null && !canFormatMessageInBackground(msg)) { + msg.getFormattedMessage(); // LOG4J2-763: ask message to makeMessageImmutable parameters + } + return msg; + } + + private static boolean canFormatMessageInBackground(final Message message) { + return Constants.FORMAT_MESSAGES_IN_BACKGROUND // LOG4J2-898: user wants to format all msgs in background + || message.getClass().isAnnotationPresent(AsynchronouslyFormattable.class); // LOG4J2-1718 + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java index abfd392..b0b023b 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java @@ -28,7 +28,6 @@ import org.apache.logging.log4j.core.impl.ContextDataFactory; import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.core.impl.ThrowableProxy; import org.apache.logging.log4j.core.util.Constants; -import org.apache.logging.log4j.message.AsynchronouslyFormattable; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.ParameterizedMessage; import org.apache.logging.log4j.message.ReusableMessage; @@ -129,19 +128,10 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen parameterCount = reusable.getParameterCount(); } } else { - // if the Message instance is reused, there is no point in freezing its message here - if (msg != null && !canFormatMessageInBackground(msg)) { - msg.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters - } - this.message = msg; + this.message = InternalAsyncUtil.makeMessageImmutable(msg); } } - private boolean canFormatMessageInBackground(final Message message) { - return Constants.FORMAT_MESSAGES_IN_BACKGROUND // LOG4J2-898: user wants to format all msgs in background - || message.getClass().isAnnotationPresent(AsynchronouslyFormattable.class); // LOG4J2-1718 - } - private StringBuilder getMessageTextForWriting() { if (messageText == null) { // Should never happen: http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java index 97f5ff3..acc31b3 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java @@ -25,8 +25,8 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.Marker; import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.async.InternalAsyncUtil; import org.apache.logging.log4j.core.util.Constants; -import org.apache.logging.log4j.message.AsynchronouslyFormattable; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.ParameterizedMessage; import org.apache.logging.log4j.message.ReusableMessage; @@ -214,19 +214,10 @@ public class MutableLogEvent implements LogEvent, ReusableMessage { parameterCount = reusable.getParameterCount(); } } else { - // if the Message instance is reused, there is no point in freezing its message here - if (msg != null && !canFormatMessageInBackground(msg)) { - msg.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters - } - this.message = msg; + this.message = InternalAsyncUtil.makeMessageImmutable(msg); } } - private boolean canFormatMessageInBackground(final Message message) { - return Constants.FORMAT_MESSAGES_IN_BACKGROUND // LOG4J2-898: user wants to format all msgs in background - || message.getClass().isAnnotationPresent(AsynchronouslyFormattable.class); // LOG4J2-1718 - } - private StringBuilder getMessageTextForWriting() { if (messageText == null) { // Should never happen: http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest3.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest3.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest3.java new file mode 100644 index 0000000..301fb73 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest3.java @@ -0,0 +1,72 @@ +/* + * 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.File; +import java.util.HashMap; +import java.util.Map; + +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.core.impl.Log4jLogEvent; +import org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.junit.Test; +import org.junit.experimental.categories.Category; + +import static org.junit.Assert.*; + +@Category(AsyncLoggers.class) +public class AsyncLoggerConfigTest3 { + + @Test + public void testNoConcurrentModificationException() throws Exception { + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, + "AsyncLoggerConfigTest2.xml"); + final File file = new File("target", "AsyncLoggerConfigTest2.log"); + assertTrue("Deleted old file before test", !file.exists() || file.delete()); + + final Logger log = LogManager.getLogger("com.foo.Bar"); + log.info("initial message"); + Thread.sleep(500); + + final Map<String, String> map = new HashMap<>(); + for (int j = 0; j < 3000; j++) { + map.put(String.valueOf(j), String.valueOf(System.nanoTime())); + } + + final Message msg = new ParameterizedMessage("{}", map); + Log4jLogEvent event = Log4jLogEvent.newBuilder() + .setLevel(Level.WARN) + .setLoggerName(getClass().getName()) + .setMessage(msg) + .setTimeMillis(0).build(); + + for (int i = 0; i < 100; i++) { + ((AsyncLoggerConfig)((org.apache.logging.log4j.core.Logger) log).get()).callAppenders(event); + for (int j = 0; j < 3000; j++) { + map.remove(String.valueOf(j)); + } + for (int j = 0; j < 3000; j++) { + map.put(String.valueOf(j), String.valueOf(System.nanoTime())); + } + } + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/log4j-core/src/test/resources/AsyncLoggerConfigTest2.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/AsyncLoggerConfigTest2.xml b/log4j-core/src/test/resources/AsyncLoggerConfigTest2.xml index 454c1ae..66b9d2c 100644 --- a/log4j-core/src/test/resources/AsyncLoggerConfigTest2.xml +++ b/log4j-core/src/test/resources/AsyncLoggerConfigTest2.xml @@ -1,17 +1,17 @@ <?xml version="1.0" encoding="UTF-8"?> -<Configuration status="OFF"> +<Configuration status="WARN"> <Appenders> - <File name="File" - fileName="target/AsyncLoggerConfigTest2.log" - bufferedIO="false" - immediateFlush="true" + <File name="File" + fileName="target/AsyncLoggerConfigTest2.log" + bufferedIO="false" + immediateFlush="true" append="true"> <PatternLayout> <Pattern>%d %p %c{1.} [%t] %X{aKey} %m %location %ex%n</Pattern> </PatternLayout> </File> </Appenders> - + <Loggers> <AsyncRoot level="info"> <AppenderRef ref="File"/> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/95dedcff/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index b13ea15..d9985ec 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -31,6 +31,12 @@ - "remove" - Removed --> <release version="2.9.1" date="2017-MM-DD" description="GA Release 2.9.1"> + <action issue="LOG4J2-1988" dev="rpopma" type="fix"> + Prevent ConcurrentModificationException with AsyncLoggerConfig. + </action> + <action issue="LOG4J2-1914" dev="rpopma" type="fix"> + Prevent ConcurrentModificationException with AsyncLoggerConfig. + </action> <action issue="LOG4J2-2048" dev="rpopma" type="fix"> Increase default queue size for AsyncAppender from 128 to 1024. </action>
