You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by ck...@apache.org on 2018/04/24 13:40:07 UTC

[7/8] logging-log4j2 git commit: LOG4J2-2269: ReusableLogEventFactory.release clears MutableLogEvent

LOG4J2-2269: ReusableLogEventFactory.release clears MutableLogEvent

Fixes a memory leak where parameter references were held beyond
MutableLogEvent usage.


Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/9496c0c2
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/9496c0c2
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/9496c0c2

Branch: refs/heads/release-2.x
Commit: 9496c0c2d7c25257933d523664896920789d6610
Parents: 0cd0f23
Author: Carter Kozak <ck...@apache.org>
Authored: Fri Apr 13 19:27:54 2018 -0700
Committer: Carter Kozak <ck...@apache.org>
Committed: Tue Apr 24 09:24:18 2018 -0400

----------------------------------------------------------------------
 .../core/impl/ReusableLogEventFactory.java      |   4 +-
 .../core/EventParameterMemoryLeakTest.java      | 138 +++++++++++++++++++
 .../core/impl/ReusableLogEventFactoryTest.java  |  11 +-
 .../resources/EventParameterMemoryLeakTest.xml  |  19 +++
 4 files changed, 167 insertions(+), 5 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9496c0c2/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 0ecefed..dd5cf62 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
@@ -98,7 +98,9 @@ public class ReusableLogEventFactory implements LogEventFactory {
      */
     public static void release(final LogEvent logEvent) { // LOG4J2-1583
         if (logEvent instanceof MutableLogEvent) {
-            ((MutableLogEvent) logEvent).reserved = false;
+            MutableLogEvent mutableLogEvent = (MutableLogEvent) logEvent;
+            mutableLogEvent.clear();
+            mutableLogEvent.reserved = false;
         }
     }
 }

http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9496c0c2/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java
----------------------------------------------------------------------
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
new file mode 100644
index 0000000..de99eef
--- /dev/null
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java
@@ -0,0 +1,138 @@
+/*
+ * 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;
+
+import com.google.common.io.ByteStreams;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.config.ConfigurationFactory;
+import org.junit.BeforeClass;
+import org.junit.Test;
+
+import java.io.BufferedReader;
+import java.io.Closeable;
+import java.io.File;
+import java.io.FileReader;
+import java.io.IOException;
+import java.io.OutputStream;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicBoolean;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.containsString;
+import static org.junit.Assert.assertNull;
+import static org.junit.Assert.assertTrue;
+
+public class EventParameterMemoryLeakTest {
+
+    @BeforeClass
+    public static void beforeClass() {
+        System.setProperty("log4j2.enable.threadlocals", "true");
+        System.setProperty("log4j2.enable.direct.encoders", "true");
+        System.setProperty("log4j2.is.webapp", "false");
+        System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, "EventParameterMemoryLeakTest.xml");
+    }
+
+    @Test
+    public void testParametersAreNotLeaked() throws Exception {
+        final File file = new File("target", "EventParameterMemoryLeakTest.log");
+        assertTrue("Deleted old file before test", !file.exists() || file.delete());
+
+        final Logger log = LogManager.getLogger("com.foo.Bar");
+        CountDownLatch latch = new CountDownLatch(1);
+        log.info("Message with parameter {}", new ParameterObject("paramValue", latch));
+        CoreLoggerContexts.stopLoggerContext(file);
+        final BufferedReader reader = new BufferedReader(new FileReader(file));
+        final String line1 = reader.readLine();
+        final String line2 = reader.readLine();
+        reader.close();
+        file.delete();
+        assertThat(line1, containsString("Message with parameter paramValue"));
+        assertNull("Expected only a single line", line2);
+        GarbageCollectionHelper gcHelper = new GarbageCollectionHelper();
+        gcHelper.run();
+        try {
+            assertTrue("Parameter should have been garbage collected", latch.await(30, TimeUnit.SECONDS));
+        } finally {
+            gcHelper.close();
+        }
+    }
+
+    private static final class ParameterObject {
+        private final String value;
+        private final CountDownLatch latch;
+        ParameterObject(String value, CountDownLatch latch) {
+            this.value = value;
+            this.latch = latch;
+        }
+
+        @Override
+        public String toString() {
+            return value;
+        }
+
+        @Override
+        protected void finalize() throws Throwable {
+            latch.countDown();
+            super.finalize();
+        }
+    }
+
+    private static final class GarbageCollectionHelper implements Closeable, Runnable {
+        private static final OutputStream sink = ByteStreams.nullOutputStream();
+        public final AtomicBoolean running = new AtomicBoolean();
+        private final CountDownLatch latch = new CountDownLatch(1);
+        private final Thread gcThread = new Thread(new Runnable() {
+            @Override
+            public void run() {
+                try {
+                    while (running.get()) {
+                        // Allocate data to help suggest a GC
+                        try {
+                            // 1mb of heap
+                            sink.write(new byte[1024 * 1024]);
+                        } catch (IOException ignored) {
+                        }
+                        // May no-op depending on the jvm configuration
+                        System.gc();
+                    }
+                } finally {
+                    latch.countDown();
+                }
+            }
+        });
+
+        @Override
+        public void run() {
+            if (running.compareAndSet(false, true)) {
+                gcThread.start();
+            }
+        }
+
+        @Override
+        public void close() {
+            running.set(false);
+            try {
+                assertTrue("GarbageCollectionHelper did not shut down cleanly",
+                        latch.await(10, TimeUnit.SECONDS));
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+        }
+    }
+}

http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9496c0c2/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 61eb8d7..cb9eea3 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
@@ -122,10 +122,13 @@ public class ReusableLogEventFactoryTest {
     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.getContextData());
-        assertNotNull(event.getContextStack());
+        try {
+            assertNotNull(event.getContextMap());
+            assertNotNull(event.getContextData());
+            assertNotNull(event.getContextStack());
+        } finally {
+            ReusableLogEventFactory.release(event);
+        }
     }
 
 }
\ No newline at end of file

http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9496c0c2/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml b/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml
new file mode 100644
index 0000000..b626375
--- /dev/null
+++ b/log4j-core/src/test/resources/EventParameterMemoryLeakTest.xml
@@ -0,0 +1,19 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration status="ERROR">
+  <Appenders>
+    <File name="File"
+          fileName="target/EventParameterMemoryLeakTest.log"
+          bufferedIO="false"
+          immediateFlush="true"
+          append="false">
+      <PatternLayout>
+        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
+      </PatternLayout>
+    </File>
+  </Appenders>
+  <Loggers>
+    <Root level="trace">
+      <AppenderRef ref="File"/>
+    </Root>
+  </Loggers>
+</Configuration>