Fix: prevent ThrowableStackTraceRenderer from throwing NPEs

log4j-core-test/pom.xml

@@ -347,6 +347,12 @@
       <scope>test</scope>
     </dependency>
 
+    <dependency>
+      <groupId>org.mockito</groupId>
+      <artifactId>mockito-inline</artifactId>
+      <scope>test</scope>
+    </dependency>
+
     <dependency>
       <groupId>org.mockito</groupId>
       <artifactId>mockito-junit-jupiter</artifactId>

log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/db/AbstractDatabaseAppenderTest.java

@@ -72,13 +72,11 @@ public void testAppend() {
         final LogEvent event2 = mock(LogEvent.class);
 
         appender.append(event1);
-        then(manager).should().isBuffered();
-        then(manager).should().writeThrough(same(event1), isNull());
+        then(manager).should().write(same(event1), isNull());
         reset(manager);
 
         appender.append(event2);
-        then(manager).should().isBuffered();
-        then(manager).should().writeThrough(same(event2), isNull());
+        then(manager).should().write(same(event2), isNull());
         reset(manager);
     }
 
@@ -108,7 +106,7 @@ public void testReplaceManager() throws Exception {
         final LocalAbstractDatabaseManager newManager = mock(LocalAbstractDatabaseManager.class);
         appender.replaceManager(newManager);
         then(manager).should().close();
-        then(newManager).should().startupInternal();
+        then(newManager).should().startup();
 
         appender.stop();
         then(newManager).should().stop(0L, TimeUnit.MILLISECONDS);
@@ -119,7 +117,7 @@ public void testStartAndStop() throws Exception {
         setUp("name");
 
         appender.start();
-        then(manager).should().startupInternal();
+        then(manager).should().startup();
 
         appender.stop();
         then(manager).should().stop(0L, TimeUnit.MILLISECONDS);

log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/db/AbstractDatabaseManagerTest.java

@@ -86,6 +86,7 @@ void testBuffering01() throws Exception {
         reset(manager);
 
         manager.write(event1, null);
+        then(manager).should().write(same(event1), isNull());
         then(manager).should().writeThrough(same(event1), isNull());
         then(manager).should().connectAndStart();
         then(manager).should().isBuffered();
@@ -95,6 +96,7 @@ void testBuffering01() throws Exception {
         reset(manager);
 
         manager.write(event2, null);
+        then(manager).should().write(same(event2), isNull());
         then(manager).should().writeThrough(same(event2), isNull());
         then(manager).should().connectAndStart();
         then(manager).should().isBuffered();
@@ -104,6 +106,7 @@ void testBuffering01() throws Exception {
         reset(manager);
 
         manager.write(event3, null);
+        then(manager).should().write(same(event3), isNull());
         then(manager).should().writeThrough(same(event3), isNull());
         then(manager).should().connectAndStart();
         then(manager).should().isBuffered();
@@ -133,14 +136,23 @@ void testBuffering02() throws Exception {
         when(event4.toImmutable()).thenReturn(event4copy);
 
         manager.startup();
+        then(manager).should().startup();
+        then(manager).should().isRunning();
         then(manager).should().startupInternal();
 
         manager.write(event1, null);
+        then(manager).should().write(event1, null);
         manager.write(event2, null);
+        then(manager).should().write(event2, null);
         manager.write(event3, null);
+        then(manager).should().write(event3, null);
         manager.write(event4, null);
+        then(manager).should().write(event4, null);
 
         then(manager).should().connectAndStart();
+
+        then(manager).should().flush();
+        verify(manager, times(2)).isRunning();
         verify(manager, times(5)).isBuffered(); // 4 + 1 in flush()
         then(manager).should().writeInternal(same(event1copy), isNull());
         then(manager).should().buffer(event1);
@@ -171,13 +183,20 @@ void testBuffering03() throws Exception {
         when(event3.toImmutable()).thenReturn(event3copy);
 
         manager.startup();
+        then(manager).should().startup();
+        then(manager).should().isRunning();
         then(manager).should().startupInternal();
 
         manager.write(event1, null);
+        then(manager).should().write(same(event1), isNull());
         manager.write(event2, null);
+        then(manager).should().write(same(event2), isNull());
         manager.write(event3, null);
-        manager.flush();
+        then(manager).should().write(same(event3), isNull());
 
+        manager.flush();
+        then(manager).should().flush();
+        verify(manager, times(2)).isRunning();
         then(manager).should().connectAndStart();
         verify(manager, times(4)).isBuffered();
         then(manager).should().writeInternal(same(event1copy), isNull());
@@ -207,14 +226,22 @@ void testBuffering04() throws Exception {
         when(event3.toImmutable()).thenReturn(event3copy);
 
         manager.startup();
+        then(manager).should().startup();
+        then(manager).should().isRunning();
         then(manager).should().startupInternal();
 
         manager.write(event1, null);
+        then(manager).should().write(same(event1), isNull());
         manager.write(event2, null);
+        then(manager).should().write(same(event2), isNull());
         manager.write(event3, null);
+        then(manager).should().write(same(event3), isNull());
         manager.shutdown();
+        then(manager).should().shutdown();
+        then(manager).should().flush();
 
         then(manager).should().connectAndStart();
+        verify(manager, times(3)).isRunning();
         verify(manager, times(4)).isBuffered();
         then(manager).should().writeInternal(same(event1copy), isNull());
         then(manager).should().buffer(event1);

log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RandomRollingAppenderOnStartupTest.java

@@ -86,10 +86,7 @@ public static void afterClass() throws Exception {
                     size = Files.size(path);
                 } else {
                     final long fileSize = Files.size(path);
-                    assertEquals(
-                            "Expected size: " + size + " Size of " + path.getFileName() + ": " + fileSize,
-                            size,
-                            fileSize);
+                    assertEquals("Expected size: " + size + " Size of " + path + ": " + fileSize, size, fileSize);
                 }
                 Files.delete(path);
             }

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

@@ -26,14 +26,20 @@
 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.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 +441,63 @@ 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;
+
+            // 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();
+                    }
+                });
+            }
+
+            // 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();
+            for (int i = 0; i < 1_000_000; i++) {
+                // 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-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRendererTest.java

@@ -0,0 +1,44 @@
+/*
+ * 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.pattern;
+
+import static org.mockito.Mockito.doReturn;
+import static org.mockito.Mockito.spy;
+
+import java.util.Collections;
+import org.junit.jupiter.api.Test;
+
+class ThrowableStackTraceRendererTest {
+
+    @Test
+    void handlesConcurrentlyMutatedSuppressions() {
+        final Throwable suppressed1 = new Throwable("suppressed1");
+        final Throwable suppressed2 = new Throwable("suppressed2");
+        final Throwable throwable = spy(new Throwable("throwable"));
+        final ThrowableRenderer renderer =
+                new ThrowableStackTraceRenderer<>(Collections.emptyList(), Integer.MAX_VALUE);
+        // returning suppressed exception arrays of different lengths on each invocation to getSuppressed() emulates
+        // the behavior experienced by ThrowableStackTraceRenderer when rendering a Throwable whose suppressed
+        // exceptions are being concurrently mutated by another thread.
+        doReturn(new Throwable[] {suppressed1})
+                .doReturn(new Throwable[] {suppressed1, suppressed2})
+                .when(throwable)
+                .getSuppressed();
+        // should not throw NPE
+        renderer.renderThrowable(new StringBuilder(), throwable, "\n");
+    }
+}

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>