Fix `NPE` in `ThrowableStackTraceRenderer` due to concurrent mutation of suppressed exceptions (#3934)
Co-authored-by: Volkan Yazıcı <volkan@yazi.ci>
diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverterTest.java
index 24230dd..c893947 100644
--- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverterTest.java
+++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/ThrowablePatternConverterTest.java
@@ -26,7 +26,13 @@
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;
@@ -34,6 +40,7 @@
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 @@
// 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) {
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java
index 6ad7173..f1d2679 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java
@@ -60,6 +60,7 @@
buffer.append(']');
buffer.append(lineSeparator);
} else {
+ final Context.Metadata metadata = context.metadataByThrowable.get(throwable);
lineCapacityAcquired = renderCause(
buffer,
throwable.getCause(),
@@ -73,9 +74,8 @@
}
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);
}
}
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java
index b16e9b9..301f6ef 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java
@@ -95,11 +95,11 @@
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 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 @@
*/
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 @@
// 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 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 @@
commonElementCount = 0;
stackLength = currentTrace.length;
}
- return new Metadata(commonElementCount, stackLength);
+ return new Metadata(commonElementCount, stackLength, suppressed);
}
}
}
diff --git a/src/changelog/2.25.1/3929_ThrowableStackTraceRenderer-npe.xml b/src/changelog/2.25.1/3929_ThrowableStackTraceRenderer-npe.xml
new file mode 100644
index 0000000..1028480
--- /dev/null
+++ b/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>
