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 24230dd23b9..c893947423c 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 @@ 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 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 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 6ad7173462b..f1d26797fa4 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 @@ 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); } } 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 b16e9b98362..301f6efccec 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 @@ 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 #3929 + * @see #3934 + */ + 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 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); } } } 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 00000000000..10284802659 --- /dev/null +++ b/src/changelog/2.25.1/3929_ThrowableStackTraceRenderer-npe.xml @@ -0,0 +1,13 @@ + + + + + + Fixes `NullPointerException` thrown by `ThrowableStackTraceRenderer` when suppressed exceptions are mutated concurrently. + +