Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -26,14 +26,21 @@
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;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
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;
Expand Down Expand Up @@ -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<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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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(),
Expand All @@ -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);
}
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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 <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) {
Expand All @@ -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);
Expand All @@ -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) {
Expand All @@ -326,7 +339,7 @@ private static Metadata populateMetadata(
commonElementCount = 0;
stackLength = currentTrace.length;
}
return new Metadata(commonElementCount, stackLength);
return new Metadata(commonElementCount, stackLength, suppressed);
}
}
}
Expand Down
13 changes: 13 additions & 0 deletions src/changelog/2.25.1/3929_ThrowableStackTraceRenderer-npe.xml
Original file line number Diff line number Diff line change
@@ -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>