From 0289e762f86eecc38ceb7dbc659f2bb4b7c2c01c Mon Sep 17 00:00:00 2001 From: Carter Kozak Date: Fri, 29 Jun 2018 17:23:01 -0400 Subject: [PATCH] LOG4J2-2364 Fix ReusableParameterizedMessage memory leak Implement Clearable interface for reusable messages, making it easier to clear references between usages. This closes #186 --- .../logging/log4j/message/Clearable.java | 17 ++++++++++++++ .../log4j/message/ReusableMessageFactory.java | 10 ++++----- .../log4j/message/ReusableObjectMessage.java | 7 +++++- .../message/ReusableParameterizedMessage.java | 12 +++++++++- .../log4j/message/ReusableSimpleMessage.java | 7 +++++- .../core/EventParameterMemoryLeakTest.java | 22 ++++++++++++++++++- .../EventParameterMemoryLeakTest.xml | 2 +- src/changes/changes.xml | 8 +++++++ 8 files changed, 74 insertions(+), 11 deletions(-) create mode 100644 log4j-api/src/main/java/org/apache/logging/log4j/message/Clearable.java diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/Clearable.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/Clearable.java new file mode 100644 index 00000000000..0e213cb739c --- /dev/null +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/Clearable.java @@ -0,0 +1,17 @@ +package org.apache.logging.log4j.message; + +/** + * {@link Clearable} objects may be reset to a reusable state. + * + * This type should be combined into {@link ReusableMessage} as a default method for 3.0. + * + * @since 2.11.1 + */ +interface Clearable { + + /** + * Resets the object to a clean state. + */ + void clear(); + +} 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 c258045da72..bf30cfad623 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 @@ -77,17 +77,15 @@ private static ReusableObjectMessage getObject() { } /** - * 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 + * Invokes {@link Clearable#clear()} when possible. + * 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; - } else if (message instanceof ReusableObjectMessage) { - ((ReusableObjectMessage) message).set(null); + if (message instanceof Clearable) { + ((Clearable) message).clear(); } } diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableObjectMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableObjectMessage.java index c272ab78db7..4844ea1530f 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableObjectMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableObjectMessage.java @@ -24,7 +24,7 @@ * @since 2.6 */ @PerformanceSensitive("allocation") -public class ReusableObjectMessage implements ReusableMessage, ParameterVisitable { +public class ReusableObjectMessage implements ReusableMessage, ParameterVisitable, Clearable { private static final long serialVersionUID = 6922476812535519960L; private transient Object obj; @@ -121,4 +121,9 @@ public void forEachParameter(ParameterConsumer action, S state) { public Message memento() { return new ObjectMessage(obj); } + + @Override + public void clear() { + obj = null; + } } 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 a1431f85c42..cdd4dab5992 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 @@ -30,7 +30,7 @@ * @since 2.6 */ @PerformanceSensitive("allocation") -public class ReusableParameterizedMessage implements ReusableMessage, ParameterVisitable { +public class ReusableParameterizedMessage implements ReusableMessage, ParameterVisitable, Clearable { private static final int MIN_BUILDER_SIZE = 512; private static final int MAX_PARMS = 10; @@ -341,4 +341,14 @@ public String toString() { return "ReusableParameterizedMessage[messagePattern=" + getFormat() + ", stringArgs=" + Arrays.toString(getParameters()) + ", throwable=" + getThrowable() + ']'; } + + @Override + public void clear() { // LOG4J2-1583 + // This method does not clear parameter values, those are expected to be swapped to a + // reusable message, which is responsible for clearing references. + reserved = false; + varargs = null; + messagePattern = null; + throwable = null; + } } diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableSimpleMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableSimpleMessage.java index 49b0d7fde78..2a186be391f 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableSimpleMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableSimpleMessage.java @@ -23,7 +23,7 @@ * @since 2.6 */ @PerformanceSensitive("allocation") -public class ReusableSimpleMessage implements ReusableMessage, CharSequence, ParameterVisitable { +public class ReusableSimpleMessage implements ReusableMessage, CharSequence, ParameterVisitable, Clearable { private static final long serialVersionUID = -9199974506498249809L; private static Object[] EMPTY_PARAMS = new Object[0]; private CharSequence charSequence; @@ -105,5 +105,10 @@ public char charAt(final int index) { public CharSequence subSequence(final int start, final int end) { return charSequence.subSequence(start, end); } + + @Override + public void clear() { + charSequence = null; + } } diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java index d2106f95b2b..ed68ae57f6e 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java @@ -59,17 +59,23 @@ public void testParametersAreNotLeaked() throws Exception { Object parameter = new ParameterObject("paramValue", latch); log.info("Message with parameter {}", parameter); log.info(parameter); + log.info("test", new ObjectThrowable(parameter)); + log.info("test {}", "hello", new ObjectThrowable(parameter)); parameter = null; CoreLoggerContexts.stopLoggerContext(file); final BufferedReader reader = new BufferedReader(new FileReader(file)); final String line1 = reader.readLine(); final String line2 = reader.readLine(); final String line3 = reader.readLine(); + final String line4 = reader.readLine(); + final String line5 = reader.readLine(); reader.close(); file.delete(); assertThat(line1, containsString("Message with parameter paramValue")); assertThat(line2, containsString("paramValue")); - assertNull("Expected only a two lines", line3); + assertThat(line3, containsString("paramValue")); + assertThat(line4, containsString("paramValue")); + assertNull("Expected only three lines", line5); GarbageCollectionHelper gcHelper = new GarbageCollectionHelper(); gcHelper.run(); try { @@ -99,6 +105,20 @@ protected void finalize() throws Throwable { } } + private static final class ObjectThrowable extends RuntimeException { + private final Object object; + + ObjectThrowable(Object object) { + super(String.valueOf(object)); + this.object = object; + } + + @Override + public String toString() { + return "ObjectThrowable " + object; + } + } + private static final class GarbageCollectionHelper implements Closeable, Runnable { private static final OutputStream sink = ByteStreams.nullOutputStream(); public final AtomicBoolean running = new AtomicBoolean(); diff --git a/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml b/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml index b626375a262..226d1c82132 100644 --- a/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml +++ b/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml @@ -7,7 +7,7 @@ immediateFlush="true" append="false"> - %d %p %c{1.} [%t] %m%n + %d %p %c{1.} [%t] %m %throwable{short.message}%n diff --git a/src/changes/changes.xml b/src/changes/changes.xml index da134c918da..269a59682ea 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -200,6 +200,10 @@ Jackson layouts used with AsyncLoggerContextSelector output the expected format rather than only a json string of the message text. + + Fixed a memory leak in which ReusableParameterizedMessage would hold a reference to the most recently + logged throwable and provided varargs array. + @@ -310,6 +314,10 @@ Jackson layouts used with AsyncLoggerContextSelector output the expected format rather than only a json string of the message text. + + Fixed a memory leak in which ReusableParameterizedMessage would hold a reference to the most recently + logged throwable and provided varargs array. +