plusterkopp opened a new issue, #4356:
URL: https://github.com/apache/logging-log4j2/issues/4356
**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:
```java
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":
```java
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`):
```java
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
```
<details>
<summary>Log4jDisruptor4Loss.java</summary>
```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);
}
}
```
</details>
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](https://github.com/user-attachments/files/32668923/Log4jDisruptor4Loss.java)
[AsyncLoggerDisruptor.java](https://github.com/user-attachments/files/32668961/AsyncLoggerDisruptor.java)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
