Fix NPE in ThrowableStackTraceRenderer due to concurrent mutation of suppressed exceptions (#3934)

Co-authored-by: Volkan Yazıcı <volkan@yazi.ci>

Author: joepembe

log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverterTest.java

@@ -26,14 +26,21 @@
 import java.nio.charset.Charset;
 import java.nio.charset.StandardCharsets;
 import java.util.List;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.locks.LockSupport;
 import java.util.stream.Collectors;
+import java.util.stream.IntStream;
 import java.util.stream.Stream;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent;
 import org.apache.logging.log4j.core.layout.PatternLayout;
 import org.jspecify.annotations.Nullable;
 import org.junit.jupiter.api.Nested;
+import org.junit.jupiter.api.RepeatedTest;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.MethodSource;
@@ -435,6 +442,66 @@ private static String normalizeStackTrace(final String stackTrace, final String
                     // We replace the `~[?:1.8.0_422]` suffix of such classes with `~[?:0]`.
                     .replaceAll(" ~\\[\\?:[^]]+](\\Q" + conversionEnding + "\\E|$)", " ~[?:0]$1");
         }
+
+        @RepeatedTest(10)
+        @Issue("https://github.com/apache/logging-log4j2/issues/3929")
+        void concurrent_suppressed_mutation_should_not_cause_failure() throws Exception {
+
+            // Test constants
+            final int threadCount = Math.max(8, Runtime.getRuntime().availableProcessors());
+            final ExecutorService executor = Executors.newFixedThreadPool(threadCount);
+            final Exception exception = new Exception();
+            final CountDownLatch startLatch =
+                    new CountDownLatch(threadCount + /* the main thread invoking the rendering: */ 1);
+            final int exceptionPerThreadCount = 100;
+            final AtomicInteger runningThreadCountRef = new AtomicInteger(threadCount);
+
+            // Schedule threads that will start adding suppressed exceptions with the start signal
+            for (int threadIndex = 0; threadIndex < threadCount; threadIndex++) {
+                final int threadIndex_ = threadIndex;
+                executor.submit(() -> {
+                    try {
+                        List<Exception> exceptions = IntStream.range(0, exceptionPerThreadCount)
+                                .mapToObj(exceptionIndex -> new Exception(threadIndex_ + "-" + exceptionIndex))
+                                .collect(Collectors.toList());
+                        startLatch.countDown();
+                        startLatch.await();
+                        for (int exceptionIndex = 0; exceptionIndex < exceptionPerThreadCount; exceptionIndex++) {
+                            exception.addSuppressed(exceptions.get(exceptionIndex));
+                            // Give some time slack to increase randomness
+                            LockSupport.parkNanos(1);
+                        }
+                    } catch (InterruptedException ignored) {
+                        // Restore the interrupt
+                        Thread.currentThread().interrupt();
+                    } finally {
+                        runningThreadCountRef.decrementAndGet();
+                    }
+                });
+            }
+
+            // Create the formatter
+            final List<PatternFormatter> patternFormatters = PATTERN_PARSER.parse(patternPrefix, false, true, true);
+            assertThat(patternFormatters).hasSize(1);
+            final PatternFormatter patternFormatter = patternFormatters.get(0);
+
+            // Create the log event and the layout buffer
+            final LogEvent logEvent = Log4jLogEvent.newBuilder()
+                    .setThrown(exception)
+                    .setLevel(LEVEL)
+                    .build();
+            final StringBuilder buffer = new StringBuilder(16384);
+
+            // Trigger the start latch and format the exception
+            startLatch.countDown();
+            startLatch.await();
+            while (runningThreadCountRef.get() > 0) {
+                // Give some time slack to increase randomness
+                LockSupport.parkNanos(1);
+                patternFormatter.format(logEvent, buffer);
+                buffer.setLength(0);
+            }
+        }
     }
 
     static String convert(final String pattern) {

log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java

@@ -60,6 +60,7 @@ private void renderThrowable(
             buffer.append(']');
             buffer.append(lineSeparator);
         } else {
+            final Context.Metadata metadata = context.metadataByThrowable.get(throwable);
             lineCapacityAcquired = renderCause(
                     buffer,
                     throwable.getCause(),
@@ -73,9 +74,8 @@ private void renderThrowable(
             }
             renderThrowableMessage(buffer, throwable);
             buffer.append(lineSeparator);
-            renderStackTraceElements(buffer, throwable, context, prefix, lineSeparator);
-            renderSuppressed(
-                    buffer, throwable.getSuppressed(), context, visitedThrowables, prefix + '\t', lineSeparator);
+            renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator);
+            renderSuppressed(buffer, metadata.suppressed, context, visitedThrowables, prefix + '\t', lineSeparator);
         }
     }
 

log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java

@@ -95,11 +95,11 @@ private void renderThrowable(
             buffer.append(']');
             buffer.append(lineSeparator);
         } else {
+            final Context.Metadata metadata = context.metadataByThrowable.get(throwable);
             renderThrowableMessage(buffer, throwable);
             buffer.append(lineSeparator);
-            renderStackTraceElements(buffer, throwable, context, prefix, lineSeparator);
-            renderSuppressed(
-                    buffer, throwable.getSuppressed(), context, visitedThrowables, prefix + '\t', lineSeparator);
+            renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator);
+            renderSuppressed(buffer, metadata.suppressed, context, visitedThrowables, prefix + '\t', lineSeparator);
             renderCause(buffer, throwable.getCause(), context, visitedThrowables, prefix, lineSeparator);
         }
     }
@@ -150,10 +150,10 @@ final void renderStackTraceElements(
             final StringBuilder buffer,
             final Throwable throwable,
             final C context,
+            final Context.Metadata metadata,
             final String prefix,
             final String lineSeparator) {
         context.ignoredStackTraceElementCount = 0;
-        final Context.Metadata metadata = context.metadataByThrowable.get(throwable);
         final StackTraceElement[] stackTraceElements = throwable.getStackTrace();
         for (int i = 0; i < metadata.stackLength; i++) {
             renderStackTraceElement(buffer, stackTraceElements[i], context, prefix, lineSeparator);
@@ -268,9 +268,19 @@ static final class Metadata {
              */
             final int stackLength;
 
-            private Metadata(final int commonElementCount, final int stackLength) {
+            /**
+             * The suppressed exceptions attached to this {@link Throwable}.
+             * This needs to be captured separately since {@link Throwable#getSuppressed()} can change.
+             *
+             * @see <a href="https://github.com/apache/logging-log4j2/issues/3929">#3929</a>
+             * @see <a href="https://github.com/apache/logging-log4j2/pull/3934">#3934</a>
+             */
+            final Throwable[] suppressed;
+
+            private Metadata(final int commonElementCount, final int stackLength, final Throwable[] suppressed) {
                 this.commonElementCount = commonElementCount;
                 this.stackLength = stackLength;
+                this.suppressed = suppressed;
             }
 
             static Map<Throwable, Metadata> ofThrowable(final Throwable throwable) {
@@ -288,11 +298,12 @@ private static void populateMetadata(
                 // Populate metadata of the current throwable
                 @Nullable
                 final StackTraceElement[] rootTrace = parentThrowable == null ? null : parentThrowable.getStackTrace();
-                final Metadata metadata = populateMetadata(rootTrace, throwable.getStackTrace());
+                final Metadata metadata =
+                        populateMetadata(rootTrace, throwable.getStackTrace(), throwable.getSuppressed());
                 metadataByThrowable.put(throwable, metadata);
 
                 // Populate metadata of suppressed exceptions
-                for (final Throwable suppressed : throwable.getSuppressed()) {
+                for (final Throwable suppressed : metadata.suppressed) {
                     if (!visitedThrowables.contains(suppressed)) {
                         visitedThrowables.add(suppressed);
                         populateMetadata(metadataByThrowable, visitedThrowables, throwable, suppressed);
@@ -308,7 +319,9 @@ private static void populateMetadata(
             }
 
             private static Metadata populateMetadata(
-                    @Nullable final StackTraceElement[] parentTrace, final StackTraceElement[] currentTrace) {
+                    @Nullable final StackTraceElement[] parentTrace,
+                    final StackTraceElement[] currentTrace,
+                    final Throwable[] suppressed) {
                 int commonElementCount;
                 int stackLength;
                 if (parentTrace != null) {
@@ -326,7 +339,7 @@ private static Metadata populateMetadata(
                     commonElementCount = 0;
                     stackLength = currentTrace.length;
                 }
-                return new Metadata(commonElementCount, stackLength);
+                return new Metadata(commonElementCount, stackLength, suppressed);
             }
         }
     }

src/changelog/2.25.1/3929_ThrowableStackTraceRenderer-npe.xml

@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns="https://logging.apache.org/xml/ns"
+       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xsi:schemaLocation="
+           https://logging.apache.org/xml/ns
+           https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+       type="fixed">
+  <issue id="3929" link="https://github.com/apache/logging-log4j2/issues/3929"/>
+  <issue id="3934" link="https://github.com/apache/logging-log4j2/pull/3934"/>
+  <description format="asciidoc">
+    Fixes `NullPointerException` thrown by `ThrowableStackTraceRenderer` when suppressed exceptions are mutated concurrently.
+  </description>
+</entry>