Prefix stack traces with a newline in Pattern Layout (#3045)

- Exception converters are reworked to ensure a newline
  prefix (which used to be a whitespace)

- Fix property extraction for root exceptions
  (e.g., %rEx{short.className})

Co-authored-by: AlanYu <[email protected]>
Co-authored-by: Piotr P. Karwasz <[email protected]>

Author: 3 people

log4j-core-test/src/test/java/foo/TestFriendlyException.java

@@ -27,18 +27,21 @@
  * A testing friendly exception featuring
  * <ul>
  * <li>Distinct localized message</li>
- * <li>Non-Log4j package origin<sup>1</sup></li>
+ * <li>Non-Log4j<sup>1</sup> and fixed<sup>2</sup> (to {@code bar}) package origin</li>
  * <li>Sufficient causal chain depth</li>
- * <li>Cyclic causal chain</li>
+ * <li>Circular causal chain</li>
  * <li>Suppressed exceptions</li>
  * <li>Clutter-free stack trace (i.e., elements from JUnit, JDK, etc.)</li>
- * <li>Stack trace elements from named modules<sup>2</sup></li>
+ * <li>Stack trace elements from named modules<sup>3</sup></li>
  * </ul>
  * <p>
  * <sup>1</sup> Helps with observing stack trace manipulation effects of Log4j.
  * </p>
  * <p>
- * <sup>2</sup> Helps with testing module name serialization.
+ * <sup>2</sup> Helps to make the origin of {@link #INSTANCE} independent of the first test accessing to it.
+ * </p>
+ * <p>
+ * <sup>3</sup> Helps with testing module name serialization.
  * </p>
  */
 public final class TestFriendlyException extends RuntimeException {
@@ -48,6 +51,9 @@ public final class TestFriendlyException extends RuntimeException {
         assertThat(TestFriendlyException.class.getPackage().getName()).doesNotStartWith("org.apache");
     }
 
+    public static final StackTraceElement ORG_APACHE_REPLACEMENT_STACK_TRACE_ELEMENT =
+            new StackTraceElement("bar.OrgApacheReplacement", "someMethod", "OrgApacheReplacement.java", 0);
+
     public static final StackTraceElement NAMED_MODULE_STACK_TRACE_ELEMENT = namedModuleStackTraceElement();
 
     @SuppressWarnings("resource")
@@ -127,16 +133,29 @@ private static Stream<StackTraceElement> mapStackTraceElement(
 
     private static Stream<StackTraceElement> filterStackTraceElement(
             final StackTraceElement stackTraceElement, final boolean[] seenExcludedStackTraceElement) {
+
+        // Short-circuit if we have already encountered an excluded stack trace element
         if (seenExcludedStackTraceElement[0]) {
             return Stream.empty();
         }
+
+        // Check if the class name is excluded
         final String className = stackTraceElement.getClassName();
         for (final String excludedClassNamePrefix : EXCLUDED_CLASS_NAME_PREFIXES) {
             if (className.startsWith(excludedClassNamePrefix)) {
                 seenExcludedStackTraceElement[0] = true;
                 return Stream.empty();
             }
         }
+
+        // Replace `org.apache`-originating entries with a constant one.
+        // Without this, `INSTANCE` might yield different origin depending on the first class accessing to it.
+        // We remove this ambiguity and fix our origin to a constant instead.
+        if (className.startsWith("org.apache")) {
+            return Stream.of(ORG_APACHE_REPLACEMENT_STACK_TRACE_ELEMENT);
+        }
+
+        // Otherwise, it looks good
         return Stream.of(stackTraceElement);
     }
 

log4j-core-test/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java

@@ -16,102 +16,111 @@
  */
 package org.apache.logging.log4j.core;
 
-import static org.hamcrest.MatcherAssert.assertThat;
-import static org.hamcrest.Matchers.containsString;
-import static org.hamcrest.Matchers.is;
-import static org.junit.jupiter.api.Assertions.assertNull;
-import static org.junit.jupiter.api.Assertions.assertTrue;
-
-import java.io.BufferedReader;
-import java.io.File;
-import java.io.FileReader;
-import java.util.concurrent.CountDownLatch;
-import java.util.concurrent.TimeUnit;
-import org.apache.logging.log4j.LogManager;
+import static org.apache.logging.log4j.core.GcHelper.awaitGarbageCollection;
+import static org.assertj.core.api.Assertions.assertThat;
+
+import java.util.List;
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.config.ConfigurationFactory;
-import org.apache.logging.log4j.core.test.CoreLoggerContexts;
-import org.junit.jupiter.api.BeforeAll;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.builder.api.AppenderComponentBuilder;
+import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilder;
+import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilderFactory;
+import org.apache.logging.log4j.core.config.builder.api.LayoutComponentBuilder;
+import org.apache.logging.log4j.core.config.builder.api.RootLoggerComponentBuilder;
+import org.apache.logging.log4j.core.config.builder.impl.BuiltConfiguration;
+import org.apache.logging.log4j.core.test.appender.ListAppender;
 import org.junit.jupiter.api.Tag;
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.TestInfo;
+import org.junitpioneer.jupiter.SetSystemProperty;
 
 @Tag("functional")
-public class EventParameterMemoryLeakTest {
+class EventParameterMemoryLeakTest {
+
+    @Test
+    @SetSystemProperty(key = "log4j2.enableDirectEncoders", value = "true")
+    @SetSystemProperty(key = "log4j2.enableThreadLocals", value = "true")
+    void parameters_should_be_garbage_collected(final TestInfo testInfo) throws Throwable {
+        awaitGarbageCollection(() -> {
+            final ListAppender[] appenderRef = {null};
+            final Logger[] loggerRef = {null};
+            try (final LoggerContext ignored = createLoggerContext(testInfo, appenderRef, loggerRef)) {
+
+                // Log messages
+                final ParameterObject parameter = new ParameterObject("paramValue");
+                loggerRef[0].info("Message with parameter {}", parameter);
+                loggerRef[0].info(parameter);
+                loggerRef[0].info("test", new ObjectThrowable(parameter));
+                loggerRef[0].info("test {}", "hello", new ObjectThrowable(parameter));
 
-    @BeforeAll
-    public static void beforeClass() {
-        System.setProperty("log4j2.enableThreadlocals", "true");
-        System.setProperty("log4j2.enableDirectEncoders", "true");
-        System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, "EventParameterMemoryLeakTest.xml");
+                // Verify the logging
+                final List<String> messages = appenderRef[0].getMessages();
+                assertThat(messages).hasSize(4);
+                assertThat(messages.get(0)).isEqualTo("Message with parameter %s", parameter.value);
+                assertThat(messages.get(1)).isEqualTo(parameter.value);
+                assertThat(messages.get(2))
+                        .startsWith(String.format("test%n%s: %s", ObjectThrowable.class.getName(), parameter.value));
+                assertThat(messages.get(3))
+                        .startsWith(
+                                String.format("test hello%n%s: %s", ObjectThrowable.class.getName(), parameter.value));
+
+                // Return the GC subject
+                return parameter;
+            }
+        });
     }
 
-    @Test
-    @SuppressWarnings("UnusedAssignment") // parameter set to null to allow garbage collection
-    public void testParametersAreNotLeaked() throws Exception {
-        final File file = new File("target", "EventParameterMemoryLeakTest.log");
-        assertTrue(!file.exists() || file.delete(), "Deleted old file before test");
-
-        final Logger log = LogManager.getLogger("com.foo.Bar");
-        final CountDownLatch latch = new CountDownLatch(1);
-        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();
-        // line4 is empty line because of the line separator after throwable pattern
-        final String line4 = reader.readLine();
-        final String line5 = reader.readLine();
-        final String line6 = reader.readLine();
-        final String line7 = reader.readLine();
-        reader.close();
-        file.delete();
-        assertThat(line1, containsString("Message with parameter paramValue"));
-        assertThat(line2, containsString("paramValue"));
-        assertThat(line3, containsString("paramValue"));
-        assertThat(line4, is(""));
-        assertThat(line5, containsString("paramValue"));
-        assertThat(line6, is(""));
-        assertNull(line7, "Expected only six lines");
-        final GarbageCollectionHelper gcHelper = new GarbageCollectionHelper();
-        gcHelper.run();
-        try {
-            assertTrue(latch.await(30, TimeUnit.SECONDS), "Parameter should have been garbage collected");
-        } finally {
-            gcHelper.close();
-        }
+    private static LoggerContext createLoggerContext(
+            final TestInfo testInfo, final ListAppender[] appenderRef, final Logger[] loggerRef) {
+        final String loggerContextName = String.format("%s-LC", testInfo.getDisplayName());
+        final LoggerContext loggerContext = new LoggerContext(loggerContextName);
+        final String appenderName = "LIST";
+        final Configuration configuration = createConfiguration(appenderName);
+        loggerContext.start(configuration);
+        appenderRef[0] = configuration.getAppender(appenderName);
+        assertThat(appenderRef[0]).isNotNull();
+        final Class<?> testClass = testInfo.getTestClass().orElse(null);
+        assertThat(testClass).isNotNull();
+        loggerRef[0] = loggerContext.getLogger(testClass);
+        return loggerContext;
+    }
+
+    @SuppressWarnings("SameParameterValue")
+    private static Configuration createConfiguration(final String appenderName) {
+        final ConfigurationBuilder<BuiltConfiguration> configBuilder =
+                ConfigurationBuilderFactory.newConfigurationBuilder();
+        final LayoutComponentBuilder layoutComponentBuilder =
+                configBuilder.newLayout("PatternLayout").addAttribute("pattern", "%m");
+        final AppenderComponentBuilder appenderComponentBuilder =
+                configBuilder.newAppender(appenderName, "List").add(layoutComponentBuilder);
+        final RootLoggerComponentBuilder loggerComponentBuilder =
+                configBuilder.newRootLogger(Level.ALL).add(configBuilder.newAppenderRef(appenderName));
+        return configBuilder
+                .add(appenderComponentBuilder)
+                .add(loggerComponentBuilder)
+                .build(false);
     }
 
     private static final class ParameterObject {
+
         private final String value;
-        private final CountDownLatch latch;
 
-        ParameterObject(final String value, final CountDownLatch latch) {
+        private ParameterObject(final String value) {
             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 ObjectThrowable extends RuntimeException {
+
         private final Object object;
 
-        ObjectThrowable(final Object object) {
+        private ObjectThrowable(final Object object) {
             super(String.valueOf(object));
             this.object = object;
         }

log4j-core-test/src/test/java/org/apache/logging/log4j/core/GarbageCollectionHelper.java

@@ -0,0 +1,54 @@
+/*
+ * 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 java.lang.ref.PhantomReference;
+import java.lang.ref.Reference;
+import java.lang.ref.ReferenceQueue;
+import org.junit.jupiter.api.function.ThrowingSupplier;
+
+public final class GcHelper {
+
+    private GcHelper() {}
+
+    /**
+     * Waits for the value to be garbage collected.
+     *
+     * @param valueSupplier a value provider
+     */
+    @SuppressWarnings({"unused", "UnusedAssignment"})
+    public static void awaitGarbageCollection(final ThrowingSupplier<?> valueSupplier) throws InterruptedException {
+
+        // Create the reference queue
+        final ReferenceQueue<Object> refQueue = new ReferenceQueue<>();
+        final Reference<?> ref;
+        try {
+            final Object value = valueSupplier.get();
+            ref = new PhantomReference<>(value, refQueue);
+        } catch (final Throwable error) {
+            throw new RuntimeException("failed obtaining value", error);
+        }
+
+        // Wait for the garbage collection
+        try (final GcPressureGenerator ignored = GcPressureGenerator.ofStarted()) {
+            final Reference<?> removedRef = refQueue.remove(30_000L);
+            if (removedRef == null) {
+                throw new AssertionError("garbage collector did not reclaim the value");
+            }
+        }
+    }
+}