Skip to content

Commit c9a38ed

Browse files
moschevy
mosche
and
vy
authored
Fix ArrayIndexOutOfBoundsException in ThrowableStackTraceRenderer when the stack trace is mutated concurrently (#3955)
Co-authored-by: Volkan Yazıcı <volkan@yazi.ci>
1 parent 1758179 commit c9a38ed

File tree

5 files changed

+121
-55
lines changed

5 files changed

+121
-55
lines changed

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

Lines changed: 88 additions & 48 deletions
Original file line numberDiff line numberDiff line change
@@ -25,12 +25,15 @@
2525
import java.io.PrintStream;
2626
import java.nio.charset.Charset;
2727
import java.nio.charset.StandardCharsets;
28+
import java.util.Arrays;
2829
import java.util.List;
2930
import java.util.concurrent.CountDownLatch;
3031
import java.util.concurrent.ExecutorService;
3132
import java.util.concurrent.Executors;
3233
import java.util.concurrent.atomic.AtomicInteger;
3334
import java.util.concurrent.locks.LockSupport;
35+
import java.util.function.Consumer;
36+
import java.util.function.Function;
3437
import java.util.stream.Collectors;
3538
import java.util.stream.IntStream;
3639
import java.util.stream.Stream;
@@ -443,64 +446,101 @@ private static String normalizeStackTrace(final String stackTrace, final String
443446
.replaceAll(" ~\\[\\?:[^]]+](\\Q" + conversionEnding + "\\E|$)", " ~[?:0]$1");
444447
}
445448

449+
@RepeatedTest(10)
450+
@Issue("https://github.com/apache/logging-log4j2/issues/3940")
451+
void concurrent_stack_trace_mutation_should_not_cause_failure() throws Exception {
452+
final int stackTracePerThreadCount = 100;
453+
formatThrowableWhileMutatingConcurrently(threadIndex -> {
454+
final List<StackTraceElement[]> stackTraces = createExceptionsOfDifferentDepths().stream()
455+
.map(Throwable::getStackTrace)
456+
.collect(Collectors.toList());
457+
return exception -> {
458+
for (int stackTraceIndex = 0; stackTraceIndex < stackTracePerThreadCount; stackTraceIndex++) {
459+
exception.setStackTrace(stackTraces.get(stackTraceIndex));
460+
// Give some time slack to increase randomness
461+
LockSupport.parkNanos(1);
462+
}
463+
};
464+
});
465+
}
466+
446467
@RepeatedTest(10)
447468
@Issue("https://github.com/apache/logging-log4j2/issues/3929")
448469
void concurrent_suppressed_mutation_should_not_cause_failure() throws Exception {
470+
formatThrowableWhileMutatingConcurrently(threadIndex -> {
471+
final List<Exception> exceptions = createExceptionsOfDifferentDepths();
472+
return exception -> exceptions.forEach(suppressed -> {
473+
exception.addSuppressed(suppressed);
474+
// Give some time slack to increase randomness
475+
LockSupport.parkNanos(1);
476+
});
477+
});
478+
}
479+
480+
private void formatThrowableWhileMutatingConcurrently(
481+
Function<Integer, Consumer<Throwable>> throwableMutatorFactory) throws Exception {
449482

450483
// Test constants
451484
final int threadCount = Math.max(8, Runtime.getRuntime().availableProcessors());
452485
final ExecutorService executor = Executors.newFixedThreadPool(threadCount);
453-
final Exception exception = new Exception();
454-
final CountDownLatch startLatch =
455-
new CountDownLatch(threadCount + /* the main thread invoking the rendering: */ 1);
456-
final int exceptionPerThreadCount = 100;
457-
final AtomicInteger runningThreadCountRef = new AtomicInteger(threadCount);
458-
459-
// Schedule threads that will start adding suppressed exceptions with the start signal
460-
for (int threadIndex = 0; threadIndex < threadCount; threadIndex++) {
461-
final int threadIndex_ = threadIndex;
462-
executor.submit(() -> {
463-
try {
464-
List<Exception> exceptions = IntStream.range(0, exceptionPerThreadCount)
465-
.mapToObj(exceptionIndex -> new Exception(threadIndex_ + "-" + exceptionIndex))
466-
.collect(Collectors.toList());
467-
startLatch.countDown();
468-
startLatch.await();
469-
for (int exceptionIndex = 0; exceptionIndex < exceptionPerThreadCount; exceptionIndex++) {
470-
exception.addSuppressed(exceptions.get(exceptionIndex));
471-
// Give some time slack to increase randomness
472-
LockSupport.parkNanos(1);
486+
try {
487+
final Exception exception = new Exception();
488+
final CountDownLatch startLatch =
489+
new CountDownLatch(threadCount + /* the main thread invoking the rendering: */ 1);
490+
final AtomicInteger runningThreadCountRef = new AtomicInteger(threadCount);
491+
492+
// Schedule threads that will start mutating the exception with the start signal
493+
for (int threadIndex = 0; threadIndex < threadCount; threadIndex++) {
494+
final Consumer<Throwable> exceptionMutator = throwableMutatorFactory.apply(threadIndex);
495+
executor.submit(() -> {
496+
try {
497+
startLatch.countDown();
498+
startLatch.await();
499+
exceptionMutator.accept(exception);
500+
} catch (InterruptedException ignored) {
501+
// Restore the interrupt
502+
Thread.currentThread().interrupt();
503+
} finally {
504+
runningThreadCountRef.decrementAndGet();
473505
}
474-
} catch (InterruptedException ignored) {
475-
// Restore the interrupt
476-
Thread.currentThread().interrupt();
477-
} finally {
478-
runningThreadCountRef.decrementAndGet();
479-
}
480-
});
506+
});
507+
}
508+
509+
// Create the formatter
510+
final List<PatternFormatter> patternFormatters = PATTERN_PARSER.parse(patternPrefix, false, true, true);
511+
assertThat(patternFormatters).hasSize(1);
512+
final PatternFormatter patternFormatter = patternFormatters.get(0);
513+
514+
// Create the log event and the layout buffer
515+
final LogEvent logEvent = Log4jLogEvent.newBuilder()
516+
.setThrown(exception)
517+
.setLevel(LEVEL)
518+
.build();
519+
final StringBuilder buffer = new StringBuilder(16384);
520+
521+
// Trigger the start latch and format the exception
522+
startLatch.countDown();
523+
startLatch.await();
524+
while (runningThreadCountRef.get() > 0) {
525+
// Give some time slack to increase randomness
526+
LockSupport.parkNanos(1);
527+
patternFormatter.format(logEvent, buffer);
528+
buffer.setLength(0);
529+
}
530+
} finally {
531+
executor.shutdownNow();
481532
}
533+
}
482534

483-
// Create the formatter
484-
final List<PatternFormatter> patternFormatters = PATTERN_PARSER.parse(patternPrefix, false, true, true);
485-
assertThat(patternFormatters).hasSize(1);
486-
final PatternFormatter patternFormatter = patternFormatters.get(0);
487-
488-
// Create the log event and the layout buffer
489-
final LogEvent logEvent = Log4jLogEvent.newBuilder()
490-
.setThrown(exception)
491-
.setLevel(LEVEL)
492-
.build();
493-
final StringBuilder buffer = new StringBuilder(16384);
494-
495-
// Trigger the start latch and format the exception
496-
startLatch.countDown();
497-
startLatch.await();
498-
while (runningThreadCountRef.get() > 0) {
499-
// Give some time slack to increase randomness
500-
LockSupport.parkNanos(1);
501-
patternFormatter.format(logEvent, buffer);
502-
buffer.setLength(0);
503-
}
535+
private static List<Exception> createExceptionsOfDifferentDepths() {
536+
final StackTraceElement[] stackTrace = new Exception().getStackTrace();
537+
return IntStream.range(0, stackTrace.length)
538+
.mapToObj(depth -> {
539+
final Exception exception = new Exception();
540+
exception.setStackTrace(Arrays.copyOfRange(stackTrace, 0, depth));
541+
return exception;
542+
})
543+
.collect(Collectors.toList());
504544
}
505545
}
506546

‎log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -132,7 +132,7 @@ private static Map<String, ClassResourceInfo> createClassResourceInfoByName(
132132
Class<?> executionStackTraceElementClass =
133133
executionStackTrace.isEmpty() ? null : executionStackTrace.peekLast();
134134
ClassLoader lastLoader = null;
135-
final StackTraceElement[] stackTraceElements = throwable.getStackTrace();
135+
final StackTraceElement[] stackTraceElements = metadata.stackTrace;
136136
for (int throwableStackIndex = metadata.stackLength - 1;
137137
throwableStackIndex >= 0;
138138
--throwableStackIndex) {

‎log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableInvertedStackTraceRenderer.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -74,7 +74,7 @@ private void renderThrowable(
7474
}
7575
renderThrowableMessage(buffer, throwable);
7676
buffer.append(lineSeparator);
77-
renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator);
77+
renderStackTraceElements(buffer, context, metadata, prefix, lineSeparator);
7878
renderSuppressed(buffer, metadata.suppressed, context, visitedThrowables, prefix + '\t', lineSeparator);
7979
}
8080
}

‎log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java‎

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,7 @@ private void renderThrowable(
9898
final Context.Metadata metadata = context.metadataByThrowable.get(throwable);
9999
renderThrowableMessage(buffer, throwable);
100100
buffer.append(lineSeparator);
101-
renderStackTraceElements(buffer, throwable, context, metadata, prefix, lineSeparator);
101+
renderStackTraceElements(buffer, context, metadata, prefix, lineSeparator);
102102
renderSuppressed(buffer, metadata.suppressed, context, visitedThrowables, prefix + '\t', lineSeparator);
103103
renderCause(buffer, throwable.getCause(), context, visitedThrowables, prefix, lineSeparator);
104104
}
@@ -148,13 +148,12 @@ static void renderThrowableMessage(final StringBuilder buffer, final Throwable t
148148

149149
final void renderStackTraceElements(
150150
final StringBuilder buffer,
151-
final Throwable throwable,
152151
final C context,
153152
final Context.Metadata metadata,
154153
final String prefix,
155154
final String lineSeparator) {
156155
context.ignoredStackTraceElementCount = 0;
157-
final StackTraceElement[] stackTraceElements = throwable.getStackTrace();
156+
final StackTraceElement[] stackTraceElements = metadata.stackTrace;
158157
for (int i = 0; i < metadata.stackLength; i++) {
159158
renderStackTraceElement(buffer, stackTraceElements[i], context, prefix, lineSeparator);
160159
}
@@ -268,6 +267,15 @@ static final class Metadata {
268267
*/
269268
final int stackLength;
270269

270+
/**
271+
* The stack trace of this {@link Throwable}.
272+
* This needs to be captured separately since {@link Throwable#getStackTrace()} can change.
273+
*
274+
* @see <a href="https://github.com/apache/logging-log4j2/issues/3940">#3940</a>
275+
* @see <a href="https://github.com/apache/logging-log4j2/pull/3955">#3955</a>
276+
*/
277+
final StackTraceElement[] stackTrace;
278+
271279
/**
272280
* The suppressed exceptions attached to this {@link Throwable}.
273281
* This needs to be captured separately since {@link Throwable#getSuppressed()} can change.
@@ -277,9 +285,14 @@ static final class Metadata {
277285
*/
278286
final Throwable[] suppressed;
279287

280-
private Metadata(final int commonElementCount, final int stackLength, final Throwable[] suppressed) {
288+
private Metadata(
289+
final int commonElementCount,
290+
final int stackLength,
291+
final StackTraceElement[] stackTrace,
292+
final Throwable[] suppressed) {
281293
this.commonElementCount = commonElementCount;
282294
this.stackLength = stackLength;
295+
this.stackTrace = stackTrace;
283296
this.suppressed = suppressed;
284297
}
285298

@@ -339,7 +352,7 @@ private static Metadata populateMetadata(
339352
commonElementCount = 0;
340353
stackLength = currentTrace.length;
341354
}
342-
return new Metadata(commonElementCount, stackLength, suppressed);
355+
return new Metadata(commonElementCount, stackLength, currentTrace, suppressed);
343356
}
344357
}
345358
}

‎src/changelog/2.25.2/3940_ThrowableStackTraceRenderer_ArrayIndexOutOfBoundsException.xml‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
<?xml version="1.0" encoding="UTF-8"?>
2+
<entry xmlns="https://logging.apache.org/xml/ns"
3+
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
4+
xsi:schemaLocation="
5+
https://logging.apache.org/xml/ns
6+
https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
7+
type="fixed">
8+
<issue id="3940" link="https://github.com/apache/logging-log4j2/issues/3940"/>
9+
<issue id="3955" link="https://github.com/apache/logging-log4j2/pull/3955"/>
10+
<description format="asciidoc">
11+
Fixes `ArrayIndexOutOfBoundsException` thrown by `ThrowableStackTraceRenderer` when the stack trace is mutated concurrently.
12+
</description>
13+
</entry>

0 commit comments

Comments
 (0)