ThrowableStackTraceRenderer throws NPE when rendering a Throwable with concurrently-mutated suppressions

[joepembe]

Description

The ThrowableStackTraceRenderer class can throw a NullPointerException if the suppressed exceptions associated with the Throwable it is rendering are being concurrently mutated. This is happening because ThrowableStackTraceRenderer invokes Throwable#getSuppressed() twice: once in ThrowableStackTraceRenderer.Context.Metadata#populateMetadata(), and a second time in ThrowableStackTraceRenderer#renderThrowable(), ahead of invoking ThrowableStackTraceRenderer#renderSuppressed(). If a racing thread manages to add a new suppressed exception to the being-logged exception between these two invocations, then the Map<Throwable, Context.Metadata> constructed by populateMetadata() will contain no mapping for the newly-added suppression, and as a result the dereference performed on line 168 explodes.

I have a repro below. To make the issue easier to detect, this repro does not use async logging, and I've configured the logger with ignoreExceptions="false" so that the NPE bubbles up to the logging site. However, it is worth noting that in an async logging setup, the appender responsible for invoking ThrowableStackTraceRenderer would run in the LMAX disruptor thread (rather than the application thread that submitted the log event), which likely means that this issue would occur if an application that uses async logging performed the following sequence of operations in a single thread:

1. Generate an exception, then
2. Log that exception, then
3. Perform an operation that resulted in the attachment of a new suppressed exception to the logged exception.

Configuration

Version: 2.25.1

Operating system: mac OS

JDK: Java 21

Logs

Log4jBugTest > test() STANDARD_ERROR
    2025-09-12T16:09:59.750535Z Test worker ERROR An exception occurred processing Appender CONSOLE
    java.lang.NullPointerException: Cannot read field "stackLength" because "metadata" is null
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderStackTraceElements(ThrowableStackTraceRenderer.java:168)
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderThrowable(ThrowableStackTraceRenderer.java:110)
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderSuppressed(ThrowableStackTraceRenderer.java:133)
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderThrowable(ThrowableStackTraceRenderer.java:111)
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderThrowable(ThrowableStackTraceRenderer.java:87)
        at org.apache.logging.log4j.core.pattern.ThrowableStackTraceRenderer.renderThrowable(ThrowableStackTraceRenderer.java:59)
        at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:130)
        at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:354)
        at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:251)
        at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:237)
        at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:711)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:669)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:645)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:589)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
        at org.apache.logging.log4j.core.Logger.log(Logger.java:187)
        at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2970)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2922)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2904)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2682)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2435)
        at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1779)
        at Log4jBugTest.test(Log4jBugTest.java:34)

Reproduction

import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.atomic.AtomicBoolean;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.jupiter.api.Test;

public class Log4jBugTest {

    private static final Logger log = LogManager.getLogger(Log4jBugTest.class);

    @Test
    public void test() throws InterruptedException, ExecutionException {
        try (ExecutorService executor = Executors.newSingleThreadExecutor()) {
            for (int i = 0; i < 1000; i++) {
                AtomicBoolean done = new AtomicBoolean(false);
                CountDownLatch latch = new CountDownLatch(1);
                Exception e = new Exception("root-" + i);
                Future<?> f = executor.submit(() -> {
                    latch.countDown();
                    while (!done.get()) {
                        e.addSuppressed(new Exception("suppressed"));
                    }
                });
                latch.await();
                log.info("The error", e);
                done.set(true);
                f.get();
            }
        }
    }
}

And my log4j2 config:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
    <Appenders>
        <Console name="CONSOLE" target="SYSTEM_OUT" ignoreExceptions="false">
            <PatternLayout pattern= "%d{dd MMM yyyy HH:mm:ss,SSS} [%p] (%t) %c: %m%n%ex"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="CONSOLE" />
        </Root>
    </Loggers>
</Configuration>

[vy]

If a racing thread manages to add a new suppressed exception to the being-logged exception between these two invocations

@joepembe, thanks so much for the report. Is this an isolated technical finding, or an issue observed in a real world application? If the latter, would you mind sharing the context that triggered this behavior, please?

[joepembe]

This was observed in a real production application. The application in question makes heavy use of RxJava, where an exception instance propagates forward through some graph of reactive operators, sometimes crossing thread boundaries, and alternately accumulating suppressed exceptions and/or being logged. But as I mentioned in the description, I strongly suspect that parallelism at the application layer is not necessary to trigger this bug. The use of async logging + the attachment of suppressed exceptions close to the site where an exception is logged is likely sufficient.

[vy]

@joepembe, if your capacity allows, would you mind contributing a PR containing the fix along with tests, please?

[shinstev333]

Found a similar bug #3933