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

- 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})

- Ports #3045

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

Author: 3 people

log4j-async-logger/src/test/java/org/apache/logging/log4j/async/logger/AsyncLoggerTestArgumentFreedOnErrorTest.java

@@ -16,63 +16,55 @@
  */
 package org.apache.logging.log4j.async.logger;
 
-import static org.junit.jupiter.api.Assertions.assertTrue;
+import static org.apache.logging.log4j.core.test.internal.GcHelper.awaitGarbageCollection;
 
-import java.util.concurrent.CountDownLatch;
-import java.util.concurrent.TimeUnit;
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.core.GarbageCollectionHelper;
+import org.apache.logging.log4j.core.Logger;
+import org.apache.logging.log4j.core.LoggerContext;
 import org.apache.logging.log4j.core.test.TestConstants;
-import org.apache.logging.log4j.core.test.junit.ContextSelectorType;
 import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.plugins.di.DI;
 import org.apache.logging.log4j.test.junit.SetTestProperty;
+import org.apache.logging.log4j.test.junit.UsingStatusListener;
 import org.apache.logging.log4j.util.StringBuilderFormattable;
 import org.junit.jupiter.api.Tag;
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.TestInfo;
 
 @Tag("async")
-@SetTestProperty(key = TestConstants.GC_ENABLE_DIRECT_ENCODERS, value = "true")
-@SetTestProperty(key = TestConstants.ASYNC_FORMAT_MESSAGES_IN_BACKGROUND, value = "true")
-@ContextSelectorType(AsyncLoggerContextSelector.class)
-public class AsyncLoggerTestArgumentFreedOnErrorTest {
+class AsyncLoggerArgumentFreedOnErrorTest {
 
-    // LOG4J2-2725: events are cleared even after failure
+    /**
+     * Tests events are cleared even after failure.
+     *
+     * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-2725">LOG4J2-2725</a>
+     */
     @Test
-    public void testMessageIsGarbageCollected() throws Exception {
-        final AsyncLogger log = (AsyncLogger) LogManager.getLogger("com.foo.Bar");
-        final CountDownLatch garbageCollectionLatch = new CountDownLatch(1);
-        log.fatal(new ThrowingMessage(garbageCollectionLatch));
-        try (final GarbageCollectionHelper gcHelper = new GarbageCollectionHelper()) {
-            gcHelper.run();
-            assertTrue(
-                    garbageCollectionLatch.await(30, TimeUnit.SECONDS), "Parameter should have been garbage collected");
-        }
+    @UsingStatusListener // Suppresses `StatusLogger` output, unless there is a failure
+    @SetTestProperty(key = TestConstants.GC_ENABLE_DIRECT_ENCODERS, value = "true")
+    @SetTestProperty(key = TestConstants.ASYNC_FORMAT_MESSAGES_IN_BACKGROUND, value = "true")
+    void parameters_throwing_exception_should_be_garbage_collected(final TestInfo testInfo) throws Exception {
+        awaitGarbageCollection(() -> {
+            final String loggerContextName = String.format("%s-LC", testInfo.getDisplayName());
+            try (final LoggerContext loggerContext =
+                    new AsyncLoggerContext(loggerContextName, null, null, DI.createInitializedFactory())) {
+                loggerContext.start();
+                final Logger logger = loggerContext.getRootLogger();
+                final ThrowingMessage parameter = new ThrowingMessage();
+                logger.fatal(parameter);
+                return parameter;
+            }
+        });
     }
 
     private static class ThrowingMessage implements Message, StringBuilderFormattable {
 
-        private final CountDownLatch latch;
-
-        ThrowingMessage(final CountDownLatch latch) {
-            this.latch = latch;
-        }
-
-        @Override
-        protected void finalize() throws Throwable {
-            latch.countDown();
-            super.finalize();
-        }
+        private ThrowingMessage() {}
 
         @Override
         public String getFormattedMessage() {
             throw new Error("Expected");
         }
 
-        @Override
-        public String getFormat() {
-            return "";
-        }
-
         @Override
         public Object[] getParameters() {
             return new Object[0];

log4j-async-logger/src/test/java/org/apache/logging/log4j/async/logger/QueueFullAsyncLogger3Test.java

@@ -16,29 +16,32 @@
  */
 package org.apache.logging.log4j.async.logger;
 
-import static java.util.concurrent.TimeUnit.SECONDS;
+import static org.apache.logging.log4j.async.logger.QueueFullAsyncAbstractTest.assertAsyncLogger;
 import static org.apache.logging.log4j.core.test.TestConstants.ASYNC_FORMAT_MESSAGES_IN_BACKGROUND;
 import static org.apache.logging.log4j.core.test.TestConstants.ASYNC_LOGGER_RING_BUFFER_SIZE;
 import static org.apache.logging.log4j.core.test.TestConstants.ASYNC_QUEUE_FULL_POLICY_CLASS_NAME;
+import static org.apache.logging.log4j.core.test.internal.GcHelper.awaitGarbageCollection;
 import static org.assertj.core.api.Assertions.assertThat;
-import static org.junit.Assert.assertTrue;
 
+import java.util.List;
 import java.util.concurrent.CountDownLatch;
+import java.util.stream.Collectors;
+import java.util.stream.IntStream;
 import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.GarbageCollectionHelper;
 import org.apache.logging.log4j.core.LoggerContext;
 import org.apache.logging.log4j.core.async.AsyncQueueFullPolicyFactory;
 import org.apache.logging.log4j.core.async.DiscardingAsyncQueueFullPolicy;
 import org.apache.logging.log4j.core.impl.CoreProperties;
 import org.apache.logging.log4j.core.test.async.BlockingAppender;
+import org.apache.logging.log4j.core.test.async.QueueFullAbstractTest;
 import org.apache.logging.log4j.core.test.junit.ContextSelectorType;
 import org.apache.logging.log4j.core.test.junit.LoggerContextSource;
 import org.apache.logging.log4j.core.test.junit.Named;
 import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.message.SimpleMessage;
 import org.apache.logging.log4j.status.StatusLogger;
 import org.apache.logging.log4j.test.junit.SetTestProperty;
 import org.junit.jupiter.api.Test;
-import org.junit.jupiter.api.Timeout;
 
 /**
  * Tests queue full scenarios with pure AsyncLoggers (all loggers async).
@@ -47,7 +50,7 @@
 @SetTestProperty(key = ASYNC_LOGGER_RING_BUFFER_SIZE, value = "128")
 @SetTestProperty(key = ASYNC_FORMAT_MESSAGES_IN_BACKGROUND, value = "true")
 @SetTestProperty(key = ASYNC_QUEUE_FULL_POLICY_CLASS_NAME, value = "Discard")
-public class QueueFullAsyncLogger3Test extends QueueFullAsyncAbstractTest {
+class QueueFullAsyncLogger3Test extends QueueFullAbstractTest {
 
     @Override
     protected void checkConfig(final LoggerContext ctx) {
@@ -60,64 +63,21 @@ protected void checkConfig(final LoggerContext ctx) {
     }
 
     @Test
-    @Timeout(value = 15, unit = SECONDS)
     @LoggerContextSource
-    public void discardedMessagesShouldBeGarbageCollected(
+    void discarded_messages_should_be_garbage_collected(
             final LoggerContext ctx, final @Named(APPENDER_NAME) BlockingAppender blockingAppender)
             throws InterruptedException {
-        checkConfig(ctx);
-        final Logger logger = ctx.getLogger(getClass());
-
-        blockingAppender.logEvents = null;
-        blockingAppender.countDownLatch = new CountDownLatch(1);
-        final int count = 200;
-        final CountDownLatch garbageCollectionLatch = new CountDownLatch(count);
-        for (int i = 0; i < count; i++) {
-            logger.info(new CountdownOnGarbageCollectMessage(garbageCollectionLatch));
-        }
-        blockingAppender.countDownLatch.countDown();
-
-        final GarbageCollectionHelper gcHelper = new GarbageCollectionHelper();
-        gcHelper.run();
-        try {
-            assertTrue("Parameter should have been garbage collected", garbageCollectionLatch.await(30, SECONDS));
-        } finally {
-            gcHelper.close();
-        }
-    }
-
-    private static final class CountdownOnGarbageCollectMessage implements Message {
-
-        private final CountDownLatch latch;
-
-        CountdownOnGarbageCollectMessage(final CountDownLatch latch) {
-            this.latch = latch;
-        }
-
-        @Override
-        public String getFormattedMessage() {
-            return "formatted";
-        }
-
-        @Override
-        public String getFormat() {
-            return null;
-        }
-
-        @Override
-        public Object[] getParameters() {
-            return org.apache.logging.log4j.util.Constants.EMPTY_OBJECT_ARRAY;
-        }
-
-        @Override
-        public Throwable getThrowable() {
-            return null;
-        }
-
-        @Override
-        protected void finalize() throws Throwable {
-            latch.countDown();
-            super.finalize();
-        }
+        awaitGarbageCollection(() -> {
+            checkConfig(ctx);
+            final Logger logger = ctx.getLogger(getClass());
+            blockingAppender.logEvents = null;
+            blockingAppender.countDownLatch = new CountDownLatch(1);
+            final List<Message> messages = IntStream.range(0, 200)
+                    .mapToObj(messageIndex -> new SimpleMessage("message " + messageIndex))
+                    .collect(Collectors.toList());
+            messages.forEach(logger::info);
+            blockingAppender.countDownLatch.countDown();
+            return messages;
+        });
     }
 }

log4j-core-test/src/main/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.test.internal;
+
+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");
+            }
+        }
+    }
+}