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..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,12 +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.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; @@ -443,64 +446,101 @@ private static String normalizeStackTrace(final String stackTrace, final String .replaceAll(" ~\\[\\?:[^]]+](\\Q" + conversionEnding + "\\E|$)", " ~[?:0]$1"); } + @RepeatedTest(10) + @Issue("https://github.com/apache/logging-log4j2/issues/3940") + 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); + } + }; + }); + } + @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); + }); + }); + } + + private void formatThrowableWhileMutatingConcurrently( + Function> throwableMutatorFactory) 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); + 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 { + startLatch.countDown(); + startLatch.await(); + exceptionMutator.accept(exception); + } catch (InterruptedException ignored) { + // Restore the interrupt + Thread.currentThread().interrupt(); + } finally { + runningThreadCountRef.decrementAndGet(); } - } 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); + } + } finally { + executor.shutdownNow(); } + } - // 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()); } } 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..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 @@ -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,15 @@ static final class Metadata { */ final int stackLength; + /** + * 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; + /** * The suppressed exceptions attached to this {@link Throwable}. * This needs to be captured separately since {@link Throwable#getSuppressed()} can change. @@ -277,9 +285,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 +352,7 @@ private static Metadata populateMetadata( commonElementCount = 0; stackLength = currentTrace.length; } - return new Metadata(commonElementCount, stackLength, suppressed); + return new Metadata(commonElementCount, stackLength, currentTrace, suppressed); } } } 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..4bd5ca2c281 --- /dev/null +++ b/src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml @@ -0,0 +1,13 @@ + + + + + + Fixes `ArrayIndexOutOfBoundsException` thrown by `ThrowableStackTraceRenderer` when the stack trace is mutated concurrently. + +