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

Đang mở
  • Có gì không ổn?
#4,356 16 bình luận 0 reaction 1 người được giao Xem trên GitHub

Maintainer thường phản hồi trong vòng 1 ngày

@ramanathan1504 đang làm issue này rồi.

Từ ngày 26/9/2026.

Đánh giá

Độ khó
4/5
Thời gian dự kiến
3-5 ngày
Mức phù hợp với người mới
70/100
Loại issue
Lỗi
Độ rõ ràng
Đặc tả rõ ràng
Mức độ hoạt động
Sôi nổi
Công nghệ
java
Lĩnh vực
backend, observability, performance

Hướng nghiên cứu

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.

Do mô hình lập chỉ mục viết ra từ nội dung của issue.

Mô tả

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

Ngôn ngữ chính
Java
Star
3.6k
Fork
1.8k
Merge trung bình
5 ngày 6 giờ
Pull request đã merge (30 ngày)
24

Chuẩn bị môi trường

  • Không có Dockerfile hay tệp Docker Compose
  • Có mẫu pull request
  • Không có hướng dẫn đóng góp

Bắt đầu từ đâu

  1. Đọc hết issue, rồi đọc hướng dẫn đóng góp của dự án.
  2. Bình luận trên issue rằng bạn sẽ nhận — tránh hai người làm cùng một việc.
  3. Fork repository và làm thay đổi trên một nhánh.
  4. Mở pull request có tham chiếu số hiệu của issue.

Issue khác của apache/logging-log4j2

Tất cả issue của apache/logging-log4j2

Issue tương tự

Thêm issue về Java

Nhận issue mới trong hộp thư của bạn

Bản tóm tắt ngắn những issue GitHub phù hợp với người mới.