Async loggers silently discard events when the ring buffer is full and LMAX Disruptor 4 is used

Aperta
  • Qualcosa non va?
#4,356 16 commenti 0 reazioni 1 assegnatario Vedi su GitHub

I maintainer di solito rispondono entro 1 giorno

@ramanathan1504 ci sta già lavorando.

Dal 26/9/2026.

Valutazione

Difficoltà
4/5
Tempo stimato
3-5 giorni
Idoneità per principianti
70/100
Tipo di issue
Bug
Chiarezza
Specificata chiaramente
Stato di attività
Attiva
Stack tecnologico
java
Ambito
backend, observability, performance

Direzione di ricerca

Start with AsyncLoggerDisruptor.java and its getEventRoute() and remainingDisruptorCapacity() entry points, then compare the corresponding logic in AsyncLoggerConfigDisruptor. Run the supplied Log4jDisruptor4Loss.java reproducer with Disruptor 4.0.0 and inspect behavior under a full ring buffer. Done means the queue-full policy is reached during saturation and the reproducer retains all expected events for both async logger paths.

Scritto dal modello di indicizzazione a partire dal testo della issue.

Descrizione

async bug priority: P1

Title: Async loggers silently discard events when the ring buffer is full and LMAX Disruptor 4 is used

Description

When AsyncLoggerContextSelector is combined with LMAX Disruptor 4.0.0, log events are dropped without any trace once the ring buffer runs full. In our server, a burst of warnings at start-up (about 180k events in under 2 s from 16 threads) made single lines of unrelated threads and appenders disappear. The standalone reproducer below loses 56–82% of its events. Nothing is written to the StatusLogger (tested with status="WARN") or to stderr.

Cause

Disruptor 4.0.0 changed MultiProducerSequencer.next() to claim a sequence first and wait for free capacity afterwards:

long current = cursor.getAndAdd(n);           // claims before capacity is available
long nextSequence = current + n;
long wrapPoint = nextSequence - bufferSize;
...
while (wrapPoint > (gatingSequence = Util.getMinimumSequence(gatingSequences, current))) {
    LockSupport.parkNanos(1L);
}

While one thread waits in that loop, the cursor is ahead of the consumer by more than the buffer size. remainingCapacity() (bufferSize - (produced - consumed)) therefore returns a negative value, typically -1. Disruptor 3.x next() only advances the cursor with a CAS after capacity is available, so this never happens there.

AsyncLoggerDisruptor.getEventRoute() treats any negative capacity as "log4j has been shut down":

EventRoute getEventRoute(final Level logLevel) {
    final int remainingCapacity = remainingDisruptorCapacity();
    if (remainingCapacity < 0) {
        return EventRoute.DISCARD;
    }
    return asyncQueueFullPolicy.getRoute(backgroundThreadId, logLevel);
}

remainingDisruptorCapacity() returns -1 only when disruptor == null, but it also passes through negative values from RingBuffer.remainingCapacity(). The sequence when the ring buffer is full:

  1. Thread A's tryPublish fails, getEventRoute() returns ENQUEUE, and A enters enqueueLogMessageWhenQueueFull → publishEvent → next(). There it claims a slot beyond the buffer and parks.
  2. Every other thread whose tryPublish fails now sees remainingCapacity() == -1. It gets DISCARD, and handleRingBufferFull clears the translator without a message.

Under sustained saturation effectively only the thread holding queueFullEnqueueLock gets its events in; all others lose theirs. The configured AsyncQueueFullPolicy is never consulted, because the DISCARD decision is made before it. log4j2.asyncLoggerSynchronizeEnqueueWhenQueueFull=false makes it worse, since more threads wait inside next() at the same time.

AsyncLoggerConfigDisruptor.getEventRoute() has the same check, so mixed async loggers (<AsyncLogger>) should be affected too; we have only tested AsyncLoggerContextSelector. The check is unchanged on the current 2.x branch.

A much rarer variant exists with Disruptor 3.x as well. remainingCapacity() reads consumed and produced separately. If the consumer advances between the two reads and producers immediately claim the freed slots, the result is briefly negative. We observed -51, one progress step of RingBufferLogEventHandler, when polling it while the buffer was full. We never saw an event lost this way, but the same check would discard it.

Suggested fix

Check for shutdown explicitly instead of inferring it from the capacity. In AsyncLoggerDisruptor (and likewise in AsyncLoggerConfigDisruptor):

EventRoute getEventRoute(final Level logLevel) {
    if (hasLog4jBeenShutDown(disruptor)) {
        return EventRoute.DISCARD;
    }
    return asyncQueueFullPolicy.getRoute(backgroundThreadId, logLevel);
}

With this change the reproducer below loses no events with Disruptor 4.0.0 (3 of 3 runs, 800,000 of 800,000 lines).

Configuration

Version: log4j 2.25.3. 2.24.3 and 2.25.2 behave the same with Disruptor 4.0.0. Disruptor 3.4.1 does not show the loss with any of them.

Operating system: Windows 11, 8 logical CPUs

JDK: Eclipse Temurin 25.0.3+9

Logs

Nothing is logged, and that is the core of the problem. With status="WARN", the StatusLogger stays silent and nothing appears on stderr.

Reproduction

Single-file program, run with Java 17+ in source-file mode. It uses the default ring buffer size, which is 4096 in garbage-free mode:

java -cp log4j-api-2.25.3.jar:log4j-core-2.25.3.jar:disruptor-4.0.0.jar Log4jDisruptor4Loss.java
Log4jDisruptor4Loss.java 
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.ArrayList;
import java.util.BitSet;
import java.util.List;
import java.util.concurrent.CountDownLatch;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Log4jDisruptor4Loss {

    static final int THREADS = 16;
    static final int LINES = 50_000;

    public static void main(String[] args) throws Exception {
        Path dir = Files.createTempDirectory("log4j-loss");
        Path log = dir.resolve("test.log");
        Path config = dir.resolve("log4j2.xml");
        Files.writeString(config, """
                <Configuration status="WARN">
                  <Appenders>
                    <File name="file" fileName="%s">
                      <PatternLayout pattern="%%d %%-5p [%%t] %%c - %%m%%n"/>
                    </File>
                  </Appenders>
                  <Loggers>
                    <Root level="INFO"><AppenderRef ref="file"/></Root>
                  </Loggers>
                </Configuration>
                """.formatted(log.toAbsolutePath().toString().replace('\\', '/')));
        System.setProperty("log4j2.contextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
        System.setProperty("log4j2.configurationFile", config.toUri().toString());

        Logger logger = LogManager.getLogger("test");
        CountDownLatch start = new CountDownLatch(1);
        List<Thread> threads = new ArrayList<>();
        for (int t = 0; t < THREADS; t++) {
            int thread = t;
            Thread th = new Thread(() -> {
                try {
                    start.await();
                } catch (InterruptedException e) {
                    return;
                }
                for (int i = 0; i < LINES; i++) {
                    logger.info("LINE {} {} padding padding padding padding padding padding padding padding", thread, i);
                }
            }, "producer-" + t);
            th.start();
            threads.add(th);
        }
        long startNanos = System.nanoTime();
        start.countDown();
        for (Thread th : threads) {
            th.join();
        }
        long producedMs = (System.nanoTime() - startNanos) / 1_000_000;
        // stops the disruptor after draining it and closes the file
        LogManager.shutdown();

        BitSet[] seen = new BitSet[THREADS];
        for (int t = 0; t < THREADS; t++) {
            seen[t] = new BitSet(LINES);
        }
        for (String line : Files.readAllLines(log, StandardCharsets.UTF_8)) {
            int at = line.indexOf(" - LINE ");
            if (at < 0) {
                continue;
            }
            String[] fields = line.substring(at + 8).split(" ", 3);
            seen[Integer.parseInt(fields[0])].set(Integer.parseInt(fields[1]));
        }
        long expected = (long) THREADS * LINES;
        long found = 0;
        for (BitSet bits : seen) {
            found += bits.cardinality();
        }
        String disruptor = com.lmax.disruptor.RingBuffer.class.getProtectionDomain().getCodeSource().getLocation().getPath();
        System.out.printf("Disruptor %s: %d threads logged %d lines in %d ms, %d in the file, %d missing (%.1f%%)%n",
                disruptor.substring(disruptor.lastIndexOf('/') + 1), THREADS, expected, producedMs, found,
                expected - found, 100.0 * (expected - found) / expected);
    }
}

Results, 3 runs each:

Setup Missing lines
log4j 2.25.3 + Disruptor 4.0.0 81.7%, 56.4%, 68.1%
log4j 2.25.3 + Disruptor 3.4.1 0, 0, 0
log4j 2.25.3 + Disruptor 4.0.0 + suggested fix 0, 0, 0

In a larger test with 16 flooding threads plus low-rate probe threads, repeated rounds and several appenders, we saw the same picture:

  • Disruptor 4.0.0 lost 50–97% with log4j 2.24.3, 2.25.2 and 2.25.3.
  • Disruptor 3.4.1 lost nothing in about 30 million lines under constant saturation.
  • A ring buffer large enough never to fill (4M) also avoids the loss, but only because the queue-full path is never taken.

Log4jDisruptor4Loss.java

AsyncLoggerDisruptor.java

Lingua principale
Java
Stelle
3.6k
Fork
1.8k
Merge medio
5g 6h
PR unite (30g)
24

Preparare l'ambiente

  • Nessun Dockerfile né file Docker Compose
  • Ha un modello di pull request
  • Nessuna guida per i contributori

Come iniziare

  1. Leggi tutta la issue e poi la guida ai contributi del progetto.
  2. Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
  3. Fai un fork del repository e lavora su un branch.
  4. Apri una pull request che faccia riferimento al numero della issue.

Altre issue di apache/logging-log4j2

Tutte le issue di apache/logging-log4j2

Issue simili

Altre issue su Java

Ricevi le nuove issue nella tua casella

Un breve riepilogo di issue GitHub adatte ai principianti.