Repository: logging-log4j2 Updated Branches: refs/heads/master 7007b861c -> ae87a679f
LOG4J2-1583 Fixed scrambled log messages triggered by nested logging from toString() method of a logging parameter object. Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/ae87a679 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/ae87a679 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/ae87a679 Branch: refs/heads/master Commit: ae87a679f4a04a2b1f3458fe62e469ae806a7eb9 Parents: 7007b86 Author: rpopma <rpo...@apache.org> Authored: Sat Sep 17 22:04:51 2016 +0900 Committer: rpopma <rpo...@apache.org> Committed: Sat Sep 17 22:04:51 2016 +0900 ---------------------------------------------------------------------- .../log4j/message/ReusableMessageFactory.java | 15 ++- .../message/ReusableParameterizedMessage.java | 12 +- .../logging/log4j/spi/AbstractLogger.java | 78 ++++++----- .../message/ReusableMessageFactoryTest.java | 130 ++++++++++++++++++ .../logging/log4j/core/config/LoggerConfig.java | 8 +- .../log4j/core/impl/MutableLogEvent.java | 1 + .../core/impl/ReusableLogEventFactory.java | 20 ++- .../impl/NestedLoggingFromToStringTest.java | 132 +++++++++++++++++++ .../core/impl/ReusableLogEventFactoryTest.java | 20 +++ .../src/test/resources/log4j-sync-to-list.xml | 35 +++++ src/changes/changes.xml | 5 +- 11 files changed, 416 insertions(+), 40 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java index 9a6329b..d75ca01 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java @@ -55,7 +55,7 @@ public final class ReusableMessageFactory implements MessageFactory2, Serializab result = new ReusableParameterizedMessage(); threadLocalParameterized.set(result); } - return result; + return result.reserved ? new ReusableParameterizedMessage().reserve() : result.reserve(); } private static ReusableSimpleMessage getSimple() { @@ -76,6 +76,19 @@ public final class ReusableMessageFactory implements MessageFactory2, Serializab return result; } + /** + * Switches the {@code reserved} flag off if the specified message is a ReusableParameterizedMessage, + * otherwise does nothing. This flag is used internally to verify that a reusable message is no longer in use and + * can be reused. + * @param message the message to make available again + * @since 2.7 + */ + public static void release(final Message message) { // LOG4J2-1583 + if (message instanceof ReusableParameterizedMessage) { + ((ReusableParameterizedMessage) message).reserved = false; + } + } + @Override public Message newMessage(final CharSequence charSequence) { final ReusableSimpleMessage result = getSimple(); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java index 96f5394..85573b1 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java @@ -33,7 +33,7 @@ public class ReusableParameterizedMessage implements ReusableMessage { private static final int MIN_BUILDER_SIZE = 512; private static final int MAX_PARMS = 10; private static final long serialVersionUID = 7800075879295123856L; - private static ThreadLocal<StringBuilder> buffer = new ThreadLocal<>(); + private ThreadLocal<StringBuilder> buffer = new ThreadLocal<>(); // non-static: LOG4J2-1583 private String messagePattern; private int argCount; @@ -42,6 +42,7 @@ public class ReusableParameterizedMessage implements ReusableMessage { private transient Object[] varargs; private transient Object[] params = new Object[MAX_PARMS]; private transient Throwable throwable; + transient boolean reserved = false; // LOG4J2-1583 prevent scrambled logs with nested logging calls /** * Creates a reusable message. @@ -308,6 +309,15 @@ public class ReusableParameterizedMessage implements ReusableMessage { } } + /** + * Sets the reserved flag to true and returns this object. + * @return this object + * @since 2.7 + */ + ReusableParameterizedMessage reserve() { + reserved = true; + return this; + } @Override public String toString() { http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/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 475e93f..84ce567 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 @@ -169,14 +169,14 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { */ protected void catching(final String fqcn, final Level level, final Throwable t) { if (isEnabled(level, CATCHING_MARKER, (Object) null, null)) { - logMessage(fqcn, level, CATCHING_MARKER, catchingMsg(t), t); + logMessageSafely(fqcn, level, CATCHING_MARKER, catchingMsg(t), t); } } @Override public void catching(final Throwable t) { if (isEnabled(Level.ERROR, CATCHING_MARKER, (Object) null, null)) { - logMessage(FQCN, Level.ERROR, CATCHING_MARKER, catchingMsg(t), t); + logMessageSafely(FQCN, Level.ERROR, CATCHING_MARKER, catchingMsg(t), t); } } @@ -501,7 +501,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected EntryMessage enter(final String fqcn, final String format, final Supplier<?>... paramSuppliers) { EntryMessage entryMsg = null; if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, paramSuppliers), null); + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, paramSuppliers), null); } return entryMsg; } @@ -517,7 +517,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected EntryMessage enter(final String fqcn, final String format, final MessageSupplier... paramSuppliers) { EntryMessage entryMsg = null; if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, paramSuppliers), null); + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, paramSuppliers), null); } return entryMsg; } @@ -532,7 +532,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected EntryMessage enter(final String fqcn, final String format, final Object... params) { EntryMessage entryMsg = null; if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, params), null); + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg = entryMsg(format, params), null); } return entryMsg; } @@ -547,7 +547,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected EntryMessage enter(final String fqcn, final MessageSupplier msgSupplier) { EntryMessage message = null; if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, message = flowMessageFactory.newEntryMessage( + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, message = flowMessageFactory.newEntryMessage( msgSupplier.get()), null); } return message; @@ -565,7 +565,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected EntryMessage enter(final String fqcn, final Message message) { EntryMessage flowMessage = null; if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, flowMessage = flowMessageFactory.newEntryMessage(message), + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, flowMessage = flowMessageFactory.newEntryMessage(message), null); } return flowMessage; @@ -590,9 +590,9 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected void entry(final String fqcn, final Object... params) { if (isEnabled(Level.TRACE, ENTRY_MARKER, (Object) null, null)) { if (params == null) { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, (Supplier<?>[]) null), null); + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, (Supplier<?>[]) null), null); } else { - logMessage(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, params), null); + logMessageSafely(fqcn, Level.TRACE, ENTRY_MARKER, entryMsg(null, params), null); } } } @@ -1810,7 +1810,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final Message msg, final Throwable t) { if (isEnabled(level, marker, msg, t)) { - logMessage(fqcn, level, marker, msg, t); + logMessageSafely(fqcn, level, marker, msg, t); } } @@ -1963,117 +1963,117 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { protected void logMessage(final String fqcn, final Level level, final Marker marker, final CharSequence message, final Throwable t) { - logMessage(fqcn, level, marker, messageFactory.newMessage(message), t); + logMessageSafely(fqcn, level, marker, messageFactory.newMessage(message), t); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final Object message, final Throwable t) { - logMessage(fqcn, level, marker, messageFactory.newMessage(message), t); + logMessageSafely(fqcn, level, marker, messageFactory.newMessage(message), t); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final MessageSupplier msgSupplier, final Throwable t) { final Message message = LambdaUtil.get(msgSupplier); - logMessage(fqcn, level, marker, message, t); + logMessageSafely(fqcn, level, marker, message, t); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final Supplier<?> msgSupplier, final Throwable t) { final Message message = LambdaUtil.getMessage(msgSupplier, messageFactory); - logMessage(fqcn, level, marker, message, t); + logMessageSafely(fqcn, level, marker, message, t); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Throwable t) { - logMessage(fqcn, level, marker, messageFactory.newMessage(message), t); + logMessageSafely(fqcn, level, marker, messageFactory.newMessage(message), t); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message) { final Message msg = messageFactory.newMessage(message); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object... params) { final Message msg = messageFactory.newMessage(message, params); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0) { final Message msg = messageFactory.newMessage(message, p0); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1) { final Message msg = messageFactory.newMessage(message, p0, p1); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2) { final Message msg = messageFactory.newMessage(message, p0, p1, p2); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4, final Object p5) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4, p5); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4, final Object p5, final Object p6) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4, p5, p6); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4, final Object p5, final Object p6, final Object p7) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4, p5, p6, p7); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4, final Object p5, final Object p6, final Object p7, final Object p8) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4, p5, p6, p7, p8); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Object p0, final Object p1, final Object p2, final Object p3, final Object p4, final Object p5, final Object p6, final Object p7, final Object p8, final Object p9) { final Message msg = messageFactory.newMessage(message, p0, p1, p2, p3, p4, p5, p6, p7, p8, p9); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message, final Supplier<?>... paramSuppliers) { final Message msg = messageFactory.newMessage(message, LambdaUtil.getAll(paramSuppliers)); - logMessage(fqcn, level, marker, msg, msg.getThrowable()); + logMessageSafely(fqcn, level, marker, msg, msg.getThrowable()); } @Override public void printf(final Level level, final Marker marker, final String format, final Object... params) { if (isEnabled(level, marker, format, params)) { final Message msg = new StringFormattedMessage(format, params); - logMessage(FQCN, level, marker, msg, msg.getThrowable()); + logMessageSafely(FQCN, level, marker, msg, msg.getThrowable()); } } @@ -2081,7 +2081,17 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { public void printf(final Level level, final String format, final Object... params) { if (isEnabled(level, null, format, params)) { final Message msg = new StringFormattedMessage(format, params); - logMessage(FQCN, level, null, msg, msg.getThrowable()); + logMessageSafely(FQCN, level, null, msg, msg.getThrowable()); + } + } + + private void logMessageSafely(final String fqcn, final Level level, final Marker marker, final Message msg, + final Throwable throwable) { + try { + logMessage(fqcn, level, marker, msg, throwable); + } finally { + // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString()) + ReusableMessageFactory.release(msg); } } @@ -2106,7 +2116,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { */ protected <T extends Throwable> T throwing(final String fqcn, final Level level, final T t) { if (isEnabled(level, THROWING_MARKER, (Object) null, null)) { - logMessage(fqcn, level, THROWING_MARKER, throwingMsg(t), t); + logMessageSafely(fqcn, level, THROWING_MARKER, throwingMsg(t), t); } return t; } @@ -2414,7 +2424,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { public void traceExit(final EntryMessage message) { // If the message is null, traceEnter returned null because flow logging was disabled, we can optimize out calling isEnabled(). if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, null)) { - logMessage(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(message), null); + logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(message), null); } } @@ -2422,7 +2432,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { public <R> R traceExit(final EntryMessage message, final R result) { // If the message is null, traceEnter returned null because flow logging was disabled, we can optimize out calling isEnabled(). if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, null)) { - logMessage(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(result, message), null); + logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(result, message), null); } return result; } @@ -2431,7 +2441,7 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { public <R> R traceExit(final Message message, final R result) { // If the message is null, traceEnter returned null because flow logging was disabled, we can optimize out calling isEnabled(). if (message != null && isEnabled(Level.TRACE, EXIT_MARKER, message, null)) { - logMessage(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(result, message), null); + logMessageSafely(FQCN, Level.TRACE, EXIT_MARKER, flowMessageFactory.newExitMessage(result, message), null); } return result; } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-api/src/test/java/org/apache/logging/log4j/message/ReusableMessageFactoryTest.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/test/java/org/apache/logging/log4j/message/ReusableMessageFactoryTest.java b/log4j-api/src/test/java/org/apache/logging/log4j/message/ReusableMessageFactoryTest.java new file mode 100644 index 0000000..6c62503 --- /dev/null +++ b/log4j-api/src/test/java/org/apache/logging/log4j/message/ReusableMessageFactoryTest.java @@ -0,0 +1,130 @@ +/* + * 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.message; + +import org.junit.Test; + +import static org.junit.Assert.*; + +/** + * Tests the ReusableMessageFactory class. + */ +public class ReusableMessageFactoryTest { + + @Test + public void testCreateEventReturnsDifferentInstanceIfNotReleased() throws Exception { + final ReusableMessageFactory factory = new ReusableMessageFactory(); + final Message message1 = factory.newMessage("text, p0={} p1={} p2={} p3={}", 1, 2, 3, 4); + final Message message2 = factory.newMessage("text, p0={} p1={} p2={} p3={}", 9, 8, 7, 6); + assertNotSame(message1, message2); + ReusableMessageFactory.release(message1); + ReusableMessageFactory.release(message2); + } + + @Test + public void testCreateEventReturnsSameInstance() throws Exception { + final ReusableMessageFactory factory = new ReusableMessageFactory(); + final Message message1 = factory.newMessage("text, p0={} p1={} p2={} p3={}", 1, 2, 3, 4); + + ReusableMessageFactory.release(message1); + final Message message2 = factory.newMessage("text, p0={} p1={} p2={} p3={}", 9, 8, 7, 6); + assertSame(message1, message2); + + ReusableMessageFactory.release(message2); + final Message message3 = factory.newMessage("text, AAA={} BBB={} p2={} p3={}", 9, 8, 7, 6); + assertSame(message2, message3); + ReusableMessageFactory.release(message3); + } + + private void assertReusableParameterizeMessage(final Message message, final String txt, final Object[] params) { + assertTrue(message instanceof ReusableParameterizedMessage); + ReusableParameterizedMessage msg = (ReusableParameterizedMessage) message; + assertTrue("reserved", msg.reserved); + + assertEquals(txt, msg.getFormat()); + assertEquals("count", msg.getParameterCount(), params.length); + Object[] messageParams = msg.getParameters(); + for (int i = 0; i < params.length; i++) { + assertEquals(messageParams[i], params[i]); + } + } + + @Test + public void testCreateEventOverwritesFields() throws Exception { + final ReusableMessageFactory factory = new ReusableMessageFactory(); + final Message message1 = factory.newMessage("text, p0={} p1={} p2={} p3={}", 1, 2, 3, 4); + assertReusableParameterizeMessage(message1, "text, p0={} p1={} p2={} p3={}", new Object[]{ + new Integer(1), // + new Integer(2), // + new Integer(3), // + new Integer(4), // + }); + + ReusableMessageFactory.release(message1); + final Message message2 = factory.newMessage("other, A={} B={} C={} D={}", 1, 2, 3, 4); + assertReusableParameterizeMessage(message1, "other, A={} B={} C={} D={}", new Object[]{ + new Integer(1), // + new Integer(2), // + new Integer(3), // + new Integer(4), // + }); + assertSame(message1, message2); + ReusableMessageFactory.release(message2); + } + + @Test + public void testCreateEventReturnsThreadLocalInstance() throws Exception { + final ReusableMessageFactory factory = new ReusableMessageFactory(); + final Message[] message1 = new Message[1]; + final Message[] message2 = new Message[1]; + final Thread t1 = new Thread("THREAD 1") { + @Override + public void run() { + message1[0] = factory.newMessage("text, p0={} p1={} p2={} p3={}", 1, 2, 3, 4); + } + }; + final Thread t2 = new Thread("Thread 2") { + @Override + public void run() { + message2[0] = factory.newMessage("other, A={} B={} C={} D={}", 1, 2, 3, 4); + } + }; + t1.start(); + t2.start(); + t1.join(); + t2.join(); + assertNotNull(message1[0]); + assertNotNull(message2[0]); + assertNotSame(message1[0], message2[0]); + assertReusableParameterizeMessage(message1[0], "text, p0={} p1={} p2={} p3={}", new Object[]{ + new Integer(1), // + new Integer(2), // + new Integer(3), // + new Integer(4), // + }); + + assertReusableParameterizeMessage(message2[0], "other, A={} B={} C={} D={}", new Object[]{ + new Integer(1), // + new Integer(2), // + new Integer(3), // + new Integer(4), // + }); + ReusableMessageFactory.release(message1[0]); + ReusableMessageFactory.release(message2[0]); + } + +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java index cc125b5..98b586f 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java @@ -397,7 +397,13 @@ public class LoggerConfig extends AbstractFilterable { } } } - log(logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t)); + final LogEvent logEvent = logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t); + try { + log(logEvent); + } finally { + // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString()) + ReusableLogEventFactory.release(logEvent); + } } /** http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/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 f0a20c9..68f7b78 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 @@ -61,6 +61,7 @@ public class MutableLogEvent implements LogEvent, ReusableMessage { private String loggerFqcn; private StackTraceElement source; private ThreadContext.ContextStack contextStack; + transient boolean reserved = false; public MutableLogEvent() { this(new StringBuilder(Constants.INITIAL_REUSABLE_MESSAGE_SIZE), new Object[10]); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java index 7b27386..825f1f7 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactory.java @@ -59,15 +59,19 @@ public class ReusableLogEventFactory implements LogEventFactory { final String fqcn, final Level level, final Message message, final List<Property> properties, final Throwable t) { MutableLogEvent result = mutableLogEventThreadLocal.get(); - if (result == null) { + if (result == null || result.reserved) { + final boolean initThreadLocal = result == null; result = new MutableLogEvent(); // usually no need to re-initialize thread-specific fields since the event is stored in a ThreadLocal result.setThreadId(Thread.currentThread().getId()); result.setThreadName(Thread.currentThread().getName()); // Thread.getName() allocates Objects on each call result.setThreadPriority(Thread.currentThread().getPriority()); - mutableLogEventThreadLocal.set(result); + if (initThreadLocal) { + mutableLogEventThreadLocal.set(result); + } } + result.reserved = true; result.clear(); // ensure any previously cached values (thrownProxy, source, etc.) are cleared result.setLoggerName(loggerName); @@ -89,4 +93,16 @@ public class ReusableLogEventFactory implements LogEventFactory { } return result; } + + /** + * Switches the {@code reserved} flag off if the specified event is a MutableLogEvent, otherwise does nothing. + * This flag is used internally to verify that a reusable log event is no longer in use and can be reused. + * @param logEvent the log event to make available again + * @since 2.7 + */ + public static void release(final LogEvent logEvent) { // LOG4J2-1583 + if (logEvent instanceof MutableLogEvent) { + ((MutableLogEvent) logEvent).reserved = false; + } + } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/NestedLoggingFromToStringTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/NestedLoggingFromToStringTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/NestedLoggingFromToStringTest.java new file mode 100644 index 0000000..995232a --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/NestedLoggingFromToStringTest.java @@ -0,0 +1,132 @@ +/* + * 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.impl; + +import java.util.List; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.apache.logging.log4j.test.appender.ListAppender; +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; + +import static org.junit.Assert.*; + +/** + * There are two logger.info() calls here. + * + * The outer one (in main()) indirectly invokes the inner one in the Thing.toString() method. + * + * The inner one comes out cleanly, but leaves ReusableParameterizedMessage.indices altered and this messes up + * the output of the outer call (which is still on the stack). + * + * <pre> + * 16:35:34.781 INFO [main] problem.demo.apache.log4j2.Log4j2ProblemDemo - getX: values x=3 y=4 z=5 + * 16:35:34.782 INFO [main] problem.demo.apache.log4j2.Log4j2ProblemDemo - getX: values x=3 y=4 z=5[Thing x=3 y=4 z=5] + * </pre> + * @author lwest + * @since 2016-09-14 in recursion + */ +public class NestedLoggingFromToStringTest { + + @Rule + public LoggerContextRule context = new LoggerContextRule("log4j-sync-to-list.xml"); + private ListAppender listAppender; + private Logger logger; + + @Before + public void before() { + listAppender = context.getListAppender("List"); + logger = LogManager.getLogger(NestedLoggingFromToStringTest.class); + } + + static class ParameterizedLoggingThing { + final Logger innerLogger = LogManager.getLogger(ParameterizedLoggingThing.class); + private int x = 3, y = 4, z = 5; + public int getX() { + innerLogger.debug("getX: values x={} y={} z={}", x, y, z); + return x; + } + @Override public String toString() { + return "[" + this.getClass().getSimpleName() + " x=" + getX() + " y=" + y + " z=" + z + "]"; + } + } + + static class ObjectLoggingThing1 { + final Logger innerLogger = LogManager.getLogger(ObjectLoggingThing1.class); + public int getX() { + innerLogger.trace(new ObjectLoggingThing2()); + return 999; + } + @Override public String toString() { + return "[" + this.getClass().getSimpleName() + " y=" + getX() + "]"; + } + } + + static class ObjectLoggingThing2 { + final Logger innerLogger = LogManager.getLogger(ObjectLoggingThing2.class); + public int getX() { + innerLogger.trace(new ParameterizedLoggingThing()); + return 123; + } + @Override public String toString() { + return "[" + this.getClass().getSimpleName() + " x=" + getX() + "]"; + } + } + + @Test + public void testNestedLoggingInLastArgument() { + ParameterizedLoggingThing it = new ParameterizedLoggingThing(); + logger.info("main: argCount={} it={}", "2", it); + final List<String> list = listAppender.getMessages(); + + String expect1 = "DEBUG org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest$ParameterizedLoggingThing getX: values x=3 y=4 z=5"; + String expect2 = "INFO org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest main: argCount=2 it=[ParameterizedLoggingThing x=3 y=4 z=5]"; + assertEquals(expect1, list.get(0)); + assertEquals(expect2, list.get(1)); + } + + @Test + public void testNestedLoggingInFirstArgument() { + ParameterizedLoggingThing it = new ParameterizedLoggingThing(); + logger.info("next: it={} some{} other{}", it, "AA", "BB"); + final List<String> list = listAppender.getMessages(); + + String expect1 = "DEBUG org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest$ParameterizedLoggingThing getX: values x=3 y=4 z=5"; + String expect2 = "INFO org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest next: it=[ParameterizedLoggingThing x=3 y=4 z=5] someAA otherBB"; + assertEquals(expect1, list.get(0)); + assertEquals(expect2, list.get(1)); + } + + @Test + public void testDoublyNestedLogging() { + logger.info(new ObjectLoggingThing1()); + final List<String> list = listAppender.getMessages(); + + String expect1 = "DEBUG org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest$ParameterizedLoggingThing getX: values x=3 y=4 z=5"; + String expect2 = "TRACE org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest$ObjectLoggingThing2 [ParameterizedLoggingThing x=3 y=4 z=5]"; + String expect3 = "TRACE org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest$ObjectLoggingThing1 [ObjectLoggingThing2 x=123]"; + String expect4 = "INFO org.apache.logging.log4j.core.impl.NestedLoggingFromToStringTest [ObjectLoggingThing1 y=999]"; + assertEquals(expect1, list.get(0)); + assertEquals(expect2, list.get(1)); + assertEquals(expect3, list.get(2)); + assertEquals(expect4, list.get(3)); + } + +} \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactoryTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactoryTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactoryTest.java index cd41263..dfc1e90 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactoryTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/impl/ReusableLogEventFactoryTest.java @@ -30,11 +30,27 @@ import static org.junit.Assert.*; public class ReusableLogEventFactoryTest { @Test + public void testCreateEventReturnsDifferentInstanceIfNotReleased() throws Exception { + final ReusableLogEventFactory factory = new ReusableLogEventFactory(); + final LogEvent event1 = callCreateEvent(factory, "a", Level.DEBUG, new SimpleMessage("abc"), null); + final LogEvent event2 = callCreateEvent(factory, "b", Level.INFO, new SimpleMessage("xyz"), null); + assertNotSame(event1, event2); + ReusableLogEventFactory.release(event1); + ReusableLogEventFactory.release(event2); + } + + @Test public void testCreateEventReturnsSameInstance() throws Exception { final ReusableLogEventFactory factory = new ReusableLogEventFactory(); final LogEvent event1 = callCreateEvent(factory, "a", Level.DEBUG, new SimpleMessage("abc"), null); + ReusableLogEventFactory.release(event1); final LogEvent event2 = callCreateEvent(factory, "b", Level.INFO, new SimpleMessage("xyz"), null); assertSame(event1, event2); + + ReusableLogEventFactory.release(event2); + final LogEvent event3 = callCreateEvent(factory, "c", Level.INFO, new SimpleMessage("123"), null); + assertSame(event2, event3); + ReusableLogEventFactory.release(event3); } @Test @@ -45,6 +61,7 @@ public class ReusableLogEventFactoryTest { assertEquals("level", Level.DEBUG, event1.getLevel()); assertEquals("msg", new SimpleMessage("abc"), event1.getMessage()); + ReusableLogEventFactory.release(event1); final LogEvent event2 = callCreateEvent(factory, "b", Level.INFO, new SimpleMessage("xyz"), null); assertSame(event1, event2); @@ -96,12 +113,15 @@ public class ReusableLogEventFactoryTest { assertEquals("msg", new SimpleMessage("xyz"), event2[0].getMessage()); assertEquals("thread name", "Thread 2", event2[0].getThreadName()); assertEquals("tid", t2.getId(), event2[0].getThreadId()); + ReusableLogEventFactory.release(event1[0]); + ReusableLogEventFactory.release(event2[0]); } @Test public void testCreateEventInitFieldsProperly() throws Exception { final ReusableLogEventFactory factory = new ReusableLogEventFactory(); final LogEvent event = callCreateEvent(factory, "logger", Level.INFO, new SimpleMessage("xyz"), null); + ReusableLogEventFactory.release(event); assertNotNull(event.getContextMap()); assertNotNull(event.getContextStack()); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/log4j-core/src/test/resources/log4j-sync-to-list.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/log4j-sync-to-list.xml b/log4j-core/src/test/resources/log4j-sync-to-list.xml new file mode 100644 index 0000000..6030bca --- /dev/null +++ b/log4j-core/src/test/resources/log4j-sync-to-list.xml @@ -0,0 +1,35 @@ +<?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="OFF" name="NestedLoggingInToString"> + + <Appenders> + <Console name="STDOUT"> + <PatternLayout pattern="%c %m%n"/> + </Console> + <List name="List"> + <PatternLayout pattern="%level %logger %m"/> + </List> + </Appenders> + + <Loggers> + <Root level="trace"> + <AppenderRef ref="List"/> + </Root> + </Loggers> +</Configuration> \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/ae87a679/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index d4f9371..f1df943 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -24,8 +24,11 @@ </properties> <body> <release version="2.7" date="2016-MM-DD" description="GA Release 2.7"> + <action issue="LOG4J2-1583" dev="rpopma" type="fix" due-to="Larry West"> + Fixed scrambled log messages triggered by nested logging from toString() method of a logging parameter object. + </action> <action issue="LOG4J2-1259" dev="ggregory" type="fix" due-to="Misagh Moayyed, Steffen Offermann"> - Log4j threads are leaking on Tomcat shutdown. + Log4j threads are no longer leaking on Tomcat shutdown. </action> <action issue="LOG4J2-1051" dev="rpopma" type="fix" due-to="Lukasz Lenart"> When starting on Google App Engine, Interpolator now suppresses the NoClassDefFoundError stack trace for the jvmrunargs lookup.
