From 8bd9590a5bc92d4806bc90a8c074640e25c2a5f4 Mon Sep 17 00:00:00 2001 From: Moritz Mack Date: Tue, 14 Oct 2025 11:25:47 +0200 Subject: [PATCH 1/6] New test case demonstrating ArrayIndexOutOfBoundsException if concurrently modifying the stacktrace --- .../ThrowablePatternConverterTest.java | 44 ++++++++++++++++++- 1 file changed, 43 insertions(+), 1 deletion(-) 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 c893947423c..eee71383e1a 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 @@ -29,6 +29,7 @@ import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.locks.LockSupport; import java.util.stream.Collectors; @@ -443,10 +444,51 @@ private static String normalizeStackTrace(final String stackTrace, final String .replaceAll(" ~\\[\\?:[^]]+](\\Q" + conversionEnding + "\\E|$)", " ~[?:0]$1"); } + @Test + @Issue("https://github.com/apache/logging-log4j2/issues/3940") + void concurrent_stacktrace_mutation_should_not_cause_failure() throws Exception { + final ExecutorService executor = Executors.newFixedThreadPool(2); + + // Create the formatter + final List patternFormatters = PATTERN_PARSER.parse(patternPrefix, false, true, true); + assertThat(patternFormatters).hasSize(1); + final PatternFormatter patternFormatter = patternFormatters.get(0); + final StringBuilder buffer = new StringBuilder(); + + try { + for (int i = 0; i < 10; i++) { + final CountDownLatch latch = new CountDownLatch(2); + final Throwable exception = new RuntimeException(); + final LogEvent logEvent = Log4jLogEvent.newBuilder() + .setThrown(exception) + .setLevel(LEVEL) + .build(); + + executor.submit(() -> { + try { + patternFormatter.format(logEvent, buffer); + buffer.setLength(0); + latch.countDown(); + } catch (Throwable e) { + e.printStackTrace(); + } + }); + executor.submit(() -> { + exception.setStackTrace(new StackTraceElement[0]); + latch.countDown(); + }); + if (latch.await(1, TimeUnit.SECONDS) == false) { + throw new IllegalStateException("timed out waiting for tasks to complete"); + } + } + } finally { + executor.shutdownNow(); + } + } + @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); From c7ef339dcfa95fc4368f1e831163732629b6e5b3 Mon Sep 17 00:00:00 2001 From: Moritz Mack Date: Tue, 14 Oct 2025 11:27:05 +0200 Subject: [PATCH 2/6] Fix ArrayIndexOutOfBoundsException if concurrently modifying the stacktrace of a throwablen while rendering it --- .../RootThrowablePatternConverterTest.java | 3 ++- .../ThrowableExtendedStackTraceRenderer.java | 2 +- .../ThrowableInvertedStackTraceRenderer.java | 2 +- .../pattern/ThrowableStackTraceRenderer.java | 19 ++++++++++++++----- 4 files changed, 18 insertions(+), 8 deletions(-) diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java index 80e4f008bf5..344fc315086 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java @@ -17,7 +17,6 @@ package org.apache.logging.log4j.core.pattern; import static java.util.Arrays.asList; -import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.EXCEPTION; import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.LEVEL; import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.convert; import static org.assertj.core.api.Assertions.assertThat; @@ -38,6 +37,8 @@ */ class RootThrowablePatternConverterTest { + static final Throwable EXCEPTION = TestFriendlyException.INSTANCE; + private static final StackTraceElement THROWING_METHOD = Throwables.getRootCause(EXCEPTION).getStackTrace()[0]; diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java index 06dbd4904ab..c70e57d4d46 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java @@ -132,7 +132,7 @@ private static Map createClassResourceInfoByName( Class executionStackTraceElementClass = executionStackTrace.isEmpty() ? null : executionStackTrace.peekLast(); ClassLoader lastLoader = null; - final StackTraceElement[] stackTraceElements = throwable.getStackTrace(); + final StackTraceElement[] stackTraceElements = metadata.stackTrace; for (int throwableStackIndex = metadata.stackLength - 1; throwableStackIndex >= 0; --throwableStackIndex) { 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 f1d26797fa4..ca8a28ea1cb 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 @@ -74,7 +74,7 @@ private void renderThrowable( } renderThrowableMessage(buffer, throwable); buffer.append(lineSeparator); - renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator); + renderStackTraceElements(buffer, 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 301f6efccec..5769ce5b65e 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 @@ -98,7 +98,7 @@ private void renderThrowable( final Context.Metadata metadata = context.metadataByThrowable.get(throwable); renderThrowableMessage(buffer, throwable); buffer.append(lineSeparator); - renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator); + renderStackTraceElements(buffer, context, metadata, prefix, lineSeparator); renderSuppressed(buffer, metadata.suppressed, context, visitedThrowables, prefix + '\t', lineSeparator); renderCause(buffer, throwable.getCause(), context, visitedThrowables, prefix, lineSeparator); } @@ -148,13 +148,12 @@ static void renderThrowableMessage(final StringBuilder buffer, final Throwable t 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 StackTraceElement[] stackTraceElements = throwable.getStackTrace(); + final StackTraceElement[] stackTraceElements = metadata.stackTrace; for (int i = 0; i < metadata.stackLength; i++) { renderStackTraceElement(buffer, stackTraceElements[i], context, prefix, lineSeparator); } @@ -268,6 +267,11 @@ static final class Metadata { */ final int stackLength; + /** + * The stack trace of this {@link Throwable} + */ + final StackTraceElement[] stackTrace; + /** * The suppressed exceptions attached to this {@link Throwable}. * This needs to be captured separately since {@link Throwable#getSuppressed()} can change. @@ -277,9 +281,14 @@ static final class Metadata { */ final Throwable[] suppressed; - private Metadata(final int commonElementCount, final int stackLength, final Throwable[] suppressed) { + private Metadata( + final int commonElementCount, + final int stackLength, + final StackTraceElement[] stackTrace, + final Throwable[] suppressed) { this.commonElementCount = commonElementCount; this.stackLength = stackLength; + this.stackTrace = stackTrace; this.suppressed = suppressed; } @@ -339,7 +348,7 @@ private static Metadata populateMetadata( commonElementCount = 0; stackLength = currentTrace.length; } - return new Metadata(commonElementCount, stackLength, suppressed); + return new Metadata(commonElementCount, stackLength, currentTrace, suppressed); } } } From 986c447dd4ed79a20061ca42995391ca1cd2ae2f Mon Sep 17 00:00:00 2001 From: Moritz Mack Date: Tue, 14 Oct 2025 11:34:33 +0200 Subject: [PATCH 3/6] Add changelog entry --- ...kTraceRenderer_ArrayIndexOutOfBoundsException.xml | 12 ++++++++++++ 1 file changed, 12 insertions(+) create mode 100644 src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml diff --git a/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml b/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml new file mode 100644 index 00000000000..8d2a15f5b1a --- /dev/null +++ b/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml @@ -0,0 +1,12 @@ + + + + + Fixes `ArrayIndexOutOfBoundsException` thrown by `ThrowableStackTraceRenderer` when a `Throwable`'s stacktrace is mutated concurrently. + + From f623aa6bb280645d05b3283abf92d65c8259b98c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 17 Oct 2025 14:07:18 +0200 Subject: [PATCH 4/6] Improve changelog --- ...ableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml b/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml index 8d2a15f5b1a..4bd5ca2c281 100644 --- a/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml +++ b/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml @@ -5,8 +5,9 @@ https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="fixed"> - + + - Fixes `ArrayIndexOutOfBoundsException` thrown by `ThrowableStackTraceRenderer` when a `Throwable`'s stacktrace is mutated concurrently. + Fixes `ArrayIndexOutOfBoundsException` thrown by `ThrowableStackTraceRenderer` when the stack trace is mutated concurrently. From f53eac2d268224cd6598593b22dc0fc0099542e7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 17 Oct 2025 14:07:30 +0200 Subject: [PATCH 5/6] Improve comments --- .../log4j/core/pattern/ThrowableStackTraceRenderer.java | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) 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 5769ce5b65e..885d7de36e8 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 @@ -268,7 +268,11 @@ static final class Metadata { final int stackLength; /** - * The stack trace of this {@link Throwable} + * The stack trace of this {@link Throwable}. + * This needs to be captured separately since {@link Throwable#getStackTrace()} can change. + * + * @see #3940 + * @see #3955 */ final StackTraceElement[] stackTrace; From f208e1bd95eed87da2d01ad9c1540d60916c4a28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 17 Oct 2025 15:00:43 +0200 Subject: [PATCH 6/6] Improve tests --- .../RootThrowablePatternConverterTest.java | 3 +- .../ThrowablePatternConverterTest.java | 170 +++++++++--------- 2 files changed, 85 insertions(+), 88 deletions(-) diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java index 344fc315086..80e4f008bf5 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/RootThrowablePatternConverterTest.java @@ -17,6 +17,7 @@ package org.apache.logging.log4j.core.pattern; import static java.util.Arrays.asList; +import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.EXCEPTION; import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.LEVEL; import static org.apache.logging.log4j.core.pattern.ThrowablePatternConverterTest.convert; import static org.assertj.core.api.Assertions.assertThat; @@ -37,8 +38,6 @@ */ class RootThrowablePatternConverterTest { - static final Throwable EXCEPTION = TestFriendlyException.INSTANCE; - private static final StackTraceElement THROWING_METHOD = Throwables.getRootCause(EXCEPTION).getStackTrace()[0]; 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 eee71383e1a..ea9294e58a4 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 @@ -25,13 +25,15 @@ import java.io.PrintStream; import java.nio.charset.Charset; import java.nio.charset.StandardCharsets; +import java.util.Arrays; import java.util.List; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; -import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.locks.LockSupport; +import java.util.function.Consumer; +import java.util.function.Function; import java.util.stream.Collectors; import java.util.stream.IntStream; import java.util.stream.Stream; @@ -444,105 +446,101 @@ private static String normalizeStackTrace(final String stackTrace, final String .replaceAll(" ~\\[\\?:[^]]+](\\Q" + conversionEnding + "\\E|$)", " ~[?:0]$1"); } - @Test + @RepeatedTest(10) @Issue("https://github.com/apache/logging-log4j2/issues/3940") - void concurrent_stacktrace_mutation_should_not_cause_failure() throws Exception { - final ExecutorService executor = Executors.newFixedThreadPool(2); + void concurrent_stack_trace_mutation_should_not_cause_failure() throws Exception { + final int stackTracePerThreadCount = 100; + formatThrowableWhileMutatingConcurrently(threadIndex -> { + final List stackTraces = createExceptionsOfDifferentDepths().stream() + .map(Throwable::getStackTrace) + .collect(Collectors.toList()); + return exception -> { + for (int stackTraceIndex = 0; stackTraceIndex < stackTracePerThreadCount; stackTraceIndex++) { + exception.setStackTrace(stackTraces.get(stackTraceIndex)); + // Give some time slack to increase randomness + LockSupport.parkNanos(1); + } + }; + }); + } - // Create the formatter - final List patternFormatters = PATTERN_PARSER.parse(patternPrefix, false, true, true); - assertThat(patternFormatters).hasSize(1); - final PatternFormatter patternFormatter = patternFormatters.get(0); - final StringBuilder buffer = new StringBuilder(); + @RepeatedTest(10) + @Issue("https://github.com/apache/logging-log4j2/issues/3929") + void concurrent_suppressed_mutation_should_not_cause_failure() throws Exception { + formatThrowableWhileMutatingConcurrently(threadIndex -> { + final List exceptions = createExceptionsOfDifferentDepths(); + return exception -> exceptions.forEach(suppressed -> { + exception.addSuppressed(suppressed); + // Give some time slack to increase randomness + LockSupport.parkNanos(1); + }); + }); + } - try { - for (int i = 0; i < 10; i++) { - final CountDownLatch latch = new CountDownLatch(2); - final Throwable exception = new RuntimeException(); - final LogEvent logEvent = Log4jLogEvent.newBuilder() - .setThrown(exception) - .setLevel(LEVEL) - .build(); + private void formatThrowableWhileMutatingConcurrently( + Function> throwableMutatorFactory) throws Exception { + // Test constants + final int threadCount = Math.max(8, Runtime.getRuntime().availableProcessors()); + final ExecutorService executor = Executors.newFixedThreadPool(threadCount); + try { + final Exception exception = new Exception(); + final CountDownLatch startLatch = + new CountDownLatch(threadCount + /* the main thread invoking the rendering: */ 1); + final AtomicInteger runningThreadCountRef = new AtomicInteger(threadCount); + + // Schedule threads that will start mutating the exception with the start signal + for (int threadIndex = 0; threadIndex < threadCount; threadIndex++) { + final Consumer exceptionMutator = throwableMutatorFactory.apply(threadIndex); executor.submit(() -> { try { - patternFormatter.format(logEvent, buffer); - buffer.setLength(0); - latch.countDown(); - } catch (Throwable e) { - e.printStackTrace(); + startLatch.countDown(); + startLatch.await(); + exceptionMutator.accept(exception); + } catch (InterruptedException ignored) { + // Restore the interrupt + Thread.currentThread().interrupt(); + } finally { + runningThreadCountRef.decrementAndGet(); } }); - executor.submit(() -> { - exception.setStackTrace(new StackTraceElement[0]); - latch.countDown(); - }); - if (latch.await(1, TimeUnit.SECONDS) == false) { - throw new IllegalStateException("timed out waiting for tasks to complete"); - } + } + + // 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); } } finally { executor.shutdownNow(); } } - @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); - } + private static List createExceptionsOfDifferentDepths() { + final StackTraceElement[] stackTrace = new Exception().getStackTrace(); + return IntStream.range(0, stackTrace.length) + .mapToObj(depth -> { + final Exception exception = new Exception(); + exception.setStackTrace(Arrays.copyOfRange(stackTrace, 0, depth)); + return exception; + }) + .collect(Collectors.toList()); } }